Search code examples
linuxjvmjavasingle-threaded

Single-threaded Java application starts over 70 threads

I just experienced a very strange behaviour of the (openJDK) JVM, when starting my single-threaded application on our compute server:

The JVM starts a lot (really a lot) of threads that heavily increase the CPU load on all processors and I don't have a suitable explanation for that [see image below].

I also tested a few more things:

  1. I also tried running it on a Amazon EC2 instance with ~200GB of RAM and got a similar result with just a few number of threads less.
  2. Instead of starting the app with java -Xms4096M -Xmx100000M -jar ... I tried smaller parameters like java -Xms1024M -Xmx1024M -jar ... and nothing changed.

Has anyone else already experienced such behaviour?

Or even better: can someone explain to me what is happening here?

https://i.sstatic.net/E9XtQ.png

EDIT: I now have tried some of the things you have suggested and indeed got some valuable and also non-valuable output. jstack PID does not work and suggests me to use jstack -F PID whose output for the main process is as follows. kill -3 PID doesn't output anything.

Attaching to process ID 39041, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.40-b25
Deadlock Detection:

No deadlocks found.

Thread 39090: (state = BLOCKED)


Thread 39089: (state = BLOCKED)
 - java.lang.Object.wait(long) @bci=0 (Interpreted frame)
 - java.lang.ref.ReferenceQueue.remove(long) @bci=59, line=143 (Interpreted frame)
 - java.lang.ref.ReferenceQueue.remove() @bci=2, line=164 (Interpreted frame)
 - java.lang.ref.Finalizer$FinalizerThread.run() @bci=36, line=209 (Interpreted frame)


Thread 39088: (state = BLOCKED)
 - java.lang.Object.wait(long) @bci=0 (Interpreted frame)
 - java.lang.Object.wait() @bci=2, line=502 (Interpreted frame)
 - java.lang.ref.Reference$ReferenceHandler.run() @bci=36, line=157 (Interpreted frame)


Thread 39043: (state = BLOCKED)
 - java.lang.AbstractStringBuilder.<init>(int) @bci=6, line=68 (Compiled frame)
 - java.lang.StringBuilder.<init>(java.lang.String) @bci=8, line=112 (Compiled frame)
 - de.unisb.react.stud.algorithm.BMCLoopConverter.convert(gov.nasa.ltl.trans.Formula, int, int, int[]) @bci=526, line=99 (Compiled frame)
 - de.unisb.react.stud.algorithm.BMCLoopConverter.convert(gov.nasa.ltl.trans.Formula, int, int, int[]) @bci=413, line=86 (Compiled frame)
 - de.unisb.react.stud.algorithm.BMCLoopConverter.convert(gov.nasa.ltl.trans.Formula, int, int, int[]) @bci=80, line=39 (Compiled frame)
 - de.unisb.react.stud.algorithm.BMCLoopConverter.convert(gov.nasa.ltl.trans.Formula, int, int, int[]) @bci=136, line=43 (Compiled frame)
 - de.unisb.react.stud.algorithm.BMCLoopConverter.convert(gov.nasa.ltl.trans.Formula, int, int, int[]) @bci=676, line=112 (Compiled frame)
 - de.unisb.react.stud.algorithm.BMCLoopConverter.convert(gov.nasa.ltl.trans.Formula, int, int, int[]) @bci=654, line=111 (Compiled frame)
 - de.unisb.react.stud.algorithm.BMCLoopConverter.convert(gov.nasa.ltl.trans.Formula, int, int, int[]) @bci=654, line=111 (Compiled frame)
 - de.unisb.react.stud.algorithm.BMCLoopConverter.convert(gov.nasa.ltl.trans.Formula, int, int, int[]) @bci=654, line=111 (Compiled frame)
 - de.unisb.react.stud.algorithm.BMCLoopConverter.convert(gov.nasa.ltl.trans.Formula, int, int, int[]) @bci=654, line=111 (Compiled frame)
 - de.unisb.react.stud.algorithm.BMCLoopConverter.convert(gov.nasa.ltl.trans.Formula, int, int, int[]) @bci=654, line=111 (Compiled frame)
 - de.unisb.react.stud.algorithm.BMCLoopConverter.convert(gov.nasa.ltl.trans.Formula, int, int, int[]) @bci=654, line=111 (Compiled frame)
 - de.unisb.react.stud.algorithm.BMCLoopConverter.convert(gov.nasa.ltl.trans.Formula, int, int, int[]) @bci=654, line=111 (Compiled frame)
 - de.unisb.react.stud.algorithm.PMC.LoopConvert(gov.nasa.ltl.trans.Formula, int, de.unisb.react.stud.algorithm.Tree) @bci=69, line=274 (Compiled frame)
 - de.unisb.react.stud.algorithm.PMC.main(java.lang.String[]) @bci=207, line=97 (Interpreted frame)

I'm not sure whether it belongs to kill or jstack, however I found this in the tmux:

2015-04-06 10:11:49
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.40-b25 mixed mode):

"Service Thread" #23 daemon prio=9 os_prio=0 tid=0x00007f0e54040000 nid=0x98c5 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C1 CompilerThread17" #22 daemon prio=9 os_prio=0 tid=0x00007f0e54039800 nid=0x98c4 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C1 CompilerThread16" #21 daemon prio=9 os_prio=0 tid=0x00007f0e54037800 nid=0x98c3 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C1 CompilerThread15" #20 daemon prio=9 os_prio=0 tid=0x00007f0e54035000 nid=0x98c2 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C1 CompilerThread14" #19 daemon prio=9 os_prio=0 tid=0x00007f0e54033000 nid=0x98c1 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C1 CompilerThread13" #18 daemon prio=9 os_prio=0 tid=0x00007f0e54031000 nid=0x98c0 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C1 CompilerThread12" #17 daemon prio=9 os_prio=0 tid=0x00007f0e5402f000 nid=0x98bf waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread11" #16 daemon prio=9 os_prio=0 tid=0x00007f0e5402d000 nid=0x98be waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread10" #15 daemon prio=9 os_prio=0 tid=0x00007f0e5402b000 nid=0x98bd waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread9" #14 daemon prio=9 os_prio=0 tid=0x0000000001bd9000 nid=0x98bc runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread8" #13 daemon prio=9 os_prio=0 tid=0x0000000001bd7000 nid=0x98bb waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread7" #12 daemon prio=9 os_prio=0 tid=0x0000000001bd5000 nid=0x98ba waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread6" #11 daemon prio=9 os_prio=0 tid=0x0000000001bd3000 nid=0x98b9 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread5" #10 daemon prio=9 os_prio=0 tid=0x0000000001bd1000 nid=0x98b8 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread4" #9 daemon prio=9 os_prio=0 tid=0x0000000001bc6800 nid=0x98b7 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread3" #8 daemon prio=9 os_prio=0 tid=0x0000000001bc4800 nid=0x98b6 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread2" #7 daemon prio=9 os_prio=0 tid=0x0000000001bc0000 nid=0x98b5 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread1" #6 daemon prio=9 os_prio=0 tid=0x0000000001bbe000 nid=0x98b4 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" #5 daemon prio=9 os_prio=0 tid=0x0000000001bbb800 nid=0x98b3 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" #4 daemon prio=9 os_prio=0 tid=0x0000000001bb9000 nid=0x98b2 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" #3 daemon prio=8 os_prio=0 tid=0x0000000001b89000 nid=0x98b1 in Object.wait() [0x00007f0e5b5ba000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x00007f0f73829c78> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:143)
        - locked <0x00007f0f73829c78> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:164)
        at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:209)

"Reference Handler" #2 daemon prio=10 os_prio=0 tid=0x0000000001b87000 nid=0x98b0 in Object.wait() [0x00007f0e5b6bb000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x00007f0f73829cc0> (a java.lang.ref.Reference$Lock)
        at java.lang.Object.wait(Object.java:502)
        at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:157)
        - locked <0x00007f0f73829cc0> (a java.lang.ref.Reference$Lock)

"main" #1 prio=5 os_prio=0 tid=0x000000000151d800 nid=0x9883 runnable [0x00007f27cbc8c000]
   java.lang.Thread.State: RUNNABLE
        at de.unisb.react.stud.algorithm.BMCLoopConverter.convertLoop(BMCLoopConverter.java:156)
        at de.unisb.react.stud.algorithm.BMCLoopConverter.convert(BMCLoopConverter.java:118)
        at de.unisb.react.stud.algorithm.BMCLoopConverter.convert(BMCLoopConverter.java:111)
        at de.unisb.react.stud.algorithm.BMCLoopConverter.convert(BMCLoopConverter.java:111)
        at de.unisb.react.stud.algorithm.BMCLoopConverter.convert(BMCLoopConverter.java:111)
        at de.unisb.react.stud.algorithm.BMCLoopConverter.convert(BMCLoopConverter.java:111)
        at de.unisb.react.stud.algorithm.BMCLoopConverter.convert(BMCLoopConverter.java:111)
        at de.unisb.react.stud.algorithm.BMCLoopConverter.convert(BMCLoopConverter.java:111)
        at de.unisb.react.stud.algorithm.BMCLoopConverter.convert(BMCLoopConverter.java:111)
        at de.unisb.react.stud.algorithm.BMCLoopConverter.convert(BMCLoopConverter.java:111)
        at de.unisb.react.stud.algorithm.BMCLoopConverter.convert(BMCLoopConverter.java:111)
        at de.unisb.react.stud.algorithm.BMCLoopConverter.convert(BMCLoopConverter.java:111)
        at de.unisb.react.stud.algorithm.PMC.LoopConvert(PMC.java:274)
        at de.unisb.react.stud.algorithm.PMC.main(PMC.java:97)

"VM Thread" os_prio=0 tid=0x0000000001b82000 nid=0x98af runnable

"GC task thread#0 (ParallelGC)" os_prio=0 tid=0x0000000001533000 nid=0x9884 runnable

"GC task thread#1 (ParallelGC)" os_prio=0 tid=0x0000000001535000 nid=0x9885 runnable

"GC task thread#2 (ParallelGC)" os_prio=0 tid=0x0000000001536800 nid=0x9886 runnable

"GC task thread#3 (ParallelGC)" os_prio=0 tid=0x0000000001538800 nid=0x9887 runnable

"GC task thread#4 (ParallelGC)" os_prio=0 tid=0x000000000153a000 nid=0x9888 runnable

"GC task thread#5 (ParallelGC)" os_prio=0 tid=0x000000000153c000 nid=0x9889 runnable

"GC task thread#6 (ParallelGC)" os_prio=0 tid=0x000000000153d800 nid=0x988a runnable

"GC task thread#7 (ParallelGC)" os_prio=0 tid=0x000000000153f800 nid=0x988b runnable

"GC task thread#8 (ParallelGC)" os_prio=0 tid=0x0000000001541000 nid=0x988c runnable

"GC task thread#9 (ParallelGC)" os_prio=0 tid=0x0000000001543000 nid=0x988d runnable

"GC task thread#10 (ParallelGC)" os_prio=0 tid=0x0000000001544800 nid=0x988e runnable

"GC task thread#11 (ParallelGC)" os_prio=0 tid=0x0000000001546800 nid=0x988f runnable

"GC task thread#12 (ParallelGC)" os_prio=0 tid=0x0000000001548000 nid=0x9890 runnable

"GC task thread#12 (ParallelGC)" os_prio=0 tid=0x0000000001548000 nid=0x9890 runnable                                                                                       [31/1020]

"GC task thread#13 (ParallelGC)" os_prio=0 tid=0x000000000154a000 nid=0x9891 runnable

"GC task thread#14 (ParallelGC)" os_prio=0 tid=0x000000000154b800 nid=0x9892 runnable

"GC task thread#15 (ParallelGC)" os_prio=0 tid=0x000000000154d800 nid=0x9893 runnable

"GC task thread#16 (ParallelGC)" os_prio=0 tid=0x000000000154f000 nid=0x9894 runnable

"GC task thread#17 (ParallelGC)" os_prio=0 tid=0x0000000001551000 nid=0x9895 runnable

"GC task thread#18 (ParallelGC)" os_prio=0 tid=0x0000000001552800 nid=0x9896 runnable

"GC task thread#19 (ParallelGC)" os_prio=0 tid=0x0000000001554800 nid=0x9897 runnable

"GC task thread#20 (ParallelGC)" os_prio=0 tid=0x0000000001556000 nid=0x9898 runnable

"GC task thread#21 (ParallelGC)" os_prio=0 tid=0x0000000001558000 nid=0x9899 runnable

"GC task thread#22 (ParallelGC)" os_prio=0 tid=0x0000000001559800 nid=0x989a runnable

"GC task thread#23 (ParallelGC)" os_prio=0 tid=0x000000000155b800 nid=0x989b runnable

"GC task thread#24 (ParallelGC)" os_prio=0 tid=0x000000000155d000 nid=0x989c runnable

"GC task thread#25 (ParallelGC)" os_prio=0 tid=0x000000000155f000 nid=0x989d runnable

"GC task thread#26 (ParallelGC)" os_prio=0 tid=0x0000000001560800 nid=0x989e runnable

"GC task thread#27 (ParallelGC)" os_prio=0 tid=0x0000000001562800 nid=0x989f runnable

"GC task thread#28 (ParallelGC)" os_prio=0 tid=0x0000000001564000 nid=0x98a0 runnable

"GC task thread#29 (ParallelGC)" os_prio=0 tid=0x0000000001566000 nid=0x98a1 runnable

"GC task thread#30 (ParallelGC)" os_prio=0 tid=0x0000000001567800 nid=0x98a2 runnable

"GC task thread#31 (ParallelGC)" os_prio=0 tid=0x0000000001569800 nid=0x98a3 runnable

"GC task thread#32 (ParallelGC)" os_prio=0 tid=0x000000000156b000 nid=0x98a4 runnable

"GC task thread#33 (ParallelGC)" os_prio=0 tid=0x000000000156d000 nid=0x98a5 runnable

"GC task thread#34 (ParallelGC)" os_prio=0 tid=0x000000000156e800 nid=0x98a6 runnable

"GC task thread#35 (ParallelGC)" os_prio=0 tid=0x0000000001570800 nid=0x98a7 runnable

"GC task thread#36 (ParallelGC)" os_prio=0 tid=0x0000000001572000 nid=0x98a8 runnable

"GC task thread#37 (ParallelGC)" os_prio=0 tid=0x0000000001574000 nid=0x98a9 runnable

"GC task thread#38 (ParallelGC)" os_prio=0 tid=0x0000000001575800 nid=0x98aa runnable

"GC task thread#39 (ParallelGC)" os_prio=0 tid=0x0000000001577800 nid=0x98ab runnable

"GC task thread#40 (ParallelGC)" os_prio=0 tid=0x0000000001579000 nid=0x98ac runnable

"GC task thread#41 (ParallelGC)" os_prio=0 tid=0x000000000157b000 nid=0x98ad runnable

"GC task thread#42 (ParallelGC)" os_prio=0 tid=0x000000000157c800 nid=0x98ae runnable

"VM Periodic Task Thread" os_prio=0 tid=0x00007f0e54042800 nid=0x98c6 waiting on condition

JNI global references: 13

Heap                                                                                                                                                                       [163/1020]
 PSYoungGen      total 22755328K, used 10392421K [0x00007f1f96300000, 0x00007f27b9800000, 0x00007f27b9800000)
  eden space 11377664K, 91% used [0x00007f1f96300000,0x00007f22107d97a8,0x00007f224ca00000)
  from space 11377664K, 0% used [0x00007f224ca00000,0x00007f224ca00000,0x00007f2503100000)
  to   space 11377664K, 0% used [0x00007f2503100000,0x00007f2503100000,0x00007f27b9800000)
 ParOldGen       total 68267008K, used 68266986K [0x00007f0f4f800000, 0x00007f1f96300000, 0x00007f1f96300000)
  object space 68267008K, 99% used [0x00007f0f4f800000,0x00007f1f962fa968,0x00007f1f96300000)
 Metaspace       used 3156K, capacity 4240K, committed 4352K, reserved 8192K

I checked the PIDs of the running processes that generate the high CPU load -> they belong to the GC threads. I'm still not sure how a single threaded program can generate so much garbage that it keeps all those GC threads busy... but at least that's a starting point. Fully explaining and debugging the code (which is somewhat complex as it is a research project) would be clearly out of scope.

Maybe a last question directly concerning the topic: Is it possible to adjust the number of GC threads the JVM spawns? I will now start debugging the garbage collection, e.g. by using -verbose:gc -XX:+PrintGCTimeStamps -XX:+PrintGCDetails, so if you know helpful tools or have any hints, please let me know. ;)

Solution

  • The only answer I can give you is that:

    1. Despite what other answers might imply, you DO have real evidence that something is wrong. While you are looking at OS-level threads, there is a one-to-one correspondence between Java threads and OS threads ... at least on Linux, with current generation JVMs.

    2. It is not the JVM's fault. Java does not spontaneously create large numbers of threads; e.g. ~70 as you are seeing.

      (Depending on the Java version, JVM parameters, etc, you might see ten or so internal threads. But they will be idle most of the time ... not running all of the time as your monitoring seems to suggest.)

    3. Fiddling with the Java heap and stack size parameters won't affect the number of threads launched ... in a way that is likely to address your problem.

    4. Running on a different platform (EC2) is unlikely to make any difference.

    You need to look at what your application is doing, and at the third party libraries that it is using. We can't help you with this, unless you provide more details.

    However, getting a thread dump (with jstack or kill -3 PID) should offer some clues as to what those threads are, and how they got created.

    Having said that, you do appear to have a suspiciously large heap, and (possible) a large number of cores. Apparently, the default policy of the throughput collector is to create a GC thread for each physical core. However, it is hard to conceive of a use-case where a single-threaded application could create enough garbage to keep a large number of GC threads busy for an extended period ... unless it had filled the heap with reachable objects.