OnCallReady

Lesson 20.17 · JVM Internals · 11 min read

jstat, and "is it our code or the collector?"

In plain words

Imagine the fuel and temperature gauges on a car's dashboard. They do not tell you what is wrong with the engine, but a glance tells you whether the car is fine, overheating or running on empty, and the needles moving tell you it is happening right now.

jstat -gcutil PID 1000 is the dashboard for the garbage collector. Every second it prints how full eden, old and metaspace are, and how many young and full GCs have happened with their total time. On a healthy orders process eden climbs and drops while old barely moves. On a thrashing one, old sits at 99.9% and the full GC count goes up every second.

jstat -gcutil

The problem. At 3am you do not have a GC log configured and you need to know now whether the collector is eating the CPU. jstat prints the JVM's own GC counters live, once a second.

What you need to know already: GC kinds and pauses (20.12), the attach rules and hsperfdata (20.3), top -H to see threads (3.5).

A live view of the collector, one row per interval:

$ sudo -u appuser jstat -gcutil $(pgrep -f orders.jar) 1000 5
    S0     S1      E      O      M    CCS    YGC     YGCT   FGC    FGCT   CGC    CGCT       GCT
  0.00  42.72  82.52  32.03  98.70  98.11      6    0.033     0    0.000     0    0.000     0.033
  0.00  42.72  92.29  32.03  98.70  98.11      6    0.033     0    0.000     0    0.000     0.033
  0.00  42.72   2.05  32.48  98.70  98.11      7    0.039     0    0.000     0    0.000     0.039
  0.00  42.72  11.83  32.48  98.70  98.11      7    0.039     0    0.000     0    0.000     0.039
  0.00  42.72  21.60  32.48  98.70  98.11      7    0.039     0    0.000     0    0.000     0.039

1000 is the interval in ms (1s also works), 5 the number of samples; without a count it runs until Ctrl+C.

S0 S1   survivor spaces, % used      (G1: S0 stays 0.00)
E       eden, % used                 climbs, drops to ~0 at each young GC
O       old generation, % used       THE column: its floor after GCs
M       metaspace, % of committed    near 100% is normal - it is % of committed, not a limit
CCS     compressed class space, % of committed
YGC     young GC count since start   YGCT  total seconds in young GCs
FGC     full GC count                FGCT  total seconds in full GCs
CGC     concurrent cycle pauses (G1 remark/cleanup)   CGCT their time
GCT     all GC time, seconds

The third row shows a young GC: E went 92 -> 2, YGC 6 -> 7, O up by half a percent (promotion). Nothing to see - healthy.

Rates, not totals

The counters are cumulative since JVM start. What matters is how fast they move. Two samples 10 seconds apart:

YGC 802 -> 811, YGCT 3.310 -> 3.349     9 young GCs, 39 ms of pause in 10 s     0.4% of time
FGC 1   -> 1                            no full GCs

A JVM thrashing looks like this instead:

  S0     S1      E      O      M    CCS    YGC     YGCT   FGC    FGCT   CGC    CGCT       GCT
  0.00   0.00 100.00  99.87  98.70  98.11   2310   12.410   418  187.211    52    0.140   199.761
  0.00   0.00 100.00  99.91  98.70  98.11   2310   12.410   420  188.140    52    0.140   200.690
  0.00   0.00 100.00  99.94  98.70  98.11   2310   12.410   422  189.071    52    0.140   201.621

Old at 99.9% and staying there, eden at 100% (it cannot be emptied: nowhere to promote), FGC going up by two every second and FGCT by almost a second per second. The JVM is spending ~93% of its time in Full GC. That is your 100% CPU.

jstat -gccause adds the reason for the last and current collection:

$ sudo -u appuser jstat -gccause $(pgrep -f orders.jar) 1s 2
...   GCT    LGCC                 GCC
... 201.621  G1 Compaction Pause  G1 Compaction Pause

The decision procedure for "Java is at 100% CPU"

  1. Is it the GC? jstat -gcutil PID 1s 10. If FGC/FGCT climb every second and O sits near 100: it is the collector. Heap too small for the live set, or a leak. Go to the histogram (later lesson).
  2. Is it one thread? top -H -p PID shows threads by CPU. Convert the hot thread id to hex (printf '%x\n' 1297) and find nid=... in a thread dump - modern dumps print the decimal nid too, which saves the conversion.
  3. Is it all the request threads? A thread dump with many RUNNABLE threads in your own code: genuine load, or an inefficient loop. A profiler answers where: jcmd PID JFR.start duration=60s filename=/tmp/cpu.jfr and open it in JDK Mission Control, or async-profiler for a flame graph.
  4. Is it the JIT? C2 CompilerThread0 busy right after startup is warm-up and settles in a minute or two.

jstat -gc: capacities in KB

$ sudo -u appuser jstat -gc $(pgrep -f orders.jar)
    S0C       S1C       S0U       S1U        EC        EU        OC        OU        MC        MU      CCSC      CCSU    YGC     YGCT   FGC    FGCT   CGC    CGCT       GCT
     0.0    8192.0       0.0    3500.0   62464.0   20480.0  301056.0  150112.0   99602.0   98304.0   13568.0   13312.0     7    0.039     0    0.000     0    0.000     0.039

C = capacity, U = used, all in KB. OU over time is the old-gen floor in absolute numbers.

What jstat cannot tell you

Why it helps

When someone pings you "payments is at 100% CPU", jstat gives you a verdict in ten seconds: is it the collector or is it the code? If FGC and FGCT climb every second with old at 99%, it is GC and the next step is the heap. If not, you move to top -H and a thread dump to find the hot thread.

That decision procedure is what separates a quick diagnosis from an hour of guessing. It also runs without attaching and without pausing the JVM, so it is the safest tool to reach for first on a sick production service. And knowing that 1210 not found means "wrong user" saves you from wrongly concluding the process died.

Commands in this lesson

jstat

FAQ

Why is the M column near 100%? Is metaspace full?

No. The M and CCS columns show usage as a percentage of committed metaspace, not of a limit. The JVM commits metaspace as it needs it, so used is always close to committed and the column sits around 98%. It only means trouble if metaspace itself keeps growing in absolute terms, which jstat -gc (MC and MU in KB) or NMT shows.

Why is S0 always 0.00 with G1?

G1 does not have two fixed survivor spaces like the older collectors. It uses survivor regions allocated as needed, and jstat shows them in one column while the other stays at zero. With Serial or Parallel you see S0 and S1 alternate, one empty and one partly used after each young GC. Either way, survivor numbers are rarely where the diagnosis is.

How do I know if the GC time is too much?

Take two samples a known interval apart and compute the rate. If GCT goes up by 0.04 seconds in 10 seconds, the JVM spent 0.4% of its time in GC: fine. If FGCT goes up by nearly a second per second, it spends almost all its time in full GC. As a rule of thumb, a few percent is normal, above 10% deserves attention, and anything with climbing FGC under steady load is a problem.

What's the difference between -gcutil, -gc and -gccause?

-gcutil shows percentages of each space and GC counts and times: the quick dashboard. -gc shows capacities and used amounts in KB, so you can track old generation used in absolute numbers over time. -gccause is like -gcutil plus the cause of the last and current collection, such as G1 Compaction Pause or G1 Humongous Allocation, which helps explain why collections happen.

Java is at 100% CPU but jstat shows no GC activity. Now what?

Then it is application threads or the JIT. top -H -p PID shows threads by CPU; take the hot thread's id and find it in a thread dump, where nid= shows the same decimal id on modern JDKs. If it is C2 CompilerThread0 right after startup, it is JIT warm-up and settles in a minute or two. If many request threads are RUNNABLE in your code, run a short JFR recording or async-profiler to see which method burns the CPU.

In an interview Mid

A Java application is at 100% CPU. What steps do you take?

  1. Is it the GC? sudo -u appuser jstat -gcutil PID 1s 10. The counters are cumulative, so watch the rates: FGC/FGCT climbing every second and O (old gen) stuck near 100% = the collector is thrashing. Then it is a heap too small for the live set, or a leak - go to the histogram.
  2. Is it one thread? top -H -p PID shows threads by CPU; find that thread id as nid= in a thread dump (printf '%x\n' 1297 on older JDKs that print hex).
  3. Is it all the request threads? Many RUNNABLE threads in your own code: real load or an inefficient loop. A profiler says where: jcmd PID JFR.start duration=60s filename=/tmp/cpu.jfr, or async-profiler.
  4. Is it the JIT? C2 CompilerThread0 busy right after startup is warm-up and settles.

jstat reads hsperfdata without attaching, so the wrong user gets PID not found.

Also asked: What do the main columns of jstat -gcutil tell you? · How do you find which Java thread is using the CPU? · What can jstat not tell you about a Java process?

Practise this lesson in the terminal Free, in your browser - a real Ubuntu terminal to try it in, with missions that check your work.