On This Page
A Java 8 flag line, run on JDK 21
This is the GC logging line that sits in about a thousand JAVA_OPTS files, copied from a blog post written around 2016:
java -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:gc.log -Xmx64m -version
On OpenJDK 21.0.12.1 it prints this and exits:
Unrecognized VM option 'PrintGCDateStamps'
Error: Could not create the Java Virtual Machine.
Error: A fatal exception has occurred. Program will exit.
The JVM doesn't start. And the interesting part is which flag killed it. -XX:+PrintGCDetails is fine on 21. So is -Xloggc. They both still work, with a deprecation warning, because the unified logging rewrite kept them as aliases. PrintGCDateStamps didn't get an alias. If your service gets bumped from 8 to 17 or 21 and the pod goes into CrashLoopBackOff before logging a single line, check your GC flags first.
Every java GC logs setup I see in the wild is either that line, or a half-translation of it. This article is the full translation: how -Xlog is put together, what each line it prints means for G1, Parallel, Serial and ZGC, and what to leave on in production. It took me more than a day to get straight, mostly because the format differs per collector and nobody documents the differences in one place. Now it's on one page.
If you only have a minute
Since JDK 9 there's one logging system inside HotSpot, and GC is just one of its users. You pick what to log with tags and levels, where it goes (stdout, stderr or a file), how each line is stamped (decorators), and how files rotate. One option, -Xlog, carries all four, separated by colons.
-Xlog:gc gives you one line per collection. -Xlog:gc* gives you everything GC-related, usually 10 to 15 times as many lines. Most of the confusion about GC logs comes from the lines having the same shape across collectors and meaning different things in each. A "pause" line from G1 is a stop-the-world event. The equivalent ZGC line is a whole concurrent cycle, and the actual pauses are elsewhere.
Run it yourself
What you need. OpenJDK 21.0.12.1 (Ubuntu build, java -version says 21.0.12.1+1-1-24.04.4-Ubuntu), a Linux box with 2 CPUs. Any JDK 17 or newer reproduces the shapes; exact millisecond values will differ. No dependencies, no JOL.
The program. It makes garbage fast, keeps a slowly rotating pile of survivors, and optionally calls System.gc() once. Save as Churn.java:
import java.util.*;
public class Churn {
static final Deque<byte[]> live = new ArrayDeque<>();
static volatile Object sink;
public static void main(String[] a) throws Exception {
int liveMb = Integer.parseInt(a[0]); // how much to keep alive, in MB
long end = System.nanoTime() + 8_000_000_000L; // run for 8 seconds
int i = 0;
while (System.nanoTime() < end) {
sink = new byte[32 * 1024]; // garbage: dies young
if (++i % 40 == 0) {
live.add(new byte[256 * 1024]); // retained for a while
if (live.size() * 256 / 1024 > liveMb) for (int k = 0; k < 8; k++) live.poll();
}
if (i == 100000 && a.length > 1) System.gc(); // explicit full GC, if you pass a 2nd arg
}
System.out.println("done");
}
}
Compile it (javac -d cls Churn.java) rather than using java Churn.java. I'll explain why in a minute.
Step 1: the plain version.
java -cp cls -Xmx128m -XX:+UseG1GC -Xlog:gc Churn 40
Expected: a Using G1 line, then a few thousand lines like GC(0) Pause Young (Normal) (G1 Evacuation Pause) 7M->3M(96M) 6.779ms. About 2,250 of them in 8 seconds on my box. That heap is tiny on purpose. Production isn't 128 MB; I shrank it so collections happen hundreds of times a second and you can watch every kind of line.
Step 2: everything.
java -cp cls -Xmx128m -XX:+UseG1GC -Xlog:gc*:file=g1-all.log:uptime,level,tags Churn 40
Expected: g1-all.log with roughly 26,000 lines and 2 MB. Open it and find a Pause Young block (shown in the next section).
Step 3: the concurrent cycle. Keep 70 MB live in a 128 MB heap so G1 has to start marking:
java -cp cls -Xmx128m -Xlog:gc,gc+marking:file=cyc.log:uptime,level,tags Churn 70
grep -a "Concurrent Start" cyc.log | head -1
Expected: Pause Young (Concurrent Start) (G1 Evacuation Pause) 85M->61M(104M) followed by a Concurrent Mark Cycle and its sub-steps.
Step 4: the explicit full GC. java -cp cls -Xmx128m -Xlog:gc Churn 30 x and look for Pause Full (System.gc()).
Step 5: other collectors. Rerun step 1 with -XX:+UseParallelGC, -XX:+UseSerialGC, then -Xmx256m -XX:+UseZGC, and finally -XX:+UseZGC -XX:+ZGenerational (the last flag exists on 21; more on that later).
Step 6: change logging on a live JVM.
java -cp cls -Xmx128m -Xlog:gc:file=live.log Churn 40 &
jcmd $! VM.log what="gc+heap=debug" output=/tmp/live2.log decorators=uptime,tags
jcmd $! VM.log disable
Expected: Command executed successfully, and live2.log fills with Heap before GC invocations=615 (full 0): blocks. That's the most useful trick in this article and the one nobody seems to know.
A dead end here. My first try used the source launcher (java Churn.java) and every jcmd call against it died with an attach stack trace from VirtualMachineImpl.checkCatchesAndSendQuitTo. I never found out why; the same flags against the compiled class worked first time, so that's what the lab uses. If you see the attach error, do the same.
Confirmation. You've reproduced it when step 3 contains a Concurrent Mark Cycle and step 4 contains a Pause Full (System.gc()). If you see no concurrent cycle, the live set is too small to cross G1's initiating threshold; raise the second argument.
Differences you might hit. The (Prepare Mixed) wording is what 21 printed; older JDKs differ in places. CPU count changes worker counts (Using 2 workers of 2).
Cleanup. rm -f *.log; rm -rf cls. A gc*=debug log was 4.3 MB per 8 seconds here; forget one on a busy service and it fills a disk.
What -Xlog is actually selecting, and how to read one line
The option has four slots, each optional, separated by colons. Read it left to right:
-Xlog : gc*,gc+age=trace : file=gc-%t.log : utctime,uptime,level,tags : filecount=10,filesize=20M
└── what ───────┘ └── where ─────┘ └── decorations ─────────┘ └── output options ─────┘
What is a list of tag sets and levels. A tag set is a combination of tags, like gc or gc+heap, and each log statement in HotSpot belongs to exactly one tag set. This is the part that bit me hardest: without a trailing *, -Xlog:gc matches only statements tagged exactly gc. Not gc+heap, not gc+phases. Those only show up with gc*, or if you name them (-Xlog:gc,gc+heap). The star means "this set and every set that contains these tags". Levels run error, warning, info, debug, trace, and asking for info gets you info and everything more severe.
Where is stdout, stderr or file=<name>. In a filename %p becomes the PID and %t the startup timestamp.
Decorations stamp each line. The default is uptime,level,tags, and I checked that it stays the default even when you specify a file. If you want wall-clock time you must ask: time is local with offset, utctime is UTC. Use utctime in anything that crosses time zones, and keep uptime too so you can line up GC events with other things the JVM stamps in seconds-since-start.
Output options are filecount and filesize for rotation. Here's a default I didn't know: when you give a file output and say nothing about rotation, jcmd VM.log list on my JVM shows filecount=5,filesize=20480K. So 5 files of 20 MB, silently, and the oldest gets overwritten.
Typos are fatal: -Xlog:gc+nonsense prints Invalid tag 'nonsense' in log selection and the JVM refuses to start.
One line, taken apart
[0.395s][info][gc] GC(1) Pause Young (Normal) (G1 Evacuation Pause) 7M->4M(96M) 4.659ms
│ │ │ │ │ │ │ │ │ │ └ wall-clock pause
│ │ │ │ │ │ │ │ │ └ committed heap
│ │ │ │ │ │ │ │ └ used after
│ │ │ │ │ │ │ └ used before
│ │ │ │ │ │ └ cause
│ │ │ │ │ └ sub-kind
│ │ │ │ └ kind of collection
│ │ │ └ collection number (GC id)
│ │ └ tag
│ └ level
└ uptime
Those three numbers are whole-heap numbers, not young-gen numbers. 7M->4M(96M) means 7 MB were in use before, 4 MB after, out of 96 MB currently committed. Your Eden might have been 6 MB of that 7. Seeing 21 MB used after a young GC doesn't mean Eden is leaking. Eden is empty after a young GC; those 21 MB are survivors plus old.
The gc* version of the same collection, trimmed, from my G1 run:
[0.304s][info][gc,start ] GC(0) Pause Young (Normal) (G1 Evacuation Pause)
[0.304s][info][gc,task ] GC(0) Using 2 workers of 2 for evacuation
[0.308s][info][gc,phases ] GC(0) Pre Evacuate Collection Set: 0.04ms
[0.308s][info][gc,phases ] GC(0) Merge Heap Roots: 0.05ms
[0.308s][info][gc,phases ] GC(0) Evacuate Collection Set: 3.02ms
[0.308s][info][gc,phases ] GC(0) Post Evacuate Collection Set: 0.29ms
[0.308s][info][gc,heap ] GC(0) Eden regions: 6->0(4)
[0.308s][info][gc,heap ] GC(0) Survivor regions: 0->1(1)
[0.308s][info][gc,heap ] GC(0) Old regions: 2->4
[0.308s][info][gc,heap ] GC(0) Humongous regions: 0->0
[0.308s][info][gc ] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 7M->3M(96M) 3.669ms
[0.308s][info][gc,cpu ] GC(0) User=0.00s Sys=0.00s Real=0.00s
Every line shares GC(0), so you can grep a single collection out of a million-line file. The Eden regions: 6->0(4) line reads: 6 regions before, 0 after, and the number in parentheses is what G1 plans to use next time. I checked that against the next collection, which logged Eden regions: 4->0(11). The 4 matches. That parenthesised number is G1's pause-time controller telling you what it just decided about young sizing, which makes this the line to read when someone asks "why did young gen shrink".
Where the JEPs moved the goalposts
Unified logging is two JEPs. JEP 158 (JDK 9) built the framework: tags, levels, decorators, outputs, rotation, runtime control through jcmd. JEP 271 (JDK 9) moved GC output onto it. JEP 271 is honest about the cost: the new output is not required to match the old format, and existing parsers aren't guaranteed to keep working. It also says PrintGC maps loosely to -Xlog:gc ("one line per GC"), and PrintGCDetails only loosely to anything. The cleaner mapping lives in JDK-8145180, which added the removed flags back as deprecated aliases:
-XX:+PrintGC → -Xlog:gc
-XX:+PrintGCDetails → -Xlog:gc*
-Xloggc:<file> → -Xlog:gc:<file>
I confirmed on 21.0.12.1 that the JVM does that translation and tells you so (-XX:+PrintGCDetails is deprecated. Will use -Xlog:gc* instead.). What I did not check is whether those three aliases survive on JDK 25. Don't assume; run java -XX:+PrintGCDetails -version on the JDK you're about to ship and read what comes out.
The flags that have no alias at all, all rejected as Unrecognized VM option on 21.0.12.1: PrintGCDateStamps, PrintGCTimeStamps, PrintGCApplicationStoppedTime, UseGCLogFileRotation, and UseConcMarkSweepGC (CMS is gone entirely, which is its own story in a later piece).
JDK 8 -XX:+PrintGCDetails, PrintGCDateStamps, -Xloggc, UseGCLogFileRotation
JDK 9 -Xlog (JEP 158) and unified GC logging (JEP 271); old flags become aliases
JDK 17 -Xlog:async: buffered logging off the allocating thread (JDK-8229517)
JDK 21 ZGC has an optional generational mode (-XX:+ZGenerational); lines change
JDK 23+ generational ZGC becomes the default (JEP 474), non-generational removed in 24 (JEP 490)
I ran the JDK 21 row. The 23 and 24 row comes from the JEPs; I haven't run it.
Lines that look like one thing and mean another
G1 has several lines starting with "Pause Young". Pause Young (Normal) is the routine one. Pause Young (Concurrent Start) is a young collection that also kicks off a marking cycle. It isn't a different pause, and the marking runs concurrently afterwards, as Concurrent Mark Cycle and its steps. In my lab it looked like this:
[0.688s][info][gc] GC(9) Pause Young (Concurrent Start) (G1 Evacuation Pause) 85M->61M(104M) 1.816ms
[0.688s][info][gc] GC(10) Concurrent Mark Cycle
[0.700s][info][gc] GC(10) Pause Remark 72M->72M(114M) 1.801ms
[0.705s][info][gc] GC(10) Pause Cleanup 89M->89M(114M) 0.136ms
[0.708s][info][gc] GC(12) Pause Young (Prepare Mixed) (G1 Evacuation Pause) 95M->73M(114M) 2.043ms
Note the GC ids. A concurrent cycle gets its own id (10), and ordinary pauses inside it keep taking new ones, so id 11 is a normal young pause in the middle of cycle 10. Pause Remark and Pause Cleanup are the real stop-the-world parts of the cycle. Everything else with "Concurrent" in the name isn't a pause, and adding it to your pause total is a classic way to scare yourself.
A Full GC can kill a concurrent cycle, and the log says so. In one lab run, System.gc() landed while G1 was in the middle of concurrent marking:
[0.603s][info][gc,start ] GC(127) Pause Full (System.gc())
[0.612s][info][gc ] GC(127) Pause Full (System.gc()) 100M->30M(128M) 8.576ms
[0.613s][info][gc,marking ] GC(126) Concurrent Mark Abort
[0.613s][info][gc ] GC(126) Concurrent Mark Cycle 10.808ms
The cycle gets a duration and an abort line, and it's easy to miss because the cycle's own id (126) is lower than the Full GC's (127). Read the cause in brackets: System.gc() means someone asked. I had a different run earlier that logged Pause Full (G1 Compaction Pause) 127M->32M(128M), which means G1 itself ran out of room. I assumed the second one would be easy to reproduce for the article. Three more runs, no luck, and I can't tell you what triggered it that one time. That's the honest answer: when it happens on your service, gc* plus gc+ergo gives you the lead-up; the one-line gc output doesn't.
Parallel and Serial say "Allocation Failure" and mean "Eden filled up". Pause Young (Allocation Failure) 24M->3M(90M) isn't an error. It's the routine trigger.
ZGC's gc line is a cycle, not a pause. On 21 with default settings:
[0.928s][info][gc] GC(0) Garbage Collection (Warmup) 32M(12%)->20M(8%)
[1.207s][info][gc] Allocation Stall (main) 15.329ms
[1.209s][info][gc] GC(2) Garbage Collection (Allocation Stall) 256M(100%)->56M(22%)
The pause times are on gc,phases lines (Pause Mark Start 0.006ms, Pause Mark End 0.009ms, Pause Relocate Start 0.005ms) and you only see them at gc*. And Allocation Stall (main) 15.329ms is the line that matters: a thread wanted memory, ZGC had none free, and the thread waited. That's the ZGC symptom of an undersized heap, and it's invisible if you only watch for "Pause". I got it here because I gave it 256 MB for a program that allocates faster than that. With the generational mode switched on, the same lab says Major Collection (Warmup) and Minor Collection (Allocation Rate) instead. Same collector, different vocabulary, so a dashboard regex written for one breaks on the other.
User=0.00s Sys=0.00s Real=0.00s on the gc,cpu line is CPU time across GC worker threads, versus wall-clock Real. If User is much bigger than Real, the collection ran in parallel and cost more CPU than its pause suggests. If Real is bigger than User+Sys, the process was waiting on something outside the collector (swap or a throttled CPU quota; once, on a laptop, a slow disk the log was written to). That second shape is the one worth learning to spot, and it's the start of the next article in the series: long GC pauses.
Rotated files aren't in age order. I set filecount=3,filesize=50k and looked at the first timestamp in each file:
rot-...log.1 starts 4.067s
rot-...log.2 starts 4.868s
rot-...log.0 starts 5.671s
rot-...log starts 6.460s (active)
Suffix .0 isn't oldest, and it isn't newest. The numbers cycle. If your shipping agent assumes .1 is newer than .2, it'll send logs out of order. Sort by mtime, or better, put %t in the name and let each JVM start get its own set.
Java GC logs in production: what to set and what it costs
My production line looks like this:
-Xlog:gc*,gc+age=trace,safepoint:file=/var/log/app/gc-%t.log:utctime,uptime,level,tags:filecount=10,filesize=20M
I ran it on the lab program and it parses and writes. The reason for each piece: gc* gives phases, heap regions and Metaspace on every collection. gc+age=trace adds the survivor age table, the evidence you need for premature promotion, covered in the aging and promotion article. safepoint adds a line per safepoint with the time to reach it, which is how you tell "the collector was slow" from "the JVM took 800 ms to stop". utctime,uptime as decorators, and rotation set explicitly so you decide how much disk this takes, not the default.
What it costs, in lab numbers (G1, 128 MB heap, about 280 collections per second, which no real service does):
-Xlog:gc 2,246 lines 192 KB
-Xlog:gc* 26,203 lines 2,013 KB
-Xlog:gc*=debug 35,411 lines 4,285 KB
Per collection, gc* costs about 12 times the lines and about ten times the bytes. On a service doing one GC every few seconds it's nothing. On one doing hundreds a second it's measurable. The -Xlog:async option, which showed up in JDK 17, buffers messages and writes them from a separate thread so the logging statement never blocks the thread that's logging. It's off by default. I haven't measured it here, so I'm not going to tell you it's free.
gc+age=trace is one of the few trace selections I'll run constantly. gc*=trace I use for ten minutes on one canary, then switch off with jcmd <pid> VM.log disable.
For quick triage without any tool, this is the one-liner I run most. It pulls pause durations from a gc-level log and gives percentiles:
grep -aE "\] GC\([0-9]+\) Pause .* [0-9.]+ms$" gc.log \
| sed -E 's/.* ([0-9.]+)ms$/\1/' | sort -n \
| awk '{a[NR]=$1; s+=$1} END {printf "n=%d avg=%.2f p50=%.2f p99=%.2f max=%.2f ms\n", NR, s/NR, a[int(NR*0.5)], a[int(NR*0.99)], a[NR]}'
On my concurrent-cycle log: n=2616 avg=1.77 p50=1.04 p99=19.29 max=25.46 ms. Notice the average is under 2 ms and the p99 is 19. The average is the number that makes everything look fine. (This works on G1, Parallel and Serial lines. On ZGC the cycle line doesn't end in ms, so it silently matches nothing.)
As for analysers. GCeasy is a hosted web tool: fast, good graphs, but you're uploading production logs to someone else's service, so check your policy first. GCViewer is open source and desktop, but it started life on the legacy format, and the Atlassian bug tracker has a ticket about Java 11 logs not parsing in it, so check which version you have before trusting its output. JDK Mission Control reads JFR recordings, not text GC logs. They answer different questions: the log tells you what the collector did, JFR tells you which allocation sites caused it. I use an analyser to find the interesting five minutes, then read the raw lines.
Staying safe across upgrades
Moving from 8 to 17 or 21, the failure is loud: unrecognised flags kill the JVM at startup. That's actually the good case. Move your GC flags to -Xlog before the JDK bump, in a separate change. Moving between 17, 21 and 25 the failure is quiet: your parser, regex or dashboard stops matching because the line vocabulary shifted (ZGC being the example I saw directly). Keep a sample log from each JDK version in your repo and run the parser against it in CI.
Things I'd alert on from these logs, with the caveat that the thresholds are mine, not a standard: any Pause Full on G1 that isn't System.gc() or a planned one; any ZGC Allocation Stall at all; p99 pause over your latency budget; and Concurrent Mark Abort, which on my box meant a Full GC arrived mid-cycle.
Before an LTS-to-LTS move, run your startup flags on the new JDK with -version and read the warnings. The Using G1 or Using Serial line tells you which collector you actually got, and ergonomics on a small container can hand you Serial when you thought you had G1. I only ran 21 this time, so treat 17 and 25 as "check it", not "confirmed".
Screenshot this bit
-Xlog:gcis one line per collection.-Xlog:gc*is everything. Without the star you match only that exact tag set.- A G1
Pause Youngline's numbers are whole-heapused before->after(committed), not young-gen sizes. - On ZGC the
gcline is a cycle. The pauses aregc,phaseslines, andAllocation Stallis the one to alert on. - Default decorators are
uptime,level,tagsand default file rotation is 5 × 20 MB. Set both on purpose. Rotated suffixes cycle, so they're not in age order. jcmd <pid> VM.log what=... output=...changes logging on a running JVM. Use it before you restart anything.
Questions people ask about GC logging
How do I enable GC logging in Java 17 or 21? Add -Xlog:gc*:file=gc-%t.log:utctime,uptime,level,tags:filecount=10,filesize=20M to the JVM flags. -Xlog:gc alone prints one line per collection to stdout. Tested on 21.0.12.1; the syntax is the same since JDK 9.
What replaced -XX:+PrintGCDetails? -Xlog:gc*. On JDK 21 the old flag still works as a deprecated alias and the JVM prints the translation, but PrintGCDateStamps, PrintGCTimeStamps and UseGCLogFileRotation are rejected outright, so a Java 8 flag set won't start.
Where is the GC log file by default? There isn't one. With no -Xlog option the JVM only prints warnings and errors; with file=gc.log and a relative path, the file lands in the process's working directory. In a container that's usually not on a volume, so write to an explicit path.
How do I read "Pause Young (Normal) (G1 Evacuation Pause) 7M->4M(96M)"? It's a young collection with the normal trigger; heap in use went from 7 MB to 4 MB, with 96 MB committed. See the line-by-line breakdown above. For what makes G1 pick that trigger, see G1 explained.
