Garbage collection

Reading GC logs with -Xlog:gc: unified logging from setup to diagnosis

Garbage collection · Published 2026-10-23

The GC log is the cheapest and most informative diagnostic a JVM produces. Since JDK 9 it is part of the unified logging framework, configured with -Xlog. If you enable only one diagnostic option in production, make it this one.

One line to enable it

-Xlog:gc*:file=/var/log/app/gc.log:time,uptime,level,tags:filecount=5,filesize=20m

Reading the parts from left to right, following the syntax in the java reference, -Xlog[:[what][:[output][:[decorators][:output-options]]]]:

• gc*: every tag set that starts with gc, at info level. Plain gc gives one line per collection; gc* adds phases, heap details and more.
• file=…: write to a file instead of standard output. You can include %p (process ID) or %t (start time) in the name to avoid overwriting the previous run's log.
• time,uptime,level,tags: the decorators prefixed to each line. The default is uptime,level,tags; adding time gives wall-clock timestamps that you can correlate with application logs and incidents.
• filecount=5,filesize=20m: rotation. The reference notes that files are rotated by default with up to 5 files of a target size of 20 MB, and that filecount=0 disables rotation.

The same framework covers other subsystems: -Xlog:help lists tags and options, and -Xlog:safepoint logs safepoint operations. Unified logging was introduced by JEP 158, and GC logging was moved onto it by JEP 271.

Changing logging at runtime

The VM.log diagnostic command reconfigures logging on a running JVM, without a restart. The jcmd reference lists options to list the current configuration, add outputs and rotate files:

$ jcmd <pid> VM.log list
$ jcmd <pid> VM.log output=/var/tmp/gc-debug.log what=gc*=debug decorators=time,uptime,tags
$ jcmd <pid> VM.log rotate

From the old flags to -Xlog

JDK 8 configurations used a set of -XX:+Print… flags that no longer exist in that form. The java reference contains a conversion table; the most common entries:

The reference also notes that the GC cause and GC ID, which needed separate flags before, are now always logged.

Reading G1 lines

With -Xlog:gc, each G1 pause produces one summary line. The shape is as follows (values are illustrative):

[2026-10-23T09:14:02.381+0000][512.884s][info][gc] GC(841) Pause Young (Normal) (G1 Evacuation Pause) 3021M->1188M(6144M) 18.402ms
[2026-10-23T09:14:40.007+0000][550.510s][info][gc] GC(852) Pause Young (Concurrent Start) (G1 Humongous Allocation) 3310M->1420M(6144M) 22.117ms
[2026-10-23T09:14:40.010+0000][550.513s][info][gc] GC(853) Concurrent Mark Cycle
[2026-10-23T09:14:41.200+0000][551.703s][info][gc] GC(853) Pause Remark 1602M->1580M(6144M) 6.950ms
[2026-10-23T09:14:41.912+0000][552.415s][info][gc] GC(853) Pause Cleanup 1640M->1640M(6144M) 0.611ms
[2026-10-23T09:14:42.100+0000][552.603s][info][gc] GC(853) Concurrent Mark Cycle 2090.112ms
[2026-10-23T09:14:47.330+0000][557.833s][info][gc] GC(860) Pause Young (Mixed) (G1 Evacuation Pause) 2410M->1015M(6144M) 31.240ms

• GC(841): the collection's ID. With gc*, every detail line of the same collection carries the same ID, so you can grep 'GC(841)' to see one collection in full.
• Pause type: Young (Normal), Young (Concurrent Start) (a young pause that also starts marking), Remark and Cleanup (short pauses within the concurrent cycle), Young (Mixed) (reclaims old regions too), and Full, the one you do not want to see.
• Cause in parentheses: G1 Evacuation Pause (normal), G1 Humongous Allocation, System.gc(), Metadata GC Threshold (Metaspace) and others.
• before->after(committed) heap occupancy, then the pause duration.

With gc* you also get, per pause, the phase breakdown, the region counts per type (Eden regions, Survivor regions, Old regions, Humongous regions), Metaspace usage, and user/sys/real CPU times. A pause where real is much larger than user divided by the GC thread count suggests the GC threads were waiting, for example for CPU or I/O on an overloaded host.

Patterns and what they mean

A rising floor: probably a leak

Extract the "after" value of each young or mixed pause and plot it. If the floor rises steadily under constant traffic, something accumulates. Confirm with class histograms and a heap dump (GC roots and memory leaks).

A high stable floor: an undersized heap

If the post-collection occupancy is stable but close to the committed size, collections become frequent and recover little. The heap is too small for the live data set plus allocation headroom.

Pause Full

On G1, a full collection indicates that the normal mechanisms could not keep up: marking started too late, or no space was left to evacuate into. The G1 tuning chapter says such collections are typically preceded by pauses tagged (Evacuation Failure). See tuning G1. A full GC whose cause is System.gc() comes from code or a tool, not from heap pressure.

Long pauses that the log does not explain

The GC log measures the collection itself. Time spent bringing threads to a safepoint before the pause is logged under the safepoint tag. If application latency spikes are longer than the GC pauses, add -Xlog:gc,safepoint and compare.

Other collectors

The framework and decorators are the same for every collector; the messages differ. Parallel and Serial log Pause Young and Pause Full lines with the same before->after(committed) pattern. ZGC logs its cycles and phases differently, and its logs report allocation stalls when the application has to wait for the collector to free memory, which is the ZGC symptom to watch for. When you switch collectors, read the first few hundred lines of the new log before writing any parsing script.

Whatever the collector, keep the startup lines: they record the collector, the heap sizes ergonomics chose, the region or page size and the number of GC threads. They answer the question "what configuration was this JVM actually running?" long after the deployment details are forgotten.

Quick command-line analysis

# the ten longest pauses
$ grep -E 'Pause (Young|Full|Remark|Cleanup)' gc.log | awk '{print $NF, $0}' | sort -rn | head -10

# any full collection at all?
$ grep -c 'Pause Full' gc.log

For longer periods, graphical analysers that read unified logs are more comfortable. Whatever the tool, compare like with like: the same workload, duration and heap size.

Sources

• The java command, section "Enable Logging with the JVM Unified Logging Framework" and the legacy flag conversion table
• The jcmd command (VM.log)
• JEP 158: Unified JVM Logging and JEP 271: Unified GC Logging
• G1 tuning, HotSpot GC Tuning Guide

Read next

More in Garbage collection

Garbage collection

Tuning G1

Heap size first, a realistic pause target, then IHOP and region size, and why -Xmn works against G1.

Garbage collection

Choosing a garbage collector

Latency, throughput or footprint: what each collector trades, and why your container may be running Serial.

Memory

GC roots and memory leaks

What counts as a GC root, the usual accidental references, and how to walk from a suspect object back to its root.