The Art of Java Application Performance Analysis and Tuning

This is the second article in the series of articles exploring the tools and techniques for analyzing, monitoring, and improving the performance of Java applications.

The Art of Java Application Performance Analysis and Tuning-Part 1 The Art of Java Application Performance Analysis and Tuning-Part 3 The Art of Java Application Performance Analysis and Tuning-Part 4 The Art of Java Application Performance Analysis and Tuning-Part 5 The Art of Java Application Performance Analysis and Tuning-Part 6 The Art of Java Application Performance Analysis and Tuning-Part 7

In this blog we are going to look at some of the useful tools for analyzing the Java application programs.

Java Thread Dump

A thread dump is a list of stack traces of all the Java threads that are currently active in a Java Virtual Machine (JVM). A thread dump shows the status of all running threads/locks at a given moment.

Java thread dump can be used to analyze many application specific issues such as

The resource usage (CPU, DB, I/O etc..)
Identifying the hot methods/queries
Identifying the synchronization/lock issues

Since a thread dump is a snapshot at a given moment, a single snapshot will not give clear status of application. So it is recommended to take more than one thread dump while analyzing.

Five thread dumps with five second time interval is a good starting point. Always get a thread dump for a hung/misbehaving application server and performance problems.

How to take Thread Dump

There are several ways to take thread dumps from a JVM.

JStack

We can use jstack command to generate the Thread dump for a given Java Process. This command is available in Oracle HotSpot JDK/bin folder.

 /usr/local/jdk1.6.0_17/bin/jstack <PID>
 /usr/local/jdk1.6.0_17/bin/jstack -l <PID> // Prints additional information about locks

Linux/Unix(AIX, Solaris etc..)

If the JVM is running in the background then send the QUIT signal:

  kill -3 PID

If the JVM is running in a console then simply press Ctrl-\.

PID is the process Id of the running Java process. The thread dump will be sent to standard out.

In IBM VM Java a separate thread dump file will be generated .

example: javacore.20130422.180453.23902.0001.txt.

You can get the process numbers of of all running Java processes with the following commands:

  ps -ef | grep java
  jps (Available in Oracle JDK/bin)

Windows

The Java application that you want to produce a thread dump for must be running / started in a command console. When you want to produce a thread dump press Ctrl-Break

For more details :

Thread Dump Analysis

Thread dumps can used to analyze performance bottlenecks, memory Leaks/OutOfMemory errors, thread leaks, deadlocks , synchronization/locks issues etc.. Without thread dumps, it it very difficult to get to root cause for an application server “hang” condition.

Thread dump format and content may vary between the different Java vendors(Oracle HotSpot JDK, IBM Java), but at core they provides you a list of the stack traces for all Java threads in the Java Virtual Machine.

A stack trace is a dump of the current execution stack that shows the method calls running on that thread from the bottom up. If there are N threads running in the JVM, thread dump contains N Threads information.

For each thread it gives

The name of the thread, priority
Thread group
State (running/blocked/waiting/parking)
Execution stack in form of thread stack trace

Here is an sample stack trace from a Java application.

"pool-3-thread-18" prio=10 tid=0x2a138c00 nid=0x1fbc waiting on condition [0x2759d000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x3102bc00> (a java.util.concurrent.FutureTask$Sync)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:158)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:747)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:905)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1217)
        at java.util.concurrent.FutureTask$Sync.innerGet(FutureTask.java:218)
        at java.util.concurrent.FutureTask.get(FutureTask.java:83)
        at java.util.concurrent.AbstractExecutorService.invokeAll(AbstractExecutorService.java:205)
        at com.test.product.reports.server.ReportProvidor.getData(ReportProvider.java:196)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
        at java.lang.Thread.run(Thread.java:619)

The stack trace is bottom up. This means that it started with java.lang.Thread.run(Thread.java:619), that method called the
“ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908” method above it which called the one above it and so on. The key here is knowing that what is currently running (or waiting) is always the top of the method.

This will give you insight as to what the threads are stuck/waiting on.

During analysis we can glance through the whole stack trace and try to understand what is actually going on. Method names/Class names/Thread names will help us identify the running code.

During coding, it is good practice to name threads/Executor threads. These names will be visible in the thread dump and help us to identify the running code. In the above stack trace we can see that some report generation code is executing.

Scenario 1: Analyzing for performance/When the processing is slow/When the CPU usage is high

Take multiple thread dumps during peak time/busy hour. Then analyze the thread dumps to find out the hot methods/frequently called methods/thread waits/I/O waits/DB waits. After identifying the bottleneck we can optimize the code/logic.

Scenario 2: Thread-leak Analysis

If the number of threads in the thread-dump are increasing then we can suspect the thread leak. By using the thread names we can identify the part of the code which is leaking the threads. Number of threads can be monitored by using JConsole tool.

Scenario 3: Deadlock Analysis

If the program is not responding then we can suspect thread deadlock. By analyzing the thread dump we can identify the threads which are waiting for each others locks.

In IBM VM thread dump file ‘LOCKS’ section shows the threads and locks involved in the deadlock

Reference :

IBM VM Thread Dump:

IBM VM Thread dump format is different from Oracle Java but provides more details for trouble shooting. IBM VM Thread dump contains complete Run-time information of the application.

At the start of a Java dump, the first three sections are the TITLE, GPINFO, and ENVINFO sections. They provide useful information about the cause of the dump.

The MEMINFO section provides information about the Memory Manager.

LOCKS section of a Java dump gives LOCK Info. Useful for Deadlock analysis.

THREADS component (This is what you get in Oracle Thread Dump):

This section shows a complete list of stack traces of Java threads that are alive in IBM VM.

Here is an example stack trace for a thread running in IBM Java

3XMTHREADINFO      "pool-3-thread-23" J9VMThread:0x32EF0500, j9thread_t:0x320ECE6C, java/lang/Thread:0x3649AA58, state:P, prio=5
3XMJAVALTHREAD            (java/lang/Thread getId:0x37, isDaemon:false)
3XMTHREADINFO1            (native thread ID:0x5DA3, native priority:0x5, native policy:UNKNOWN)
3XMTHREADINFO2            (native stack address range from:0x2FE6A000, to:0x2FEAB000, size:0x41000)
3XMTHREADINFO3           Java callstack:
4XESTACKTRACE                at sun/misc/Unsafe.park(Native Method)
4XESTACKTRACE                at java/util/concurrent/locks/LockSupport.parkNanos(LockSupport.java:222)
4XESTACKTRACE                at java/util/concurrent/SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:435)
4XESTACKTRACE                at java/util/concurrent/SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:334)
4XESTACKTRACE                at java/util/concurrent/SynchronousQueue.poll(SynchronousQueue.java:885)
4XESTACKTRACE                at java/util/concurrent/ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:956)
4XESTACKTRACE                at java/util/concurrent/ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
4XESTACKTRACE                at java/lang/Thread.run(Thread.java:738)
3XMTHREADINFO3           Native callstack:
4XENATIVESTACK               (0xB7468B56 [libj9prt24.so+0xbb56])
4XENATIVESTACK               (0xB747464C [libj9prt24.so+0x1764c])
4XENATIVESTACK               (0xB7468BE9 [libj9prt24.so+0xbbe9])
4XENATIVESTACK               (0xB7468D0C [libj9prt24.so+0xbd0c])
4XENATIVESTACK               (0xB7468988 [libj9prt24.so+0xb988])
4XENATIVESTACK               (0xB747464C [libj9prt24.so+0x1764c])
4XENATIVESTACK               (0xB74689FC [libj9prt24.so+0xb9fc])
4XENATIVESTACK               (0xB746483D [libj9prt24.so+0x783d])
4XENATIVESTACK               (0xB773D40C)
4XENATIVESTACK               (0x0D49C778 [<unknown>+0x0])

More Details available at: