JVM Monitoring and Troubleshooting Tools

The JDK includes a set of tools for looking inside a running JVM: which Java processes are running, how much memory they use, how often they collect garbage, what each thread is doing, and what is slow. Most are small command-line programs in the JDK's bin folder; others are graphical. The most versatile is jcmd, which can do the work of most of the others. In this lesson, you will meet each tool with real output from a running program.

The Tools

Real Output from a Running Program

The following outputs come from a small program, Busy, that keeps 50,000 Order records in a list and has a thread named order-worker. It was started with -Xmx128m; process IDs and memory addresses will differ on your machine.

jps: Find the Process

$ jps -l
24306 Busy

jcmd: Heap Information and Flags

$ jcmd 24306 GC.heap_info
24306:
garbage-first heap   total reserved 131072K, committed 131072K, used 5246K [...]
 region size 1024K, 4 young (4096K), 0 survivors (0K)

jcmd <pid> help lists every command; useful ones include GC.heap_info, GC.class_histogram, GC.heap_dump, Thread.print, VM.flags, VM.system_properties, VM.stringtable and JFR.start.

jstat: Watch GC Statistics

$ jstat -gcutil 24306 250 3
  S0     S1     E      O      M     CCS    YGC     YGCT     FGC    FGCT     CGC    CGCT       GCT
     -      -   6.38   0.00      -      -      0     0.000     0     0.000     0     0.000     0.000
     -      -   6.38   0.00      -      -      0     0.000     0     0.000     0     0.000     0.000
     -      -   6.38   0.00      -      -      0     0.000     0     0.000     0     0.000     0.000

Every 250 milliseconds, three times, it reports how full each area is in percent (E eden, O old) and the number and time of young (YGC), full (FGC) and concurrent (CGC) collections. This program was idle, so nothing changed.

jmap: What Is on the Heap?

$ jmap -histo:live 24306 | head -5
 num     #instances         #bytes  class name (module)
-------------------------------------------------------
   1:         50000        1200000  Busy$Order
   2:          1076         420368  [Ljava.lang.Object; (java.base@25.0.5.0.3)
   3:          8531         383912  [B (java.base@25.0.5.0.3)

The 50,000 Order records use 1.2 MB (24 bytes each, as explained in "Object Memory Layout in Java").

jstack: What Is Each Thread Doing?

$ jstack 24306
"order-worker" #25 [27395] prio=5 os_prio=31 cpu=1.99ms elapsed=4.11s ... waiting on condition
   java.lang.Thread.State: TIMED_WAITING (sleeping)
    at java.lang.Thread.sleepNanos0(java.base@25.0.5.0.3/Native Method)
    at java.lang.Thread.sleep(java.base@25.0.5.0.3/Thread.java:540)

Naming threads, as here, makes thread dumps much easier to read.

Java Flight Recorder

jcmd 24306 JFR.start duration=2s filename=busy.jfr
jfr summary busy.jfr

A recording captures events such as allocations, GC, locks, I/O and CPU samples with very little overhead. Open the .jfr file in JDK Mission Control for charts, or use jfr print and jfr view on the command line.

Example: The Same Information from Inside a Program

Many of these commands are also available to the program itself through the DiagnosticCommand MBean, which runs jcmd's commands inside the current JVM:

import java.lang.management.ManagementFactory;
import javax.management.ObjectName;
 
public class SelfDiagnostics {
    static String jcmd(String operation) throws Exception {
        return (String) ManagementFactory.getPlatformMBeanServer().invoke(
            new ObjectName("com.sun.management:type=DiagnosticCommand"),
            operation, new Object[] {null},
            new String[] {String[].class.getName()});
    }
 
    public static void main(String[] args) throws Exception {
        String heap = jcmd("gcHeapInfo");
        System.out.println("Heap report mentions G1? "
            + heap.contains("garbage-first heap"));
 
        Thread worker = new Thread(() -> {
            try {
                Thread.sleep(2000);
            } catch (InterruptedException e) {
                Thread.currentThread().interrupt();
            }
        }, "report-worker");
        worker.start();
        Thread.sleep(200);
        String dump = jcmd("threadPrint");
        int at = dump.indexOf("\"report-worker\"");
        String entry = dump.substring(at, at + 400);
        System.out.println("Thread dump shows report-worker sleeping? "
            + entry.contains("TIMED_WAITING (sleeping)"));
        worker.interrupt();
        worker.join();
    }
}

Heap report mentions G1? true
Thread dump shows report-worker sleeping? true

Explanation: gcHeapInfo and threadPrint are the in-process names of jcmd's GC.heap_info and Thread.print. This is how monitoring agents and admin pages collect the same data the command-line tools show.

Common Mistakes

Using jmap -histo:live casually on a busy server. :live forces a full GC first; it pauses the application.

Taking one thread dump. Take three, a few seconds apart, to see which threads are really stuck.

Running tools as a different OS user. The tools must run as the same user as the JVM.

Interview Corner

Practice

1. Easy: Start any long-running Java program, find it with jps, and run jcmd <pid> GC.heap_info and jcmd <pid> VM.flags.
2. Harder: Record 30 seconds of JFR on a busy program, then use jfr print --events jdk.GarbageCollection busy.jfr to list the collections.

Key Takeaways