Wednesday, June 24, 2009

Thread Analysis with VisualVM

Although jstack (Java Stack Trace) is a useful tool for learning more about a how a Java thread is behaving, VisualVM is an even easier method for obtaining the same type of information.

It is easy to run jstack as demonstrated in the next screen snapshot:



Only the top portion of the generated stack trace information is shown above. The output of an entire jstack run looks similar to that which follows:


2009-06-24 23:25:26
Full thread dump Java HotSpot(TM) Client VM (14.0-b16 mixed mode, sharing):

"RMI Scheduler(0)" daemon prio=6 tid=0x04bb4c00 nid=0x126c waiting on condition [0x048ef000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x2492dac8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:158)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1925)
at java.util.concurrent.DelayQueue.take(DelayQueue.java:160)
at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:583)
at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:576)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:947)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
at java.lang.Thread.run(Thread.java:619)

Locked ownable synchronizers:
- None

"RMI TCP Accept-0" daemon prio=6 tid=0x023bfc00 nid=0xa74 runnable [0x0483f000]
java.lang.Thread.State: RUNNABLE
at java.net.PlainSocketImpl.socketAccept(Native Method)
at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:390)
- locked <0x2492dc48> (a java.net.SocksSocketImpl)
at java.net.ServerSocket.implAccept(ServerSocket.java:453)
at java.net.ServerSocket.accept(ServerSocket.java:421)
at sun.management.jmxremote.LocalRMIServerSocketFactory$1.accept(LocalRMIServerSocketFactory.java:34)
at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.executeAcceptLoop(TCPTransport.java:369)
at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.run(TCPTransport.java:341)
at java.lang.Thread.run(Thread.java:619)

Locked ownable synchronizers:
- None

"Low Memory Detector" daemon prio=6 tid=0x02348000 nid=0xec4 runnable [0x00000000]
java.lang.Thread.State: RUNNABLE

Locked ownable synchronizers:
- None

"CompilerThread0" daemon prio=10 tid=0x02343000 nid=0x108 waiting on condition [0x00000000]
java.lang.Thread.State: RUNNABLE

Locked ownable synchronizers:
- None

"Attach Listener" daemon prio=10 tid=0x02342800 nid=0xf6c waiting on condition [0x00000000]
java.lang.Thread.State: RUNNABLE

Locked ownable synchronizers:
- None

"Signal Dispatcher" daemon prio=10 tid=0x02339c00 nid=0xac runnable [0x00000000]
java.lang.Thread.State: RUNNABLE

Locked ownable synchronizers:
- None

"Finalizer" daemon prio=8 tid=0x022f4000 nid=0xd14 in Object.wait() [0x044cf000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x248ee9a0> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)
- locked <0x248ee9a0> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:134)
at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)

Locked ownable synchronizers:
- None

"Reference Handler" daemon prio=10 tid=0x022f2c00 nid=0x1198 in Object.wait() [0x0240f000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x248eea28> (a java.lang.ref.Reference$Lock)
at java.lang.Object.wait(Object.java:485)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
- locked <0x248eea28> (a java.lang.ref.Reference$Lock)

Locked ownable synchronizers:
- None

"main" prio=6 tid=0x00209000 nid=0x1134 runnable [0x002af000]
java.lang.Thread.State: RUNNABLE
at java.util.Arrays.copyOf(Arrays.java:2882)
at java.lang.AbstractStringBuilder.expandCapacity(AbstractStringBuilder.java:100)
at java.lang.AbstractStringBuilder.append(AbstractStringBuilder.java:390)
at java.lang.StringBuilder.append(StringBuilder.java:119)
at dustin.examples.tools.AnalyzableImpl.loopProvidedNumberOfTimes(AnalyzableImpl.java:48)
at dustin.examples.tools.AnalyzableImpl.main(AnalyzableImpl.java:80)

Locked ownable synchronizers:
- None

"VM Thread" prio=10 tid=0x022f1400 nid=0x10c runnable

"VM Periodic Task Thread" prio=10 tid=0x02348c00 nid=0x278 waiting on condition

JNI global references: 872



VisualVM makes it easy to monitor application threads. VisualVM offers the capability to generate and view the jstack-generated stack trace. The first way to do this is to right-click on the appropriate Java process and select the option "Thread Dump." This will generate a thread dump file whose name appears under the selected Java process as shown in the following screen snapshot.



A second way to get the thread dump generated in VisualVM is to use the "Threads" tab and click on the button "Thread Dump." This button is demonstrated in the next screen snapshot.



Whether the right-click option is used or the "Thread Dump" button is pressed, VisualVM generates jstack thread dump output file and displays it as shown in the next screen snapshot.



As discussed and demonstrated, VisualVM allows for easy generation of a stack trace dump with jstack. However, VisualVM provides much more than that for thread analysis.

The screen snapshot above that showed the "Thread Dump" button also conveniently demonstrates VisualVM's Timeline tab that demonstrates in a live fashion the "live" threads. These colored horizontal bars represent individual threads. Their display is enabled because the "Threads visualization" checkbox is checked.

Another useful tab on VisualVM is the "Threads" "Table" view that provides textual overview information on the threads. This is demonstrated in the next screen snapshot.



Any individual thread can be clicked on to see the detailed Threads view. This view, also under the "Threads" tab in VisualVM. When "Threads visualization" is checked, a pie chart is included that graphically indicates what each thread is doing. This is demonstrated in the next screen snapshot.




Conclusion

The jstack tool is a useful command-line tool, but VisualVM provides the same capabilities along with a significantly improved presentation and details.

3 comments:

Software Wikipedia said...

nice post, hv you participated in the VisualVM blogging contest? if not go do it. :)

David Hergert said...

How can you attach to another process on another server? Does that process have to be running a certain version of java and running with certain flags?

Dustin said...

David,

VisualVM uses JMX to monitor threading information (specifically the platform MXBean called ThreadMXBean). You can instruct VisualVM to connect to the remote JMX Agent explicitly as defined in visualvm: Connecting to JMX Agents Explicitly (see specifically the section titled "Remote JMX Connections"). See also visualvm: Working with Remote Applications for additional details on using VisualVM to monitor remote applications.