Aquire and Inspect Java Thread Dumps
A thread dump is a useful way of peaking into a live application. It's a starting point for hunting down a large number of issues include stuck threads and deadlocks.
For our example let's use a super simple Java threading example. Basically we create two threads which run forever, and put a loop into the main thread so it runs forever as well. Here's the code.
Here is me running it manually.
$ pwd /Users/johnminchuk/Development/CodeExamples/target/classes $ java -cp ./ net.largepixels.examples.threading.basicthreading.BasicThreading Thread Main! Thread Main! Thread Main! Thread A! Thread A! Thread A! Thread A! Thread B! Thread B! Thread B! Thread A! Thread A! Thread Main! Thread Main! Thread Main! Thread A! Thread B!
While it's running, let's find its PID and use jstack to dump the values in the threads.
$ ps -ax | grep -i basicthreading 78268 ttys017 0:05.55 java -classpath . net.largepixels.examples.threading.basicthreading.BasicThreading 78270 ttys021 0:00.00 grep -i basicthreading
$ jstack 78268
Which produces the following. This output is useful if you just want to look at a healthy application. Notice we have three threads "Thread-0", "Thread-1", and "main". Thread-0 and main are in the BLOCKED state which isn't necessarily a bad thing. The code is writing to a stream which can put a thread in blocked state while it waits for it's turn. Blocked threads only become and issue, when they stay that way. So you might want to take several dumps and watch for threads that appear to be stuck in this state over time
2017-03-23 16:31:31 Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.92-b14 mixed mode): "Attach Listener" #12 daemon prio=9 os_prio=31 tid=0x00007f81d4854800 nid=0x1307 waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE "Thread-1" #11 prio=5 os_prio=31 tid=0x00007f81d6084800 nid=0x5803 runnable [0x00007000016d8000] java.lang.Thread.State: RUNNABLE at java.io.FileOutputStream.writeBytes(Native Method) at java.io.FileOutputStream.write(FileOutputStream.java:326) at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82) at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140) - locked (a java.io.BufferedOutputStream) at java.io.PrintStream.write(PrintStream.java:482) - locked (a java.io.PrintStream) at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221) at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:291) at sun.nio.cs.StreamEncoder.flushBuffer(StreamEncoder.java:104) - locked (a java.io.OutputStreamWriter) at java.io.OutputStreamWriter.flushBuffer(OutputStreamWriter.java:185) at java.io.PrintStream.write(PrintStream.java:527) - eliminated (a java.io.PrintStream) at java.io.PrintStream.print(PrintStream.java:669) at java.io.PrintStream.println(PrintStream.java:806) - locked (a java.io.PrintStream) at net.largepixels.examples.threading.basicthreading.BasicThreading$ThreadB.run(BasicThreading.java:23) at java.lang.Thread.run(Thread.java:745) "Thread-0" #10 prio=5 os_prio=31 tid=0x00007f81d6084000 nid=0x5603 waiting for monitor entry [0x00007000015d5000] java.lang.Thread.State: BLOCKED (on object monitor) at java.io.PrintStream.println(PrintStream.java:805) - waiting to lock (a java.io.PrintStream) at net.largepixels.examples.threading.basicthreading.BasicThreading$ThreadA.run(BasicThreading.java:14) at java.lang.Thread.run(Thread.java:745) "Service Thread" #9 daemon prio=9 os_prio=31 tid=0x00007f81d403b800 nid=0x5203 runnable [0x0000000000000000] java.lang.Thread.State: RUNNABLE "C1 CompilerThread3" #8 daemon prio=9 os_prio=31 tid=0x00007f81d6039800 nid=0x5003 waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE "C2 CompilerThread2" #7 daemon prio=9 os_prio=31 tid=0x00007f81d6039000 nid=0x4e03 waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE "C2 CompilerThread1" #6 daemon prio=9 os_prio=31 tid=0x00007f81d6024000 nid=0x4c03 waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE "C2 CompilerThread0" #5 daemon prio=9 os_prio=31 tid=0x00007f81d4821800 nid=0x4a03 waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE "Signal Dispatcher" #4 daemon prio=9 os_prio=31 tid=0x00007f81d484b800 nid=0x3e0f runnable [0x0000000000000000] java.lang.Thread.State: RUNNABLE "Finalizer" #3 daemon prio=8 os_prio=31 tid=0x00007f81d5805800 nid=0x3803 in Object.wait() [0x0000700000d3a000] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:143) - locked (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=31 tid=0x00007f81d5802800 nid=0x3603 in Object.wait() [0x0000700000c37000] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on (a java.lang.ref.Reference$Lock) at java.lang.Object.wait(Object.java:502) at java.lang.ref.Reference.tryHandlePending(Reference.java:191) - locked (a java.lang.ref.Reference$Lock) at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153) "main" #1 prio=5 os_prio=31 tid=0x00007f81d4801800 nid=0x1703 waiting for monitor entry [0x0000700000219000] java.lang.Thread.State: BLOCKED (on object monitor) at java.io.PrintStream.println(PrintStream.java:805) - waiting to lock (a java.io.PrintStream) at net.largepixels.examples.threading.basicthreading.BasicThreading.runMe(BasicThreading.java:36) at net.largepixels.examples.threading.basicthreading.BasicThreading.main(BasicThreading.java:43) "VM Thread" os_prio=31 tid=0x00007f81d4847000 nid=0x3403 runnable "GC task thread#0 (ParallelGC)" os_prio=31 tid=0x00007f81d6006000 nid=0x2403 runnable "GC task thread#1 (ParallelGC)" os_prio=31 tid=0x00007f81d5800000 nid=0x2603 runnable "GC task thread#2 (ParallelGC)" os_prio=31 tid=0x00007f81d5801800 nid=0x2803 runnable "GC task thread#3 (ParallelGC)" os_prio=31 tid=0x00007f81d5802000 nid=0x2a03 runnable "GC task thread#4 (ParallelGC)" os_prio=31 tid=0x00007f81d480b800 nid=0x2c03 runnable "GC task thread#5 (ParallelGC)" os_prio=31 tid=0x00007f81d480c000 nid=0x2e03 runnable "GC task thread#6 (ParallelGC)" os_prio=31 tid=0x00007f81d480c800 nid=0x3003 runnable "GC task thread#7 (ParallelGC)" os_prio=31 tid=0x00007f81d480d800 nid=0x3203 runnable "VM Periodic Task Thread" os_prio=31 tid=0x00007f81d4821000 nid=0x5403 waiting on condition JNI global references: 15
Additional Tips
Even in this simple example the threadump looks messy. If you're an IntelliJ User you can run "Analyze Stacktrace..." and copy the output form jstack into it. This will parse it and allow you to browse around the code.
