> ## Content Index > Fetch the complete content index at: https://www.ggorantala.dev/llms.txt > Use this file to discover other available public pages before exploring further. # Java GC Logs: Turn on -Xlog and Read Every Line of Output - URL: https://www.ggorantala.dev/java-gc-logs-xlog/ - Published: 2026-11-05T03:55:26.000Z - Updated: 2026-11-05T03:55:26.000Z - Description: Set up java GC logs with -Xlog the right way, then read every line it prints: G1 and ZGC pause lines, phases, heap before and after, rotation, and analysers. - Author: Gopi Gorantala - Tags: jvm, gc-tuning, garbage-collection ## 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: ```bash java -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:gc.log -Xmx64m -version ``` On OpenJDK 21.0.12.1 it prints this and exits: ```log 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`: ```java import java.util.*; public class Churn { static final Deque 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.** ```bash 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.** ```bash 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: ```bash 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.** ```bash 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: ```log -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=`. 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 ```log [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: ```log [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: ```log -XX:+PrintGC → -Xlog:gc -XX:+PrintGCDetails → -Xlog:gc* -Xloggc: → -Xlog:gc: ``` 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). ```log 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: ```log [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: ```log [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: ```log [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](https://ggorantala.dev/long-gc-pauses-java/?ref=ggorantala.dev). **Rotated files aren't in age order.** I set `filecount=3,filesize=50k` and looked at the first timestamp in each file: ```log 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: ```bash -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](https://ggorantala.dev/object-aging-promotion-java/?ref=ggorantala.dev) 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): ```log -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 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: ```bash 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:gc` is one line per collection. `-Xlog:gc*` is everything. Without the star you match only that exact tag set. - A G1 `Pause Young` line's numbers are whole-heap `used before->after(committed)`, not young-gen sizes. - On ZGC the `gc` line is a cycle. The pauses are `gc,phases` lines, and `Allocation Stall` is the one to alert on. - Default decorators are `uptime,level,tags` and default file rotation is 5 × 20 MB. Set both on purpose. Rotated suffixes cycle, so they're not in age order. - `jcmd 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](https://ggorantala.dev/g1-gc-explained/?ref=ggorantala.dev).