Java GC Logs, in depth: the -Xlog grammar, a production setup, reading G1 pauses line by line, other collectors, safepoints, parsing and alerting

The -Xlog grammar

Unified logging is not GC-specific. Every message the JVM logs carries a set of tags (such as gc, heap, phases or safepoint) and a level. An -Xlog option chooses which messages to keep, where to write them, and what to prefix each line with. Its general shape is -Xlog:<selectors>:<output>:<decorators>:<output-options>, and each part after the first can be left empty.

Several -Xlog options can appear on one command line, each with its own output, and -Xlog:disable turns off everything, including the default configuration that sends warnings and errors to stdout.

A production configuration

A production configuration should keep every info-level GC message, the per-phase timings, and safepoint records; write them to a file that survives a restart; rotate so the disk cannot fill; and stamp each line with wall-clock time so it can be lined up with application logs.

java -Xlog:async \
     -Xlog:gc*=info,gc+phases=debug,safepoint=info:file=/var/log/app/gc-%p-%t.log:time,uptime,level,tags:filecount=10,filesize=50m \
     -jar app.jar

Each choice has a reason. gc* at info is a few lines per collection, which is cheap. gc+phases=debug adds the breakdown that tells you which part of a slow pause was slow. safepoint records every stop, including the ones that are not GC. The %p and %t in the file name mean a restarted process writes a new set of files instead of mixing runs together.

-Xlog:async, added in JDK 17, moves the writing off the logging thread: log sites put messages in a bounded buffer (2 MB by default, set with -XX:AsyncLogBufferSize) and a separate thread flushes it. If the buffer fills, messages are dropped rather than blocking. That trade is right for GC logs, because the alternative is a GC thread blocked on a slow disk while every application thread waits at a safepoint.

Reading one G1 young pause, line by line

Below is an illustrative G1 young pause as -Xlog:gc* prints it on a recent JDK with the default decorators. Wording varies between releases, so treat it as a shape, not a format to hard-code.

[41.207s][info][gc,start    ] GC(57) Pause Young (Normal) (G1 Evacuation Pause)
[41.207s][info][gc,task     ] GC(57) Using 8 workers of 8 for evacuation
[41.219s][info][gc,phases   ] GC(57)   Pre Evacuate Collection Set: 0.2ms
[41.219s][info][gc,phases   ] GC(57)   Merge Heap Roots: 0.4ms
[41.219s][info][gc,phases   ] GC(57)   Evacuate Collection Set: 10.1ms
[41.219s][info][gc,phases   ] GC(57)   Post Evacuate Collection Set: 1.0ms
[41.219s][info][gc,phases   ] GC(57)   Other: 0.3ms
[41.219s][info][gc,heap     ] GC(57) Eden regions: 180->0(178)
[41.219s][info][gc,heap     ] GC(57) Survivor regions: 12->14(23)
[41.219s][info][gc,heap     ] GC(57) Old regions: 310->312
[41.219s][info][gc,heap     ] GC(57) Humongous regions: 6->4
[41.219s][info][gc          ] GC(57) Pause Young (Normal) (G1 Evacuation Pause) 1013M->663M(2048M) 12.034ms
[41.219s][info][gc,cpu      ] GC(57) User=0.09s Sys=0.00s Real=0.01s

Read it from the outside in. GC(57) is the collection id; every line with the same id belongs to the same event, even when other events interleave. The start line gives the kind of pause (Young (Normal)) and its cause (G1 Evacuation Pause: eden filled up). The summary line, tagged plain gc, is the one most tools parse: heap used before and after, committed heap in parentheses, and the pause duration.

The region lines explain the summary. Eden went from 180 regions to 0, as it always does after a young pause, and the number in parentheses is the eden target G1 chose for the next cycle. Survivors grew slightly and two regions were promoted to old. The phase lines show that evacuation, copying live objects, took 10.1 of the 12 ms. That is normal: G1 pause time tracks live data copied, not garbage.

The gc,cpu line is the quickest health check in the file. User is CPU time summed over GC threads, Real is wall time. With 8 workers, 0.09 s of user time in 0.01 s of real time is about what you expect. If Real is close to or larger than User plus Sys, the GC threads were not running in parallel: the host was CPU-starved, the container was throttled, or the process was swapping. High Sys usually points at page faults.

Following a whole G1 cycle by GC id

Young pauses are only part of G1's work. When old-generation occupancy crosses the initiating threshold, a young pause also starts concurrent marking, and the next few ids tell a story you can follow by kind:

What the other collectors log

Every collector logs the same summary-plus-detail pattern under gc*, but the lines that mean trouble differ:

• Parallel reports Pause Young and Pause Full lines. Full pauses are part of its normal design, so watch their duration and frequency rather than alerting on their presence.
• ZGC pauses are tiny and most work is concurrent, so pause lines are rarely the problem. Look for lines containing Allocation Stall: an application thread wanted memory, the concurrent cycle had not freed enough, and the thread waited. It is invisible in pause statistics. Generational ZGC (JDK 21 and later) also distinguishes minor and major collections in its lines. See ZGC architecture.
• Shenandoah reports degenerated and full cycles when the concurrent cycle loses the race with allocation. Treat both like G1's evacuation failure.

Safepoints: the stops that are not GC

A GC pause is one kind of safepoint, not the only one. Biased-lock revocation (in older JDKs), deoptimisation, thread dumps, class redefinition by agents, and some jcmd operations all stop the world too, and none of them appear in gc*. -Xlog:safepoint records each one with its operation name and timings, including the time it took for all threads to reach the safepoint. That time-to-safepoint is the hidden part of a pause: one thread running a long counted loop without a safepoint poll can hold everyone else waiting even though the GC itself was quick. When stalls exceed the GC pause lines, check the safepoint lines first. JVM safepoints explains the mechanism.

Worked example: a parser that groups by GC id

The parser below reads unified GC logs with any decorator choice, groups lines by GC id, and emits one record per event with its kind, cause, pause time, heap before and after, and CPU times. It then applies four alert rules. It reads rotated files in order and is meant to run on a sidecar or in your log pipeline, not inside the JVM.

import re
import sys
from dataclasses import dataclass, field

PREFIX = re.compile(r"^((?:\[[^\]]*\])+)\s?(.*)$")
GCID = re.compile(r"^GC\((\d+)\)\s*(.*)$")
PAUSE = re.compile(r"Pause (?P<kind>[A-Za-z]+(?: \((?:Normal|Concurrent Start|Prepare Mixed|Mixed)\))?)"
                   r"(?: \((?P<cause>[^)]*)\))?"
                   r".*?(?P<before>\d+)M->(?P<after>\d+)M\((?P<cap>\d+)M\) (?P<ms>[\d.]+)ms")
CPU = re.compile(r"User=([\d.]+)s Sys=([\d.]+)s Real=([\d.]+)s")
TROUBLE = ("To-space exhausted", "Evacuation Failure", "Allocation Stall", "Pause Full")


@dataclass
class Event:
    gc_id: int
    uptime: float = 0.0
    kind: str = ""
    cause: str = ""
    pause_ms: float = 0.0
    before: int = 0
    after: int = 0
    cpu: tuple = ()
    flags: set = field(default_factory=set)


def parse(lines):
    events = {}
    for raw in lines:
        m = PREFIX.match(raw.rstrip("\n"))
        if not m:
            continue
        decorations = re.findall(r"\[([^\]]*)\]", m.group(1))
        uptime = next((float(d[:-1]) for d in decorations
                       if d.endswith("s") and d[:-1].replace(".", "", 1).isdigit()), 0.0)
        g = GCID.match(m.group(2))
        if not g:
            continue
        ev = events.setdefault(int(g.group(1)), Event(int(g.group(1)), uptime))
        msg = g.group(2)
        if (pm := PAUSE.search(msg)):
            ev.kind, ev.cause = pm["kind"], pm["cause"] or ""
            ev.pause_ms, ev.before, ev.after = float(pm["ms"]), int(pm["before"]), int(pm["after"])
        if (cm := CPU.search(msg)):
            ev.cpu = tuple(float(x) for x in cm.groups())
        ev.flags.update(t for t in TROUBLE if t in msg)
    return sorted(events.values(), key=lambda e: e.gc_id)


def alerts(events, pause_budget_ms=200.0):
    for e in events:
        if e.flags:
            yield f"GC({e.gc_id}) at {e.uptime:.0f}s: {', '.join(sorted(e.flags))}"
        if e.pause_ms > pause_budget_ms:
            yield f"GC({e.gc_id}) {e.kind} paused {e.pause_ms:.0f} ms"
        if e.cpu and e.cpu[2] > 0.05 and e.cpu[2] >= e.cpu[0] + e.cpu[1]:
            yield f"GC({e.gc_id}) Real >= User+Sys: GC threads starved of CPU"


def read_lines(paths):
    for path in paths:                       # pass rotated files oldest first
        with open(path, encoding="utf-8", errors="replace") as fh:
            yield from fh


if __name__ == "__main__":
    for message in alerts(parse(read_lines(sys.argv[1:]))):
        print(message)

The important parts are the grouping by id and the decorator-agnostic prefix match, which keep the parser working when someone adds a decorator. Add a fifth rule from the heap-after values of mixed or full pauses: if the post-collection floor keeps rising across a day, you have a leak or a growing cache, and the log showed it before the OutOfMemoryError did. GC overhead, pause time over wall time in a window, is the metric to graph.

Changing logging on a running JVM

You do not need a restart to get more detail during an incident. jcmd can list, change, rotate and disable logging on a running JVM:

jcmd <pid> VM.log list                       # current outputs and selectors
jcmd <pid> VM.log output=/tmp/gc-debug.log what=gc*=debug decorators=time,uptime,level,tags
jcmd <pid> VM.log rotate                     # start new files, e.g. before collecting them
jcmd <pid> VM.log disable                    # turn everything off, including the default output

Add a temporary debug output, capture the episode, then remove it; permanent debug or trace output buries the lines you need.

Migrating JDK 8 logging flags

JDK 8 flags are still pasted into start scripts. Some are translated to -Xlog with a deprecation warning; others were removed, and the JVM refuses to start with an unrecognised option. The mapping from the java manual:

Note that -Xloggc:file maps to plain gc, not gc*, so a migrated script loses the detail lines. Expect parsers written for JDK 8 output to break.

Failure modes

The ways GC logging fails in practice:

• Writing to a slow or network disk without async logging. The write happens inside the pause. Symptoms: pauses whose Real time far exceeds the phase totals. Fix: -Xlog:async and local disk.
• Logs on an ephemeral container filesystem. The pod that crashed takes its log with it. Write to a mounted volume or ship continuously.
• Parsers tied to one decorator set or JDK release. Pin the decorators in the start script, test the parser against logs from every JDK you run, and treat a parse rate of zero as an alert, not as a quiet day.
• Reading young-pause heap-after as the live set. It still includes dead old objects. Use mixed and full pauses.
• Dropped async messages. A buffer too small for a burst loses lines. If you see gaps in GC ids, raise AsyncLogBufferSize.

GC logs, JFR and metrics

GC logs are not the only source of GC data, and each source answers a different question.

What to do next

1. Replace any legacy PrintGC flags with one -Xlog line: gc*, gc+phases=debug, safepoint, decorators time,uptime,level,tags.
2. Add -Xlog:async on JDK 17 or later and write to local, persistent disk with %p in the file name.
3. Size rotation so the files cover at least three days at peak volume.
4. Ship the files and run a parser that groups by GC id; alert on full pauses, evacuation failures, allocation stalls and pauses over budget.
5. Graph GC overhead and the post-mixed-collection heap floor per instance.
6. Practise jcmd <pid> VM.log on a staging JVM so you can raise detail during an incident without a restart.
7. When a stall appears, compare GC lines with safepoint lines before tuning the collector, then follow G1 GC architecture and the heap tuning guide.