Lesson 20.13 · JVM Internals · 16 min read

Reading unified GC logs, and the leak test

Q: What is the difference between -Xlog:gc and -Xlog:gc*?

gc selects messages tagged exactly gc, which is one summary line per collection: kind, cause, heap before and after, and pause. gc selects every tag set that starts with gc, so you also get phases, per-region counts, metaspace and CPU time. gc is more useful in incidents and still cheap. The old -XX:+PrintGCDetails and -Xloggc flags are gone or deprecated since JDK 9's unified logging.

Q: Why did the JVM refuse to start after I added GC logging?

If the log file cannot be opened, the -Xlog option is invalid and the JVM exits: Error opening log file ... No such file or directory and Could not create the Java Virtual Machine. The directory must exist and be writable by the JVM's user, not by you. On a systemd service that often means creating it with the right owner, or using LogsDirectory= in the unit.

Q: How would you tell from a GC log whether a service has a memory leak?

Turn the log on with unified logging, rotated: -Xlog:gc:file=/var/log/app/gc.log:time,uptime:filecount=5,filesize=10M. Each collection ends in a summary line like 223M-165M(272M) 4.900ms: heap used before - after (committed), pause. Used goes up and down all day, so ignore it. Look at the heap after collections over hours - ideally after Mixed or Full GCs, which include the old generation: - After-GC floor keeps climbing (100 - 234 - 310 - 408 MB over five hours, committed growing to the maximum) = a leak: something keeps objects reachable. - After-GC floor moves in a band and returns to a baseline = churn, healthy. - Caveat: a cache filling to its configured size climbs too, then flattens - look at a longer window. The end state is lines like Pause Full ... 511M-498M(512M) 431ms: a long stop-the-world pause that freed almost nothing, right before OutOfMemoryError.

In plain words

Imagine a diary kept by the person who empties your bins, one line per visit: how full the bins were, how full after emptying, and how long it took. On a normal street, bins go from full to nearly empty every time. On a street where someone is hoarding, the "after" number creeps up every week until the bins are full even right after emptying.

The GC log is that diary. Each summary line like 223M->165M(272M) 4.900ms says heap used before, after, committed and the pause. The trick this lesson teaches is reading only the "after" numbers over hours. If they return to a baseline, it is churn. If they climb and never come back, like 100 to 408 MB in five hours, something is holding on to objects: a leak.

Unified logging syntax

The problem. "Is it a memory leak?" gets argued for days on feelings. The GC log answers it with numbers: how much of the heap is still in use after each collection, over hours.

What you need to know already: minor, mixed and full GCs and G1 (20.12), grep/awk (7.1, 7.8), systemd drop-ins and JAVA_TOOL_OPTIONS (2.3, 20.2).

The JVM can write one line per collection to a file - the GC log. Since JDK 9 it uses unified logging, configured with a single -Xlog:... flag.

Since JDK 9, all JVM logging goes through -Xlog:

-Xlog:<selectors>:<output>:<decorators>:<output-options>

-Xlog:gc                                   GC summary lines to stdout
-Xlog:gc*                                  every gc-tagged message (phases, heap, cpu)
-Xlog:gc*:file=/var/log/app/gc.log         ... to a file
-Xlog:gc*:file=gc.log:time,uptime          ... with wall-clock time and JVM uptime
-Xlog:gc*:file=gc.log:time,uptime:filecount=5,filesize=10M    ... rotated, 5 x 10 MB
-Xlog:gc+heap=debug                        one tag set at a higher level

gc selects messages tagged exactly gc - one summary line per collection. gc* selects every tag set that starts with gc: gc,start, gc,heap, gc,phases, gc,cpu, gc,metaspace... The old -XX:+PrintGCDetails and -Xloggc flags are gone or deprecated.

The file must be writable by the JVM's user, and a bad path is fatal:

[0.003s][error][logging] Error opening log file '/var/log/orders/gc.log': No such file or directory
Invalid -Xlog option '-Xlog:gc*:file=/var/log/orders/gc.log:time,uptime', see error log for details.
Error: Could not create the Java Virtual Machine.
Error: A fatal exception has occurred. Program will exit.

Anatomy of a young GC with gc*

[2026-09-23T10:15:12.740+0000][10.240s] GC(0) Pause Young (Normal) (G1 Evacuation Pause)
[2026-09-23T10:15:12.740+0000][10.240s] GC(0) Using 2 workers of 2 for evacuation
[2026-09-23T10:15:12.740+0000][10.240s] GC(0)   Pre Evacuate Collection Set: 0.2ms
[2026-09-23T10:15:12.740+0000][10.240s] GC(0)   Merge Heap Roots: 0.2ms
[2026-09-23T10:15:12.740+0000][10.240s] GC(0)   Evacuate Collection Set: 4.7ms
[2026-09-23T10:15:12.740+0000][10.240s] GC(0)   Post Evacuate Collection Set: 0.6ms
[2026-09-23T10:15:12.740+0000][10.240s] GC(0)   Other: 0.2ms
[2026-09-23T10:15:12.740+0000][10.240s] GC(0) Eden regions: 61->0(61)
[2026-09-23T10:15:12.740+0000][10.240s] GC(0) Survivor regions: 3->3(8)
[2026-09-23T10:15:12.740+0000][10.240s] GC(0) Old regions: 106->108
[2026-09-23T10:15:12.740+0000][10.240s] GC(0) Humongous regions: 0->0
[2026-09-23T10:15:12.740+0000][10.240s] GC(0) Metaspace: 96543K(97280K)->96543K(97280K) NonClass: ...
[2026-09-23T10:15:12.740+0000][10.240s] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 223M->165M(272M) 4.900ms
[2026-09-23T10:15:12.740+0000][10.240s] GC(0) User=0.01s Sys=0.00s Real=0.00s

[...+0000] is the time decorator, [10.240s] is uptime since JVM start.
GC(0) is the collection id. Every line of one collection shares it: grep for 'GC(1234)' to get one event.
Pause Young (Normal) (G1 Evacuation Pause): kind of pause, then the cause. Other kinds: (Concurrent Start), (Prepare Mixed), (Mixed). Other causes: G1 Humongous Allocation, Metadata GC Threshold, System.gc(), Heap Inspection Initiated GC (someone ran jmap -histo:live).
Eden regions: 61->0(61) - before, after, and (target size).
Old regions: 106->108 - old grew by 2 regions: promotion.
The summary line: 223M->165M(272M) 4.900ms = heap used before -> after (committed) and the pause. This is the line you mostly need, and it is what plain -Xlog:gc gives you.
User/Sys/Real: CPU time of the GC threads vs wall time. User much bigger than Real = parallel work; Real much bigger than User+Sys = the GC threads were waiting for CPU (a starved container, or swapping).

A Full GC:

GC(57) Pause Full (G1 Compaction Pause)
GC(57) Phase 1: Mark live objects 180.123ms
GC(57) Phase 2: Prepare compaction 40.1ms
GC(57) Phase 3: Adjust pointers 80.2ms
GC(57) Phase 4: Compact heap 120.4ms
GC(57) Pause Full (G1 Compaction Pause) 511M->498M(512M) 431.234ms

511M -> 498M after a Full GC in a 512M heap: the collector stopped everything for 431 ms and freed 13 MB. The live set fills the heap. This is the line that precedes OutOfMemoryError.

The one skill: after-GC trend

Heap used goes up and down all day. What tells you about a leak is the heap after collections - the troughs:

# gc.log = a day of a leaking service's GC log (not on this box)
grep -E 'Pause (Young|Full).*->' gc.log | awk '{print $1, $(NF-1)}' | sed 's/(.*//' | awk -F'->' '{print $1, $2}' | ...

A simpler way to see the trend: take every Nth summary line and look at the number after ->:

grep 'Pause Young' gc.log | grep -v 'Evacuation Pause)$' | awk 'NR % 300 == 1'
[2026-09-20T06:00:07.680+0000][7.680s] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 159M->100M(192M) 5.900ms
[2026-09-20T07:07:27.360+0000][4047.360s] GC(548) Pause Young (Concurrent Start) (G1 Evacuation Pause) 294M->234M(364M) 6.450ms
[2026-09-20T08:07:36.960+0000][7656.960s] GC(1096) Pause Young (Mixed) (G1 Evacuation Pause) 326M->262M(398M) 5.345ms
[2026-09-20T09:06:06.720+0000][11166.720s] GC(1644) Pause Young (Mixed) (G1 Evacuation Pause) 372M->310M(460M) 6.874ms
[2026-09-20T11:02:58.560+0000][18178.560s] GC(2740) Pause Young (Mixed) (G1 Evacuation Pause) 473M->408M(512M) 5.295ms

After-GC 100 -> 234 -> 262 -> 310 -> 408 MB over five hours, committed growing to the maximum. That is a leak: something keeps objects reachable. The precise version of the test uses the heap after Full or after Mixed collections, because those include the old generation; young-only numbers carry old-gen garbage that a later mixed GC would have reclaimed.

Compare a healthy service over the same six hours:

... GC(0)    Pause Young (Normal) ... 159M->100M(192M)
... GC(482)  Pause Young (Normal) ... 275M->216M(364M)
... GC(964)  Pause Young (Normal) ... 247M->188M(364M)
... GC(1446) Pause Young (Normal) ... 219M->160M(364M)
... GC(2887) Pause Young (Mixed)  ... 298M->183M(364M)

It moves between 160 and 220 MB, returns to a baseline after every mixed cycle, and committed stops growing. That is churn - lots of allocation, nothing retained. No action needed.

The Notion question: heap after full GC climbs from 200 MB to 600 MB over six hours. Leak or not? - Almost certainly a leak, unless it flattens: caches that fill to a configured maximum also climb for a while, then stop. Look at a longer window, and at what the histogram says is growing.

Useful one-liners

grep -c 'Pause Young' gc.log                               how many young GCs
grep 'Pause Full' gc.log                                   any full GCs at all?
grep -E 'Pause.*ms$' gc.log | awk '{print $NF}' | sort -n | tail -3      the longest pauses
grep 'Pause Full' gc.log | awk '{print $1}' | cut -c2-17 | uniq -c        full GCs per minute
grep -E 'Pause (Young|Full).*->' gc.log | tail -1                         the latest summary

Serial and Parallel look different

GC(3) Pause Young (Allocation Failure)
GC(3) DefNew: 69952K(78656K)->8704K(78656K) Eden: 69952K(69952K)->0K(69952K) From: 0K(8704K)->8704K(8704K)
GC(3) Tenured: 150000K(174784K)->151000K(174784K)
GC(3) Pause Young (Allocation Failure) 215M->155M(247M) 12.345ms

DefNew is Serial's young generation, Tenured its old. If you see these in a service you thought was on G1, check its memory limit: it fell below the server-class threshold.

Why it helps

"Is it a leak?" is the question behind half of all Java memory tickets, and the GC log answers it without touching the running service. With a grep and awk you can show a developer that the after-GC floor went from 150 to 420 MB in eleven minutes, which is far more convincing than "memory looks high".

It also answers "was the latency spike a GC pause?" after the fact, since the log has timestamps and pause times, and it tells you when a service unexpectedly runs Serial (DefNew and Tenured in the log). Leaving rotated GC logs on in every service template costs almost nothing and gives you this history for every incident.

FAQ

What is the difference between -Xlog:gc and -Xlog:gc*?

gc selects messages tagged exactly gc, which is one summary line per collection: kind, cause, heap before and after, and pause. gc* selects every tag set that starts with gc, so you also get phases, per-region counts, metaspace and CPU time. gc* is more useful in incidents and still cheap. The old -XX:+PrintGCDetails and -Xloggc flags are gone or deprecated since JDK 9's unified logging.

Why does the heap after young GCs not tell the whole story?

Young collections only clean the young generation. Garbage in the old generation stays until a mixed or full collection, so the after-young number includes old-gen garbage that will be reclaimed later. That can look like growth when it is not. The precise leak test uses the heap after mixed or full collections, which include the old generation. Over a long enough window the young-only trend is still a good first signal.

What do User, Sys and Real mean at the end of a GC?

User and Sys are the CPU time the GC threads used; Real is the wall-clock time. With several GC threads, User is normally larger than Real, which means parallel work. If Real is much bigger than User plus Sys, the GC threads were waiting instead of working: the container was CPU-throttled, the host was overloaded, or the process was swapping. That is a platform problem, not a Java one.

Climbing after-GC heap: is it always a leak?

Almost always, but not always. A cache with a configured maximum also climbs while it fills and then flattens. A service that warms up over its first hours can look similar. So look at a longer window: if the floor levels off at a stable value, it is a bounded cache or warm-up. If it keeps climbing until full GCs start, it is a leak, and a histogram diff tells you which class.

Why did the JVM refuse to start after I added GC logging?

If the log file cannot be opened, the -Xlog option is invalid and the JVM exits: Error opening log file ... No such file or directory and Could not create the Java Virtual Machine. The directory must exist and be writable by the JVM's user, not by you. On a systemd service that often means creating it with the right owner, or using LogsDirectory= in the unit.

In an interview Mid

How would you tell from a GC log whether a service has a memory leak?

Turn the log on with unified logging, rotated: -Xlog:gc*:file=/var/log/app/gc.log:time,uptime:filecount=5,filesize=10M.

Each collection ends in a summary line like 223M->165M(272M) 4.900ms: heap used before -> after (committed), pause.

Used goes up and down all day, so ignore it. Look at the heap after collections over hours - ideally after Mixed or Full GCs, which include the old generation:

After-GC floor keeps climbing (100 -> 234 -> 310 -> 408 MB over five hours, committed growing to the maximum) = a leak: something keeps objects reachable.
After-GC floor moves in a band and returns to a baseline = churn, healthy.
Caveat: a cache filling to its configured size climbs too, then flattens - look at a longer window.

The end state is lines like Pause Full ... 511M->498M(512M) 431ms: a long stop-the-world pause that freed almost nothing, right before OutOfMemoryError.

Also asked: How do you enable GC logging on a JVM in production? · Latency spikes every few minutes on a Java service. How do you check whether GC is responsible? · What does a Full GC that frees almost nothing tell you?

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