JVM Diagnostic tools

Notes

• For every beautiful GUI tool there is an equivalent command-line tool.
• Command-line tools have priority for us. Because in real-world troubleshooting you may not have access to GUI or broadband networks but only lonely tty terminal in your hands.

Main JVM Diagnostic tools

jps	JVM processes info
jinfo	Inspect JVM configuration info.
jstat	JVM statistics
jstatd	Server that exposes host JVMs to remoted monitor and diagnostic tools.
jsadebugd	JVM debug server
jstack	Inspect stack trace of JVM process
jmap	Prints heap memory details and shared object memory maps. Takes JVM heap dump.
jhat	Heap analysis tool.

Main JVM Diagnostic tools

HPROF	Command line profiling tool for heap and cpu profiling
JMH	Java benchmark framework
jconsole	Visual JVM statistics tool
jvisualvm	Visual JVM statistics tool. CPU/Memory profiling tool.

jps

List available JVMs on target machine and their options.

jps [ options ] [ hostid ]

• -m Output the arguments passed to the main method.
• -v[V] Output the arguments passed to the JVM
• -l Output the full package name for the application's main class or the full path name to the application's JAR file.

hostid
[protocol:][[//]hostname][:port][/servername]

jps sample

jinfo

Prints Java configuration information for a given Java process or core file or a remote debug server.

jstat

jstat — is JVM monitoring tool.

jstat [ generalOption | outputOptions vmid [interval[s|ms] [count]] ]

• Monitors GC activity
• Provides statistics on the behavior of the HotSpot JIT compiler.
• Class loader statistics

jstat documentation

jstat

SO/S1 - Survivor space 0/1 utilization as a percentage of the space's current capacity.
E - Eden space utilization.
O - Old space utilization.
P - Permanent space utilization.
YGC - Number of young generation GC events.
YGCT - Young generation garbage collection time.
FGC - Number of full GC events.

jstat option	decription
gc	It shows the current size for each heap area and its current usage (Ede, survivor, old, etc.), total number of GC performed, and the accumulated time for GC operations.
gcutil	Usage for each heap area. GC counters.
gccapactiy	It shows the minimum size (ms) and maximum size (mx) of each heap area, current size, and the number of GC performed for each area. (Does not show current usage and accumulated time for GC operations.)
gccause	It shows the "information provided by -gcutil" + reason for the last GC and the reason for the current GC.

jstat option	decription
gcnew	Shows the GC performance data for the new area.
gcold	Shows the GC performance data for the old area.
gcpermcapacity	Shows statistics for the permanent area.

jstack

Prints Java stack traces of Java threads for a given Java process or core file or a remote debug server.

jstack [ option ] pid
jstack [ option ] executable core
jstack [ option ] [server-id@]remote-hostname-or-IP
        

jstack showcase

Resolving deadlocks.

jstack showcase

What is deadlocks?

jstack showcase

TestDeadLock.java

java -cp out/testgcpause.jar nsu.fit.javaperf.TestDeadLock

This program never ends... ☹ Really?

kill -9 `jps | grep TestDeadLock | awk '{print $1}'`

jstack showcase

jstack showcase

jstack helps you

• Locate deadlocks
• Locate program stall points
• Locate program crash points

You need JVM process heap analysis

• If your app consuming too much memory
• If you got OutOfMemory errors
• If you suspecting memory leak

You need JVM process heap analysis tool

• jmap — Dumps JVM process/core object heap into heap dump file. This utility is unsupported and may or may not be available in future versions of the JDK.
• jhat — Processes JVM heap dump file and opens web server to navigate heap objects.
• HPROF — Command line profiling tool for heap and cpu profiling

jmap

jmap [ options ] pid|core|remote-server

Let's dump the heap.

Your application will be freezed during heap dump.

jhat (Inspect heap dump)

jhat [ options ] <heap-dump-file>

Now open web browser: http://localhost:7000

OQL

http://visualvm.java.net/oqlhelp.html

HPROF

HPROF — command line profiling tool for heap and cpu profiling. HPROF is a dynamically-linked native library that uses JVM TI and writes out profiling information either to a file descriptor or to a socket in ascii or binary format.

In order to gather profiling data HPROF uses Byte Code Insertion (BCI) on all java class images loaded into the VM.

HPROF binary heap dumps can be used with with JHAT

HPROF options

hprof usage: java -agentlib:hprof=[help]|[<option>=<value>, ...]

Option Name and Value  Description                    Default
---------------------  -----------                    -------
heap=dump|sites|all    heap profiling                 all
cpu=samples|times|old  CPU usage                      off
monitor=y|n            monitor contention             n
format=a|b             text(txt) or binary output     a
file=<file>            write data to file             java.hprof[.txt]
net=<host>:<port>      send data over a socket        off
depth=<size>           stack trace depth              4
interval=<ms>          sample interval in ms          10
cutoff=<value>         output cutoff point            0.0001
lineno=y|n             line number in traces?         y
thread=y|n             thread in traces?              n
doe=y|n                dump on exit?                  y
msa=y|n                Solaris micro state accounting n
force=y|n              force output to <file>         y
verbose=y|n            print messages about dumps     y
        

HPROF showcase

java -agentlib:hprof=heap=sites -cp ./testgcpause.jar nsu.fit.javaperf.LoadSet

> yg
> Young garbage generator: amount: 50000, rm period: 150
yg stop
> Stopping young garbage generator
> q

SITES BEGIN (ordered by live bytes) Thu Sep  5 14:56:44 2013
          percent          live          alloc'ed  stack class
rank   self  accum     bytes objs     bytes  objs trace name
1 39,44% 39,44%  12000000 500000  12000000 500000 301279 byte[]
2 39,44% 78,87%  12000000 500000  12000000 500000 301280 java.util.LinkedList$Node
3 10,52% 89,39%   3200096 100003   3200096 100003 300706 java.util.LinkedList
4  5,26% 94,65%   1600000 100000   1600000 100000 301278 nsu.fit.javaperf.LoadSet$Garbage
5  2,81% 97,46%    854648   27    854648    27 300598 java.lang.Object[]
6  0,08% 97,54%     25776  144     25776   144 300006 char[]
7  0,08% 97,62%     23440   11     23440    11 300339 byte[]
8  0,05% 97,67%     16416    2     16416     2 300582 byte[]
        

HPROF showcase

SITES BEGIN (ordered by live bytes) Thu Sep  5 14:56:44 2013
          percent          live          alloc'ed  stack class
rank   self  accum     bytes objs     bytes  objs trace name
1 39,44% 39,44%  12000000 500000  12000000 500000 301279 byte[]
2 39,44% 78,87%  12000000 500000  12000000 500000 301280 java.util.LinkedList$Node
3 10,52% 89,39%   3200096 100003   3200096 100003 300706 java.util.LinkedList
4  5,26% 94,65%   1600000 100000   1600000 100000 301278 nsu.fit.javaperf.LoadSet$Garbage

TRACE 301279:
	nsu.fit.javaperf.LoadSet$Garbage.<init>(LoadSet.java:31)
	nsu.fit.javaperf.LoadSet$GarbageProducer.run(LoadSet.java:59)

 LoadSet.java line 59:

 public void run() {
            garbageStorage = new ArrayList<>();
            try {
                long lastGarbageRemoveTime = System.currentTimeMillis();
                while (!stopped) {
                    for (int i = 0; i < garbageAmount.longValue(); i++) {
                        garbageStorage.add(new Garbage());
                    }
                ...

CPU Sampling

Profiler periodically queries stacks of all running threads to record the most frequently active stack traces. Methods invocation count are not recorded.

pros:

• Small overhead

cons:

• Method invocation counts are not available.

CPU Times

Profiler instruments the bytecode of the profiled application for recording thread CPU time spent inside each profiled method. Both invocation times and counts are available.

pros:

• Method invocations counts available

cons:

• Slows down whole application.
• CPU times are not accurate due to profiler overhead.

HPROF CPU profiling showcase

Run the high load CPU function for 10s

time java  -agentlib:hprof=heap=sites,cpu=samples,thread=y,interval=5,depth=10 \
            -cp ./testgcpause.jar  \
            nsu.fit.javaperf.LoadSet -cpu 10

real	0m51.962s
user	0m51.736s
sys	0m1.780s

HPROF CPU profiling showcase

CPU SAMPLES BEGIN (total = 9530) Fri Sep  6 11:26:25 2013
rank   self  accum   count trace method
   1 21,11% 21,11%    2012 300730 java.util.Arrays.copyOf
   2 20,29% 41,41%    1934 300731 java.lang.Object.<init>
   3 18,97% 60,38%    1808 300737 java.lang.Object.<init>
   4 18,61% 78,99%    1774 300728 java.lang.Character.toString
   5 10,42% 89,41%     993 300766 java.util.Random.next
   6  8,33% 97,74%     794 300764 java.util.Random.nextInt
   7  0,36% 98,10%      34 300736 java.util.Arrays.copyOfRange
   8  0,35% 98,45%      33 300720 java.lang.AbstractStringBuilder.<init>
   9  0,35% 98,79%      33 300746 java.lang.Object.<init>
  10  0,34% 99,13%      32 300748 java.lang.Object.<init>
  11  0,28% 99,41%      27 300769 nsu.fit.javaperf.LoadSet$CPULoader.action
  12  0,10% 99,52%      10 300768 nsu.fit.javaperf.LoadSet$CPULoader.run
  13  0,07% 99,59%       7 300749 nsu.fit.javaperf.LoadSet$CPULoader.<init>
  14  0,07% 99,66%       7 300765 nsu.fit.javaperf.LoadSet$CPULoader.run

HPROF CPU profiling showcase

TRACE 300769: (thread=200006)
	nsu.fit.javaperf.LoadSet$CPULoader.action(LoadSet.java:58)
	nsu.fit.javaperf.LoadSet$CPULoader.run(LoadSet.java:69)
        

THREAD START (obj=5000017f, id = 200001, name="main", group="main")
THREAD START (obj=50000458, id = 200006, name="CPULoader", group="main")
...

public void run() {
            while (!stopped) {
                int k = 0;
                for (int j = 0; j < 10; ++j) {
                    for (int i = 0; i < DATA_COUNT; ++i) {
                        k += action(i);                            
                    }
    ...

Monitoring remote machines

Options:

• Use jstatd server jstatd ...
• Use JMX MBean server embedded in JVM. Turning it on:
  

       java -Dcom.sun.management.jmxremote.port=...
  -Dcom.sun.management.jmxremote.ssl=true|false
  -Dcom.sun.management.jmxremote.authenticate=true|false
                  

jstatd on remote JVM

> jstatd -h
usage: jstatd [-nr] [-p port] [-n rminame]

• Allows you to monitor JVM activity on remote machines
• Monitor tools:
  • jps
  • jstat
  • jvisualvm

jstatd on remote JVM

Run jstatd on remote machine.

jstatd -p 1099 -J-Djava.security.policy=./etc/tools.policy

cat ./etc/tools.policy
grant codebase "file:${java.home}/../lib/tools.jar" {
    permission java.security.AllPermission;
};

> jps -l ulixes:1099
18831 com.intellij.idea.Main
9392 sun.tools.jps.Jps
9171 sun.tools.jstatd.Jstatd

> jconsole

Internal JVM JMX server

Using JVM JMX server you can get internal JVM info from context Java programs.

java.lang.management.RuntimeMXBean

VisualVM is the JConsole on steroids

> jvisualvm

• Display application configuration and runtime environment.
• Monitors application memory consumption and runtime behavior
• Profile application performance and analyze memory allocation.
• Monitors application threads.
• Take and browse heap dumps and core dumps.

https://visualvm.java.net

Resources

• How to Monitor Java Garbage Collection
• JDK Tools and Utilities
• Java SE Monitoring and Management Guide
• Using JConsole
• HPROF: A Heap/CPU Profiling Tool
• visualvm.java.net