Bug #25514 many daemon threads accumulating, hanging around
Submitted: 10 Jan 2007 0:56 Modified: 22 Feb 2007 14:12
Reporter: Mark Taylor Email Updates:
Status: Closed Impact on me:
None 
Category:Connector / J Severity:S3 (Non-critical)
Version:5.0.4 OS:multiple linux
Assigned to: CPU Architecture:Any
Tags: daemon thread timer timerthread

[10 Jan 2007 0:56] Mark Taylor
Description:
We are using Connector/J 5.0.3 

Since upgrading from 3.1.12 to 5.0.3 some months ago, we are finding that a thread dump of our programs turns up many long-lingering Timer daemon threads as in the "how to repeat" section.

In our real programs, the timer id numbers quickly and easily climb into the thousands, although there are usually only a few dozen hanging around at any one time.

Given that the Timers do (usually) go away, I assume this means they eventually meet their exit criteria and then (eventually) get GC'd.  But it doesn't always happen in a timely a fashion, and we have had programs go nonresponsive for lack of being able to allocate new threads.

Even some of our single-threaded, single-connection background daemon processes, have been found with multiple dozens of lingering Timers.

Since the programs in question do not invoke any Timer threads of their own, and since this started happening when we moved from conn/j 3.1 to 5.0, we searched and found that conn/j started using Timers in a new way with 5.0 (and continue to use them the same way with 5.0.4)

As far as we understand the code, it looks like the connector/j may be in a transitional state -- moving away from a "Timer per connection" model to a "static cleanup Timer" that operates globally.  No idea if this is relevant to the problem, but it seems a possiblity worth mentioning.

Note in the given example that we make 10 consecutive connections, and allow each in turn to fully complete, close everything, and give it a second to go quiescent.  Even then, by the time the 10th iteration finishes, and a couple seconds go by, there are still a few Timers that should have long since gone away.

Thanks,
   Mark

P.S.  FWIW we are also using Hibernate 2.x (yes, it's old but we can't upgrade yet), dbcp 1.2, and Spring 1.2.  While I don't think they have any direct bearing on our problem (because it can be reproduced with pure jdbc access) it seems conceivable that an interaction between the tools could exacerbate the problem leading to our occasional thread explosion/exhaustion.  

How to repeat:
cat > TimerThreadIssue.java <<-EOF

import java.sql.Connection;
import java.sql.DriverManager;
import java.sql.ResultSet;
import java.sql.Statement;

public class TimerThreadIssue {

    public static void main(String[] args) throws Exception {

        String username = args[0];
        String password = args[1];

        Class.forName("com.mysql.jdbc.Driver");
        String hostname = "localhost";
        String port = "3306";
        String schema = "mysql";
        String url = "jdbc:mysql://"+hostname+":"+port+"/"+schema+"?jdbcCompliantTruncation=false&explainSlowQueries=true&dumpQueriesOnException=true&zeroDateTimeBehavior=convertToNull&enablePacketDebug=true";
        
        for(int i=0; i<10; i++) {
            System.out.println("Executing iteration "+i);
            
            Connection conn = DriverManager.getConnection(url, username, password);
            Statement stmt = conn.createStatement();
            ResultSet rs = stmt.executeQuery( "select count(*) from user" );
            rs.next();
            rs.getInt(1);
            rs.close();
            stmt.close();
            conn.close();
            
            Thread.sleep(1000);
        }

        System.out.println("ctrl-backslash to thread dump now...");
        Thread.sleep(5000);
        System.out.println("...Exiting");

    }

}
EOF

$ java -cp ./mysql-connector-java-5.0.3-bin.jar:. TimerThreadIssue MYUSER MYPASS
Executing iteration 0
Executing iteration 1
Executing iteration 2
Executing iteration 3
Executing iteration 4
Executing iteration 5
Executing iteration 6
Executing iteration 7
Executing iteration 8
Executing iteration 9
ctrl-backslash to thread dump now...
Full thread dump Java HotSpot(TM) 64-Bit Server VM (1.5.0_08-b03 mixed mode):

"Timer-9" daemon prio=1 tid=0x00002aaaf7b3caa0 nid=0x7002 in Object.wait() [0x0000000041060000..0x0000000041060c40]
        at java.lang.Object.wait(Native Method)
        - waiting on <0x00002aaae27ec548> (a java.util.TaskQueue)
        at java.lang.Object.wait(Object.java:474)
        at java.util.TimerThread.mainLoop(Timer.java:483)
        - locked <0x00002aaae27ec548> (a java.util.TaskQueue)
        at java.util.TimerThread.run(Timer.java:462)

"Timer-8" daemon prio=1 tid=0x00002aaaf7b834f0 nid=0x7001 in Object.wait() [0x0000000040f5f000..0x0000000040f5fbc0]
        at java.lang.Object.wait(Native Method)
        - waiting on <0x00002aaae214eb98> (a java.util.TaskQueue)
        at java.lang.Object.wait(Object.java:474)
        at java.util.TimerThread.mainLoop(Timer.java:483)
        - locked <0x00002aaae214eb98> (a java.util.TaskQueue)
        at java.util.TimerThread.run(Timer.java:462)

"Timer-7" daemon prio=1 tid=0x00002aaaf7bd0f10 nid=0x7000 in Object.wait() [0x0000000041666000..0x0000000041666b40]
        at java.lang.Object.wait(Native Method)
        - waiting on <0x00002aaae4fa6a50> (a java.util.TaskQueue)
        at java.lang.Object.wait(Object.java:474)
        at java.util.TimerThread.mainLoop(Timer.java:483)
        - locked <0x00002aaae4fa6a50> (a java.util.TaskQueue)
        at java.util.TimerThread.run(Timer.java:462)

"Low Memory Detector" daemon prio=1 tid=0x00002aaaf7b07f40 nid=0x6ff7 runnable [0x0000000000000000..0x0000000000000000]

"CompilerThread1" daemon prio=1 tid=0x00002aaaf7b064f0 nid=0x6ff6 waiting on condition [0x0000000000000000..0x0000000040c5b6d0]

"CompilerThread0" daemon prio=1 tid=0x00002aaaf7b05160 nid=0x6ff5 waiting on condition [0x0000000000000000..0x0000000040b5a6a0]

"AdapterThread" daemon prio=1 tid=0x00002aaaf7b03d60 nid=0x6ff4 waiting on condition [0x0000000000000000..0x0000000000000000]

"Signal Dispatcher" daemon prio=1 tid=0x00002aaaf7afeb50 nid=0x6ff3 waiting on condition [0x0000000000000000..0x0000000000000000]

"Finalizer" daemon prio=1 tid=0x00002aaaf7ad0460 nid=0x6ff2 in Object.wait() [0x0000000040858000..0x0000000040858c40]
        at java.lang.Object.wait(Native Method)
        - waiting on <0x00002aaae4fb1ae0> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116)
        - locked <0x00002aaae4fb1ae0> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:132)
        at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)

"Reference Handler" daemon prio=1 tid=0x00002aaaf7acfcd0 nid=0x6ff1 in Object.wait() [0x0000000040757000..0x0000000040757bc0]
        at java.lang.Object.wait(Native Method)
        - waiting on <0x00002aaae4fa8218> (a java.lang.ref.Reference$Lock)
        at java.lang.Object.wait(Object.java:474)
        at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
        - locked <0x00002aaae4fa8218> (a java.lang.ref.Reference$Lock)

"main" prio=1 tid=0x0000000040115660 nid=0x6feb waiting on condition [0x00007fffffbe4000..0x00007fffffbe49e0]
        at java.lang.Thread.sleep(Native Method)
        at TimerThreadIssue.main(TimerThreadIssue.java:36)

"VM Thread" prio=1 tid=0x00002aaaf7acb9d0 nid=0x6ff0 runnable

"GC task thread#0 (ParallelGC)" prio=1 tid=0x00000000401338a0 nid=0x6fec runnable

"GC task thread#1 (ParallelGC)" prio=1 tid=0x0000000040134690 nid=0x6fed runnable

"GC task thread#2 (ParallelGC)" prio=1 tid=0x0000000040135480 nid=0x6fee runnable

"GC task thread#3 (ParallelGC)" prio=1 tid=0x0000000040136270 nid=0x6fef runnable

"VM Periodic Task Thread" prio=1 tid=0x00002aaaf7b09c80 nid=0x6ff8 waiting on condition

...Exiting
[10 Jan 2007 2:04] Mark Taylor
Incidentally, I re-ran the example program, specifying the older 3.1.12 jar instead, as below, and it did NOT get the lingering daemon thread issue...

$ java -cp ./mysql-connector-java-3.1.12-bin.jar:. TimerThreadIssue MYUSER MYPASS
Executing iteration 0
Executing iteration 1
Executing iteration 2
Executing iteration 3
Executing iteration 4
Executing iteration 5
Executing iteration 6
Executing iteration 7
Executing iteration 8
Executing iteration 9
ctrl-backslash to thread dump now...
Full thread dump Java HotSpot(TM) 64-Bit Server VM (1.5.0_08-b03 mixed mode):

"Low Memory Detector" daemon prio=1 tid=0x00002aaaf7a03830 nid=0x48a6 runnable [0x0000000000000000..0x0000000000000000]

"CompilerThread1" daemon prio=1 tid=0x00002aaaf7a01de0 nid=0x48a5 waiting on condition [0x0000000000000000..0x0000000040c5b620]

"CompilerThread0" daemon prio=1 tid=0x00002aaaf7a00a50 nid=0x48a4 waiting on condition [0x0000000000000000..0x0000000040b5a750]

"AdapterThread" daemon prio=1 tid=0x00002aaaf7be8c10 nid=0x48a3 waiting on condition [0x0000000000000000..0x0000000000000000]

"Signal Dispatcher" daemon prio=1 tid=0x00002aaaf7be77f0 nid=0x48a1 waiting on condition [0x0000000000000000..0x0000000000000000]

"Finalizer" daemon prio=1 tid=0x00002aaaf7bb5f60 nid=0x489c in Object.wait() [0x0000000040858000..0x0000000040858b40]
        at java.lang.Object.wait(Native Method)
        - waiting on <0x00002aaae4fa63d0> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116)
        - locked <0x00002aaae4fa63d0> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:132)
        at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)

"Reference Handler" daemon prio=1 tid=0x00002aaaf7bb3710 nid=0x489b in Object.wait() [0x0000000040757000..0x0000000040757cc0]
        at java.lang.Object.wait(Native Method)
        - waiting on <0x00002aaae4fa8250> (a java.lang.ref.Reference$Lock)
        at java.lang.Object.wait(Object.java:474)
        at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
        - locked <0x00002aaae4fa8250> (a java.lang.ref.Reference$Lock)

"main" prio=1 tid=0x0000000040115610 nid=0x4891 waiting on condition [0x00007fffffc5e000..0x00007fffffc5ea70]
        at java.lang.Thread.sleep(Native Method)
        at TimerThreadIssue.main(TimerThreadIssue.java:36)

"VM Thread" prio=1 tid=0x00002aaaf7baf2b0 nid=0x489a runnable

"GC task thread#0 (ParallelGC)" prio=1 tid=0x0000000040133850 nid=0x4893 runnable

"GC task thread#1 (ParallelGC)" prio=1 tid=0x0000000040134640 nid=0x4894 runnable

"GC task thread#2 (ParallelGC)" prio=1 tid=0x0000000040135430 nid=0x4895 runnable

"GC task thread#3 (ParallelGC)" prio=1 tid=0x0000000040136220 nid=0x4896 runnable

"VM Periodic Task Thread" prio=1 tid=0x00002aaaf7a05570 nid=0x48a7 waiting on condition

...Exiting
[10 Jan 2007 2:12] Mark Taylor
Oh, and before anyone asks... Yes, I also downloaded 5.0.4 and tried this.  The lingering Timer daemon threads returned just as before with 5.0.3 (with 3 Timer threads in the output, as in the original example output)
[10 Jan 2007 16:17] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/17860
[22 Feb 2007 14:12] MC Brown
A note has been added to the 5.0.5 changelog.
[27 Feb 2007 5:20] Walter Zheng
I force System.gc() , it will collect those hanging timer threads.