This chapter tutorial notes on JVM troubleshooting tools. Topics include 'jinfo' to check JVM option values, 'jstack' to dump stack traces and detect deadlocks, 'jmap' to print heap histogram and dump heap files, 'jhat' to browse head files and run OQL queries.
JVM Troubleshooting Tools in JDK 1.5 'jinfo' - VM Option Value Checker
Changing HotSpot VM Option using 'jinfo' 'jstack' - Stack Tracer of JVM Threads Java Thread Deadlock Demo Program
Detecting Java Thread Deadlocks with 'jstack' 'jmap' - JVM Heap Dump Tool
Printing Histogram of Java Object Heap Generating Heap Dump File with 'jmap' 'jhat' - Java Heap Analysis Tool
Starting 'jhat' Web Server on a Heap Dump File Listing Instance Counts of All Classes
Browsing Object Instance Values Object Query Language (OQL)
Searching for Instances with OQL Statements Conclusions:
• JDK 1.6 offers a number of nice trouble shooting tools: jinfo, jstack, jmap, and jhat.
• jinfo allows you to check current VM options of a running JVM process.
• jstack allows you to dump thread stack traces and find any deadlocks.
• jmap allows you to print heap memory usages and instance counts by classes and dump the entire heap to a file.
• jhat allows you to browse a heap dump file with a Web interface.
• jhat also supports OQL (Object Query Language) statements - a very powerful tool to investigate any data issues in your Java application.
JVM Troubleshooting Tools in JDK 1.5
If you look at Java tools section of the JDK 1.5 documentation page, you will see a group of new experimental tools called "Troubleshooting Tools":
"jinfo": Prints configuration information for a given JVM process or a Java core file on the local machine or on a remote machine through a debug server.
"jhat" - Heap Dump Browser: Starts a Web server on a Java heap dump file (eg, produced by "jmap -dump"), allowing the heap to be browsed.
"jmap" - Memory Map: Prints shared object memory maps or heap memory details of a given JVM process or a Java core file on the local machine or on a remote machine through a debug server.
"jsadebugd" - Serviceability Agent Debug Daemon: Attaches to a JVM process or a Java core file and acts as a debug server for remote tools to connect.
"jstack" - Stack Trace: Prints a stack trace of threads for a given JVM process or a Java core file on the local machine or on a remote machine through a debug server.
Note that not all functions described above are available on Windows systems. See next sections on how to use those tools provided in JDK 1.6 on a Windows system.
'jinfo' - VM Option Value Checker
The first JVM troubleshooting tool I want try is the "jinfo" tool.
The "jinfo" tool included in the Windows version of JDK 1.6 only supports functions to view and modify HotSpot VM options of the specified JVM process. Here is the "jinfo" command syntax:
C:\herong>\Progra~1\java\jdk1.6.0_02\bin\jinfo Usage:
jinfo <option> <pid>
(to connect to a running process) where <option> is one of:
-flag <name> to print the value of the named VM option -flag [+|-]<name> to enable or disable the named VM option -flag <name>=<value> to set the named VM option to the given value -h | -help to print this help message
HotSpot VM supports many options as described on the "Java HotSpot VM Options" page. You can change the default value of any HotSpot VM option using the "-XX:..." command option when running the "java" command.
Here is a tutorial example of how to use the "jinfo" tool get the current value of a given VM option:
C:\herong>\Progra~1\java\jdk1.6.0_02\bin\java
-jar "\Program Files\java\jdk1.6.0_02\demo\jfc\Notepad\notepad.jar"
(Notepad started.)
(Start another command window.)
C:\herong>\Progra~1\java\jdk1.6.0_02\bin\jps -l -m
424 \Program Files\java\jdk1.6.0_02\demo\jfc\Notepad\notepad.jar 3984 sun.tools.jps.Jps -l -m
C:\herong>\Progra~1\java\jdk1.6.0_02\bin\jinfo -flag ThreadStackSize 424
-XX:ThreadStackSize=0
Note that:
• The "jps" tool is used to get the process ID (pid) of the Notepad JVM: 424.
• The output of the "jinfo" command shows that the current value of the ThreadStackSize option is 0 in the Notepad JVM.
Changing HotSpot VM Option using 'jinfo'
The "jinfo" tool can be used to view the current value of any HotSpot VM option of a given JVM process as described in the previous section.
The "jinfo" tool can also be used set a new value of any HotSpot VM option using the "jinfo -flag name=value" format. Here is what I did to test this function with JDK 1.6 on a Windows system:
C:\herong>\Progra~1\java\jdk1.6.0_02\bin\java -XX:ThreadStackSize=512 -jar "\Program Files\java\jdk1.6.0_02\demo\jfc\Notepad\notepad.jar"
(Notepad started)
(Start another command window.)
C:\herong>\Progra~1\java\jdk1.6.0_02\bin\jps -l -m
1424 \Program Files\java\jdk1.6.0_02\demo\jfc\Notepad\notepad.jar 3124 sun.tools.jps.Jps -l -m
C:\herong>\Progra~1\java\jdk1.6.0_02\bin\jinfo -flag ThreadStackSize 1424
-XX:ThreadStackSize=512
C:\herong>\Progra~1\java\jdk1.6.0_02\bin\jinfo -flag ThreadStackSize=1024 1424
Exception in thread "main" java.io.IOException:
Command failed in target VM
at sun.tools.attach.WindowsVirtualMachine.execute (WindowsVirtualMachine.java:94)
at sun.tools.attach.HotSpotVirtualMachine.executeCommand (HotSpotVirtualMachine.java:195)
at sun.tools.attach.HotSpotVirtualMachine.setFlag (HotSpotVirtualMachine.java:172)
at sun.tools.jinfo.JInfo.flag(JInfo.java:105) at sun.tools.jinfo.JInfo.main(JInfo.java:58)
Apparently, the target VM (the Notepad VM) does not allow me to change its option. I do not know why?
'jstack' - Stack Tracer of JVM Threads
"jstack": A JVM troubleshooting tool that prints stack traces of all running threads of a given JVM process, a Java core file, or remote debug server. The "jstack" tool included in the JDK 1.6 Windows version only supports limited functions as shown the this help message:
C:\herong>\Progra~1\java\jdk1.6.0_02\bin\jstack -help Usage:
jstack [-l] <pid>
(to connect to running process) Options:
-l long listing. Prints additional information about locks -h or -help to print this help message
In order to test "jstack", I used this simple Java program, LongSleep.java:
/**
* LongSleep.java
* Copyright (c) 2008 by Dr. Herong Yang, http://www.herongyang.com/
*/
class LongSleep {
public static void main(String[] a) { Runtime rt = Runtime.getRuntime();
System.out.println(" Free memory: " + rt.freeMemory());
System.out.println("Total memory: " + rt.totalMemory());
try {Thread.sleep(1000*60*60);}
catch (InterruptedException e) {}
} }
When LongSleep.java is running, I used "jps" to get its JVM process ID, pid. Then I ran "jstack" with that pid to get the following stack information:
C:\herong>\Progra~1\java\jdk1.6.0_02\bin\javac LongSleep.java C:\herong>\Progra~1\java\jdk1.6.0_02\bin\java LongSleep
Free memory: 4997104 Total memory: 5177344
(Start another command window.)
C:\herong>\Progra~1\java\jdk1.6.0_02\bin\jps -l -m 3296 LongSleep
2224 sun.tools.jps.Jps -l -m
C:\herong>\Progra~1\java\jdk1.6.0_02\bin\jstack 3296
Full thread dump Java HotSpot(TM) Client VM (1.6.0_02-b06 mixed mod...
"Low Memory Detector" daemon prio=6 tid=0x02a7c800 nid=0xf20 runnable java.lang.Thread.State: RUNNABLE
"CompilerThread0" daemon prio=10 tid=0x02a78000 nid=0xb3c waiting ...
java.lang.Thread.State: RUNNABLE
"Attach Listener" daemon prio=10 tid=0x02a76c00 nid=0x37c waiting ...
java.lang.Thread.State: RUNNABLE
"Signal Dispatcher" daemon prio=10 tid=0x02a75c00 nid=0xd7c runnable java.lang.Thread.State: RUNNABLE
"Finalizer" daemon prio=8 tid=0x02a71400 nid=0x2e8 in Object.wait()
java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method)
- waiting on <0x22990b38> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116) - locked <0x22990b38> (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=10 tid=0x02a6d000 nid=0xfbc in Obje...
java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method)
- waiting on <0x22990a38> (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 <0x22990a38> (a java.lang.ref.Reference$Lock)
"main" prio=6 tid=0x00296000 nid=0xef4 waiting on condition [0x0090...
java.lang.Thread.State: TIMED_WAITING (sleeping) at java.lang.Thread.sleep(Native Method)
at LongSleep.main(LongSleep.java:10)
"VM Thread" prio=10 tid=0x02a63c00 nid=0xc70 runnable
"VM Periodic Task Thread" prio=10 tid=0x02a7e000 nid=0xdd0 waiting ...
JNI global references: 571
Cool. Now I know how many threads are running inside a JVM, 8 of them. But my Java application, LongSleep, only runs under 1 thread named as "main", which is in a state called, TIMED_WAITING.
This matches my expectation.
Java Thread Deadlock Demo Program
In the previous section, "jstack" was used to print stack traces of all running threads of a given JVM process. But "jstack" can also be used to detect deadlocks inside a given JVM process. The tutorial example below shows you how "jstack" prints deadlock information:
1. Copy and save this Java program,
/**
* SimpleDeadLock.java
* Copyright (c) 2008 by Dr. Herong Yang, http://www.herongyang.com/
*/
import java.util.*;
public class SimpleDeadLock extends Thread { public static Object l1 = new Object();
public static Object l2 = new Object();
private int index;
public static void main(String[] a) { Thread t1 = new Thread1();
Thread t2 = new Thread2();
t1.start();
t2.start();
}
private static class Thread1 extends Thread { public void run() {
synchronized (l1) {
System.out.println("Thread 1: Holding lock 1...");
private static class Thread2 extends Thread { public void run() {
2. Compile and run SimpleDeadLock.java. A deadlock will be created immediately between two running threads:
C:\herong>\Progra~1\java\jdk1.6.0_02\bin\javac SimpleDeadLock.java C:\herong>\Progra~1\java\jdk1.6.0_02\bin\java SimpleDeadLock
Thread 1: Holding lock 1...
Thread 2: Holding lock 2...
Thread 2: Waiting for lock 1...
Thread 1: Waiting for lock 2...
This deadlock is expected - Thread 1 is holding lock 1 and waiting for lock 2, while thread 2 is holding lock 2 and waiting for lock 1.
See the next section on how to use "jstack" to print the deadlock information and stack traces of 2 related threads.
Detecting Java Thread Deadlocks with 'jstack'
This section provides a tutorial example on how to detect Java thread deadlocks with the thread stack trace dump tool, 'jstack'.
With the deadlock demo program, SimpleDeadLock.java, running in a locked status as described in the previous section, I am ready to run "jstack" to print the deadlock information and stack traces of 2 locked threads:
C:\herong>\Progra~1\java\jdk1.6.0_02\bin\jps -l -m 1464 SimpleDeadLock
464 sun.tools.jps.Jps -l -m
C:\herong>\Progra~1\java\jdk1.6.0_02\bin\jstack 1464
Full thread dump Java HotSpot(TM) Client VM (1.6.0_02-b06 mixed mod...
"DestroyJavaVM" prio=6 tid=0x00296000 nid=0x198 waiting on conditio...
java.lang.Thread.State: RUNNABLE
"Thread-1" prio=6 tid=0x02a99c00 nid=0xee0 waiting for monitor entr...
java.lang.Thread.State: BLOCKED (on object monitor)
at SimpleDeadLock$Thread2.run(SimpleDeadLock.java:37) - waiting to lock <0x229bd238> (a java.lang.Object) - locked <0x229bd240> (a java.lang.Object)
"Thread-0" prio=6 tid=0x02a99000 nid=0xefc waiting for monitor entr...
java.lang.Thread.State: BLOCKED (on object monitor)
at SimpleDeadLock$Thread1.run(SimpleDeadLock.java:24) - waiting to lock <0x229bd240> (a java.lang.Object) - locked <0x229bd238> (a java.lang.Object)
"Low Memory Detector" daemon prio=6 tid=0x02a7c800 nid=0xd2c runnab...
java.lang.Thread.State: RUNNABLE
"CompilerThread0" daemon prio=10 tid=0x02a78000 nid=0x500 waiting o...
java.lang.Thread.State: RUNNABLE
"Attach Listener" daemon prio=10 tid=0x02a76c00 nid=0x32c waiting o...
java.lang.Thread.State: RUNNABLE
"Signal Dispatcher" daemon prio=10 tid=0x02a75c00 nid=0x190 runnabl...
java.lang.Thread.State: RUNNABLE
"Finalizer" daemon prio=8 tid=0x02a6e000 nid=0xdb0 in Object.wait()...
java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method)
- waiting on <0x22990b38> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116) - locked <0x22990b38> (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=10 tid=0x02a6d000 nid=0xa44 in Obje...
java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method)
- waiting on <0x22990a38> (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 <0x22990a38> (a java.lang.ref.Reference$Lock)
"VM Thread" prio=10 tid=0x02a63c00 nid=0xe88 runnable
"VM Periodic Task Thread" prio=10 tid=0x02a7e000 nid=0xf58 waiting ...
JNI global references: 571
Found one Java-level deadlock:
=============================
"Thread-1":
waiting to lock monitor 0x02a6ee64 (object 0x229bd238, a java.lang.Object), which is held by "Thread-0"
"Thread-0":
waiting to lock monitor 0x02a6eecc (object 0x229bd240, a java.lang.Object), which is held by "Thread-1"
Java stack information for the threads listed above:
===================================================
"Thread-1":
at SimpleDeadLock$Thread2.run(SimpleDeadLock.java:37) - waiting to lock <0x229bd238> (a java.lang.Object) - locked <0x229bd240> (a java.lang.Object)
"Thread-0":
at SimpleDeadLock$Thread1.run(SimpleDeadLock.java:24) - waiting to lock <0x229bd240> (a java.lang.Object) - locked <0x229bd238> (a java.lang.Object)
Found 1 deadlock.
The output of "jstack" is very useful for debugging. It tells me:
• How many deadlocks exist in this JVM process.
• What are the 2 waiting threads for each deadlock.
• Stack traces of waiting threads with source code line numbers, if source codes were compile with debug options.
'jmap' - JVM Heap Dump Tool
"jmap" - Memory Map: Prints shared object memory maps or heap memory details of a given JVM process or a Java core file on the local machine or on a remote machine through a debug server. "jmap"
supports several functions with these syntaxes:
jmap [ option ] pid
jmap [ option ] executable core
jmap [ option ] [server-id@]remote-hostname-or-IP
<no option>
When no option is used jmap prints shared object mappings.
For each shared object loaded in the target VM, start address, the size of the mapping, and the full path of the shared object file are printed. This is similar to the Solaris pmap utility.
-dump:[live,]format=b,file=<filename>
Dumps the Java heap in hprof binary format to filename. The live suboption is optional. If specified, only the live objects in the heap are dumped. To browse the heap dump, you can use jhat (Java Heap Analysis Tool) to read the generated file.
-finalizerinfo
Prints information on objects awaiting finalization.
-heap
Prints a heap summary. GC algorithm used, heap configuration and generation wise heap usage are printed.
-histo[:live]
Prints a histogram of the heap. For each Java class, number of objects, memory size in bytes, and fully qualified class names are printed. VM internal class names are printed with '*' prefix.
If the live suboption is specified, only live objects are counted.
-permstat
Prints class loader wise statistics of permanent generation of Java heap. For each class loader, its name, liveness, address, parent class loader, and the number and size of classes it has loaded are printed. In addition, the number and size of interned Strings are printed.
-F
Force. Use with jmap -dump or jmap -histo option if the pid does not respond. The live suboption is not supported in this mode.
But the "jmap" tool included in the Windows version of JDK 1.6 only supports functions to print histogram of Java object heap and generate a heap dump of a given JVM process:
C:\herong>\Progra~1\java\jdk1.6.0_02\bin\jmap Usage:
jmap -histo <pid>
(to print histogram of java object heap of the JVM process) jmap -dump:<dump-options> <pid>
(to dump java heap of the JVM process) dump-options:
format=b binary default file=<file> dump heap to <file>
Example: jmap -dump:format=b,file=heap.bin <pid>
See the next section on how to use "jmap" to print heap histogram and to generate heap dump.
Printing Histogram of Java Object Heap
The first function of the "jmap" tool is to print histogram of object heap of a given JVM process. Now I am going to use a sample Java program, GarbageCollection.java, I wrote in another tutorial example in this book.
The first test is to print the heap histogram of a JVM process that runs GarbageCollection.java with the
"jmap -histo pid" command:
C:\herong>\Progra~1\java\jdk1.6.0_02\bin\javac GarbageCollection.java
C:\herong>\Progra~1\java\jdk1.6.0_02\bin\java -Xms24m -Xmx24m GarbageCollection
Free/total memory:
23725256 25034752 22710400 25034752 21618728 25034752 20523584 25034752 ...
(Start another command window.)
The histogram gives a very good summary of heap objects used in my GarbageCollection.java program:
• Most of the objects were String objects. There were 73925 of them. This matches well with what I allocated in the program: one array of 64*64 string objects for each MB object. If 16 1-MB objects were allocated, there should be 65536 string objects.
• "[Ljava.lang.String;" is a special class name representing a java.lang.String[] array.
• "[I" is a special class name representing a int[] array.
Generating Heap Dump File with 'jmap'
The second function of the "jmap" tool is to generate a heap dump of a given JVM process with the
"jmap -dump:file=<filename>" command:
C:\herong>\Progra~1\java\jdk1.6.0_02\bin\java -Xms24m -Xmx24m GarbageCollection
Free/total memory:
23725256 25034752 22710400 25034752 21618728 25034752 20523584 25034752
...
(Start another command window.)
C:\herong>\Progra~1\java\jdk1.6.0_02\bin\jps -l -m 764 GarbageCollection
1204 sun.tools.jps.Jps -l -m
C:\herong>\Progra~1\java\jdk1.6.0_02\bin\jmap -dump:file=GarbageCollection.map 764
Dumping heap to C:\herong\GarbageCollection.map ...
Heap dump file created
C:\herong>dir *.map
12:08 AM 19,816,895 GarbageCollection.map
So the heap dump file, "GarbageCollection.map", is a snapshot of all heap objects used by the running GarbageCollection.java process.
Heap dump files can be browsed by the heap dump browser, "jhat", as described in the next section.
'jhat' - Java Heap Analysis Tool
"jhat" - Java heap analysis tool or heap dump file browser: Parses a Java heap dump file and launches a Web server. "jhat" enables you to browse heap dump files using your favorite webbrowser. "jhat"
supports pre-designed queries (such as 'show all instances of a known class "Foo"') as well as OQL (Object Query Language) - a SQL-like query language to query heap dumps. Help on OQL is available from the OQL help page shown by "jhat". With the default port, OQL help is available at
http://localhost:7000/oqlhelp/
But the "jmap" tool included in the Windows version of JDK 1.6 only supports functions to print histogram of Java object heap and generate a heap dump of a given JVM process:
C:\herong>\Progra~1\java\jdk1.6.0_02\bin\jhat -help
Usage: jhat [-stack <bool>] [-refs <bool>] [-port <port>]
[-baseline <file>] [-debug <int>] [-version] [-h|-help] <file>
-stack false Turn off tracking object allocation call stack.
-refs false Turn off tracking of references to objects
-port <port> Set the port for the HTTP server. Default is 7000.
-exclude <file> Specify a file that lists data members that should be excluded from the reachableFrom query.
-baseline <file> Specify a baseline object dump. Objects in both heap dumps with the same ID and same class will be marked as not being "new".
-debug <int> Set debug level.
0: No debug output
1: Debug hprof file parsing
2: Debug hprof file parsing, no server -version Report version number
-h|-help Print this help and exit
<file> The file to read
For a dump file that contains multiple heap dumps, you may specify which dump in the file
by appending "#<number>" to the file name, i.e. "foo.hprof#3".
All boolean options default to "true"
Starting 'jhat' Web Server on a Heap Dump File
In an earlier tutorial example, I created a Java heap dump file with the "jmap" tool on my
GarbageCollection.java program. The heap dump file is named as GarbageCollection.map. Now I want to try to run the "jhat" Web server on this dump file and browse the heap dump with a Web browser.
1. Run the "jhat" command with default options:
C:\herong>\Progra~1\java\jdk1.6.0_02\bin\jhat GarbageCollection.map Reading from GarbageCollection.map...
Dump file created Jan 1 00:08:10 EDT 2008 Snapshot read, resolving...
Resolving 67324 objects...
Chasing references, expect 13 dots...
Eliminating duplicate references...
Snapshot resolved.
Started HTTP server on port 7000 Server is ready.
2. Run a Web browser with http://localhost:7000. The "jhat" heap dump file server page shows up:
See next sections on how to use "jhat" Web server to browse heap objects.
Listing Instance Counts of All Classes
Running "jhat" Web server on a heap dump file offers us a very good debugging tool. You can get statistical counts of loaded classes and objects. You can review object contents and references. You can also run object queries to search for any specific information.
First, let's see how to get instance counts for all loaded classes.
1. Run a Web browser with http://localhost:7000. The heap dump first page shows up.
2. Click the link of "Show instance counts for all classes (including platform)". The instance count page
2. Click the link of "Show instance counts for all classes (including platform)". The instance count page