reading GC logs

the picture

you know how "is the GC the problem?" usually gets answered with a guess? the JVM already wrote the answer down, you just have to switch it on and learn to read the receipts.

a GC log is a till receipt for every trip the cleaners make. each one says when they came (uptime), why they were called (the cause), how full the place was when they arrived and when they left (before → after), and how long the shop was closed while they worked (the pause). one receipt tells you almost nothing. a few hundred in a row tell you whether the shop is healthy, or slowly filling up with stuff nobody will ever buy.

turning it on

GC logging goes through the JVM's unified logging (-Xlog, java 9, JEPs 158 and 271). the shape is -Xlog:what:where:decorations:options, and every part after the first is optional:

# the summary lines only, to stdout
java -Xlog:gc -jar app.jar
 
# everything GC-related, to rotating files. a sane production setting.
java '-Xlog:gc*:file=gc-%p.log:time,uptime,level,tags:filecount=5,filesize=20m' -jar app.jar
 
# already running? switch it on without a restart
jcmd <pid> VM.log output=gc.log what='gc*' decorators=time,uptime,level,tags

quote the whole thing in a shell, because * is a glob. the old java 8 flags still work but print a warning: -XX:+PrintGCDetails becomes -Xlog:gc*, -Xloggc:x.log becomes -Xlog:gc:x.log, and -verbose:gc is just -Xlog:gc. the java 8 format is gone, though, so any old script that parses GC logs needs rewriting.

anatomy of one collection

here's the first GC of the toy service from serial and parallel (256 MB heap, G1, jdk 25), every line of it. the last line with no extra tag, [gc], is the summary. everything above it is detail.

on almost every line, four fields do most of the work:

the kind

Pause Young, Pause Young (Mixed), Pause Remark, Pause Full. young pauses are the normal heartbeat. a full GC on G1 means something went wrong.

the cause

in parentheses: (G1 Evacuation Pause), (Allocation Failure), (System.gc()), (G1 Humongous Allocation), (Metadata GC Threshold). it says why, which often says what to fix.

before → after (committed)

53M->40M(256M): heap in use when the GC started and when it finished, and how much heap the JVM has committed right now.

the time

5.102ms: on a line that starts with Pause, how long every app thread was stopped.

GC(3) Pause Full (Allocation Failure) 207M->50M(245M) 3.827ms

the whole run in one picture

one line is a data point. the shape only shows up when you plot hundreds of them. this chart is built straight from the five logs (one per collector, same program, same 256 MB heap), the same runs the viewer above quotes:

add up the pauses and divide by the run time and you get the fraction of time the app wasn't running at all. on this (very allocation-heavy) program, that's about 31% for G1 (359 ms of pauses in 1.16 s), 37% for Parallel, 69% for Serial, 2.4% for Shenandoah and 0.1% for ZGC. real services allocate far less per second, so expect single digits, but the comparison holds: "how much of my time is GC" is a number the log gives you for free.

what to look for

most of the time a healthy log is boring: young pauses at a steady rhythm, a marking cycle now and then, "after" values that wander but don't climb. these are the things that aren't boring, every one reproduced on jdk 25:

the allocation stall one deserves a second read. a dashboard that only plots GC pauses would have shown that ZGC run as perfect (nothing over 12 microseconds) while the main thread spent 4.5 seconds waiting for memory. concurrent collectors move the cost out of the pause, they don't make it disappear. if you run ZGC or Shenandoah, alert on Allocation Stall and Degenerated GC, not just pause times.