Modern Oracle JVM versions are bundled with diagnostic tools. Here i’m going introduce the most prominent of them.
First to mention is of course VisualVM which evolves even independently of jvm releases. VisualVM allows relative deep analysis and its comprehensive enough furthermore it’s open source tool.
However it reaches limits when you have to work with java version prior to 1.5. (yes, sometimes things changes very slowly ;) Also it’s often the case that its not easy to connect over RMI remotely to productive machines, therefore its never a bad thing to be familiar with console tools modern jdk and JVM provided with the installation. Furthermore console tools are often very handy, focused on one or few tasks, they are low resource consuming and you can build chains of such tools and reuse them in your way. So let’s look on them.
jps
- Since jdk 1.5.0*
- JPS Home Page
The name of the command suggest that is similar to known UNIX ps command but for java processes. When called without parameters it will list all java processes found on the local machine. Let’s look on some examples.
$jps
#returns
2928 TestSuite
2524 Jps
5684
1796 org.eclipse.equinox.launcher_1.3.0.v20120522-1813.jar
Do you see which vmid (PID) has my Eclipse ide? Here another verbose example with program arguments and jvm params.
$jps -v -m
2928 TestSuite -Dfile.encoding=Cp1252
5684 -Xbootclasspath/a:C:PROGRA~2Javajre6libdeploy.jar;C:PROGRA~2Javajre6libjavaws.jar;C:PROGRA~2Javajre6libplugin.jar -Xmx32m -Djava.awt.headless=true -Dkernel.background.download=false -Dkernel.download.dialog=false -XX:MaxDirectMemorySize=64m
4256 Jps -v -m -Dapplication.home=C:envjava1.7.0_5jdk_64 -Xms8m
1796 org.eclipse.equinox.launcher_1.3.0.v20120522-1813.jar -os win32 -ws win32 -arch x86_64 -showsplash C:developmenteclipse4.2\pluginsorg.eclipse.platform_4.2.0.v201206081400splash.bmp -launcher C:developmenteclipse4.2eclipse.exe -name Eclipse --launcher.library C:developmenteclipse4.2\plugins/org.eclipse.equinox.launcher.win32.win32.x86_64_1.1.200.v20120522-1813eclipse_1503.dll -startup C:developmenteclipse4.2\plugins/org.eclipse.equinox.launcher_1.3.0.v20120522-1813.jar --launcher.overrideVmargs -exitdata d50_5c -product org.eclipse.epp.package.jee.product -vm C:WINDOWSsystem32javaw.exe -vmargs -Dosgi.requiredJavaVersion=1.5 -Dhelp.lucene.tokenizer=standard -Xms40m -Xmx512m -XX:MaxPermSize=256m -jar C:developmenteclipse4.2\plugins/org.eclipse.equinox.launcher_1.3.0.v20120522-1813.jar -Dosgi.requiredJavaVersion=1.5 -Dhelp.lucene.tokenizer=standard -Xms40m -Xmx512m -XX:MaxPermSize=256m
jinfo
- Since jdk 1.5.0 (Will not be able connect to jvm’s version below 1.5)*
Next interesting command is jinfo. It prints configuration information for a given Java process or core file or a remote debug server. Information details include Java System properties and command line flags. Here is example with shortened output.
jinfo 2992
#prints
Attaching to process ID 2992, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 23.1-b03
Java System Properties:
java.runtime.name = Java(TM) SE Runtime Environment
sun.boot.library.path = C:envjava1.7.0_5jdk_64jrebin
...
java.class.version = 51.0
sun.management.compiler = HotSpot 64-Bit Tiered Compilers
...
sun.cpu.endian = little
...
VM Flags:
-Dfile.encoding=Cp1252
jmap
- Since jdk 1.5.0 (Will not be able connect to jvm’s version below 1.5)
jmap lists information about shared objects used by a java process, also it lists heap memory details. Some examples:
jmap 2992
#prints
Attaching to process ID 2992, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 23.1-b03
0x000000005f1d0000 7272K C:envjava1.7.0_5jdk_64jrebinserverjvm.dll
0x000000005f9c0000 836K C:envjava1.7.0_5jdk_64jrebinmsvcr100.dll
0x000000006b430000 160K C:envjava1.7.0_5jdk_64jrebinjava.dll
0x000000006d3c0000 84K C:envjava1.7.0_5jdk_64jrebinzip.dll
0x00000000727b0000 60K C:envjava1.7.0_5jdk_64jrebinverify.dll
0x0000000077380000 1148K C:WINDOWSsystem32kernel32.dll
0x00000000774a0000 1000K C:WINDOWSsystem32USER32.dll
0x00000000775a0000 1700K C:WINDOWSSYSTEM32ntdll.dll
0x0000000077760000 28K C:WINDOWSsystem32PSAPI.DLL
0x000000013f150000 208K C:envjava1.7.0_5jdk_64binjavaw.exe
0x000007fefa7f0000 36K C:WINDOWSsystem32WSOCK32.dll
0x000007fefabe0000 236K C:WINDOWSsystem32WINMM.dll
0x000007fefc070000 2000K C:WINDOWSWinSxSamd64_microsoft.windows.common-controls_6595b64144ccf1df_6.0.7601.17514_none_fa396087175ac9acCOMCTL32.dll
0x000007fefdb50000 432K C:WINDOWSsystem32KERNELBASE.dll
....
jmap has also useful options like -heap to show current heap situation. Also it has the option -histo which print memory statistic per class. Here an example of Sting-intensive application…
jmap -histo 2992
num #instances #bytes class name
----------------------------------------------
1: 125224 4007168 java.lang.String
2: 123817 2971608 java.util.LinkedList$Node
3: 359 2827440 [I
4: 5388 737888 <methodKlass>
5: 5388 642200 <constMethodKlass>
6: 353 400888 <constantPoolKlass>
7: 353 256096 <instanceKlassKlass>
8: 320 255008 <constantPoolCacheKlass>
...
jmap has also option that is not mentioned in the documentation, but if you type -help on the console. The useful -dump option which allows you to dump heap to file system:
$jmap -dump:format=b,file=test_heap.bin 2992
Dumping heap to C:envjava1.7.0_5jdk_64bintest_heap.bin ...
Heap dump file created
This is very useful for further detailed analysis of heap, which is done with the tool named jhat
jhat
- Since jdk 1.6.0
jhat parses a java heap dump file, launches a webserver on default port 7000. So it is possible to browse through the heap. jhat even supports Object Query Language) (OQL) to query heap dumps. To look inside the generated heap dump we execute:
jhat -J-mx768m test_heap.bin
#Prints
Reading from test_heap.bin...
Dump file created Thu Aug 02 11:38:50 CEST 2012
Snapshot read, resolving...
Resolving 430136 objects...
Chasing references, expect 86 dots.................................................
Eliminating duplicate references...................................................
Snapshot resolved.
Started HTTP server on port 7000
Server is ready.
Now we can browse through parsed heap on the local server: http://localhost:7000. Alternatively you can browse your heap dumps with Eclipse MAT.
jstat
- Since jdk 1.5.0*
jstat monitors jvms Garbage Collection (GC), Hot Spot compilation and Heap statistic. Therefore its quite powerful and useful tool. You have to give the option, PID, interval and count. Print all available options
jstat -options
-class
-compiler
-gc
-gccapacity
-gccause
-gcnew
-gcnewcapacity
-gcold
-gcoldcapacity
-gcpermcapacity
-gcutil
-printcompilation
Next shows information about loaded and unload classes, corresponding bytes and time that was spend for such operations:
jstat -class 1160
Loaded Bytes Unloaded Bytes Time
12049 26208,9 40 66,3 7,58
Now overall state of jvm GC. It’s pick the state 5 times with an interval of 3 seconds.
jstat -gc 1160 3000 5
#periodic output
S0C S1C S0U S1U EC EU OC OU PC PU YGC YGCT FGC FGCT GCT
2176,0 64,0 0,0 0,0 81536,0 1414,4 73600,0 31683,4 75776,0 75442,4 57 0,492 46 8,149 8,641
2176,0 64,0 0,0 0,0 81536,0 2001,0 73600,0 31683,4 75776,0 75442,8 57 0,492 46 8,149 8,641
2176,0 64,0 0,0 0,0 81536,0 18898,7 73600,0 31683,4 76160,0 76104,4 57 0,492 46 8,149 8,641
2176,0 64,0 0,0 0,0 81536,0 19213,5 73600,0 31683,4 76160,0 76111,9 57 0,492 46 8,149 8,641
2176,0 64,0 0,0 0,0 81536,0 20479,0 73600,0 31683,4 76160,0 76145,3 57 0,492 46 8,149 8,641
This helps to interpret the columns:
| Header | Description |
|---|---|
| S0C | Current survivor space 0 capacity (KB) |
| S1C | Current survivor space 1 capacity (KB) |
| S0U | Survivor space 0 utilization (KB) |
| S1U | Survivor space 1 utilization (KB) |
| EC | Current eden space capacity (KB) |
| EU | Eden space utilization (KB) |
| OC | Current old space capacity (KB) |
| OU | Old space utilization (KB) |
| PC | Current permanent space capacity (KB) |
| PU | Permanent space utilization (KB) |
| YGC | Number of young generation GC Events |
| YGCT | Young generation garbage collection time |
| FGC | Number of full GC events |
| FGCT | Full garbage collection time |
| GCT | Total garbage collection time |
I my case we can see some increase in eden Space utilization (EU) during the time. If you want to be able to track jstat of remote machines, you can do it utilizing jstatd on the remote side.
jstack
- Since jdk 1.5.0
Abowe we saw GC, memory and Heap statistics, now its time for threads. This is where jstack comes into play. jstack prints Java stack traces for a given Java process or core file or a remote debug server.
jstack 5124
#prints
2012-08-02 22:29:34
Full thread dump Java HotSpot(TM) 64-Bit Server VM (22.1-b02 mixed mode):
"DestroyJavaVM" prio=6 tid=0x000000000276b800 nid=0x157c waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
...
"Thread-1" prio=6 tid=0x000000000675d000 nid=0x1814 waiting on condition [0x0000000007b7f000]
java.lang.Thread.State: TIMED_WAITING (sleeping)
at java.lang.Thread.sleep(Native Method)
at de.oc.profiling.tests.TestSuite$MyThread.run(TestSuite.java:56)
"Thread-0" prio=6 tid=0x000000000675a000 nid=0x1810 waiting on condition [0x000000000792f000]
java.lang.Thread.State: TIMED_WAITING (sleeping)
at java.lang.Thread.sleep(Native Method)
at de.oc.profiling.tests.TestSuite$MyThread.run(TestSuite.java:56)
"Service Thread" daemon prio=6 tid=0x000000000673d000 nid=0x1808 runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"C2 CompilerThread1" daemon prio=10 tid=0x000000000673b800 nid=0x1804 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"C2 CompilerThread0" daemon prio=10 tid=0x0000000006736800 nid=0x50c waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Attach Listener" daemon prio=10 tid=0x000000000672f800 nid=0x17d4 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Signal Dispatcher" daemon prio=10 tid=0x000000000672a000 nid=0x8f0 runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Finalizer" daemon prio=8 tid=0x0000000002714000 nid=0x1410 in Object.wait() [0x000000000701f000]
...
"Reference Handler" daemon prio=10 tid=0x000000000270d000 nid=0xee8 in Object.wait() [0x0000000006c7f000]
...
"VM Thread" prio=10 tid=0x0000000002705800 nid=0xca0 runnable
"GC task thread#0 (ParallelGC)" prio=6 tid=0x000000000265f800 nid=0xd60 runnable
"GC task thread#1 (ParallelGC)" prio=6 tid=0x0000000002661000 nid=0x6f8 runnable
"GC task thread#2 (ParallelGC)" prio=6 tid=0x0000000002663000 nid=0x14c0 runnable
"GC task thread#3 (ParallelGC)" prio=6 tid=0x0000000002664800 nid=0xe08 runnable
"VM Periodic Task Thread" prio=10 tid=0x000000000674f800 nid=0x180c waiting on condition
JNI global references: 123
This is a very small stacktrace, i’ve also shortened the output a bit e.g. removed
Reference Handler and Finalizer threads. So what you see it typical situation for a small app. JVM uses many threads for it’s internal tasks. So you can see that my jvm chooses to use Parallel GC with 4 Threads (good choise on my 4 cores Laptop) My application do not run into any deadlocks, so we see no message about it, otherwise we would see it clearly.
Remote usage of jtrack is possible through jsadebugd.
Hope this help somebody. Feel free to share your experinces.