zgc-jdk25-benchmarks/docs/05-logging-and-jfr.md

5. Reading the logs and the flight recording

Runnable companion: analysis/.../GcLogParser.java

5.1 The unified log lines you need

-Xlog:gc*,gc+alloc=debug:file=gc.log:time,uptime,level,tags:filecount=5,filesize=50m

Selector	Gives you
gc	one line per collection
gc+phases	every sub-phase, including the three ZGC pauses
gc+heap	before/after occupancy
gc+alloc=debug	Allocation Stall lines — off by default, and the reason most people never see stalls
gc+start, gc+task, gc+ref	cycle triggers, worker counts, reference processing

5.2 The category error that makes ZGC look terrible

A ZGC cycle produces lines like this:

GC(41) Minor Collection (Allocation Rate) 1180M(58%)->402M(20%) 0.051s
GC(41) y: Pause Mark Start 0.014ms
GC(41) y: Concurrent Mark 32.109ms
GC(41) y: Pause Mark End 0.011ms
GC(41) y: Concurrent Relocate 14.802ms
GC(41) y: Pause Relocate Start 0.009ms

A naive script that sums every duration on every line reports "51 ms of GC" for this cycle. The real stop-the-world time is 0.034 ms — the three Pause lines. The Concurrent phases ran alongside the application.

G1's log has no such trap: its lines are pauses.

GC(12) Pause Young (Normal) (G1 Evacuation Pause) 1180M->402M(2048M) 16.784ms

GcLogParser in this repository keeps the two categories in separate buckets and prints them separately, precisely so the comparison cannot be made accidentally. It also prints the sentence that should accompany every such table:

  Adding the block above to the pause block would be a category error:
  concurrent time overlaps application execution by design.

5.3 The same trap exists in JMX

GarbageCollectorMXBean.getCollectionTime() means different things per collector:

Bean	Reports
ZGC Minor Cycles / ZGC Major Cycles	concurrent cycle duration — not freeze time
ZGC Minor Pauses / ZGC Major Pauses	real stop-the-world time
G1 Young Generation / G1 Old Generation	real stop-the-world time
G1 Concurrent GC	concurrent cycle — despite sitting in the same bean list

A dashboard that sums getCollectionTime() over all beans will report ZGC as spending ~1.6 seconds "in GC" during a 60-second run where its actual freeze time rounded to 0 ms. That is how ZGC acquires a reputation for being slow on teams that never changed their dashboard query.

GcObserver in this repository classifies each bean and labels it in the output:

GC activity during the measured window
  ZGC Minor Cycles       collections=18     time=    919 ms   [cycle (mostly concurrent)]
  ZGC Minor Pauses       collections=54     time=      0 ms   [stop-the-world]
  ZGC Major Cycles       collections=3      time=    667 ms   [cycle (mostly concurrent)]
  ZGC Major Pauses       collections=15     time=      0 ms   [stop-the-world]

Note also the 3 pauses per cycle arithmetic: 18 minor cycles → 54 minor pauses.

5.4 JFR events worth enabling

Event	Default threshold	Why
jdk.ZAllocationStall	10 ms	The real ZGC latency source. Set to 0 ms and enable stack traces.
jdk.ZPageAllocation	—	Shows the Small / Medium / Large split; diagnoses which kind of pressure.
jdk.ZYoungGarbageCollection / jdk.ZOldGarbageCollection	—	Cycle counts with cause.
jdk.ZRelocationSet, jdk.ZRelocationSetGroup	—	What is being compacted each cycle.
jdk.ZUncommit, jdk.ZUnmap	—	Heap being handed back to the OS.
jdk.GCPhasePause	—	Works for both collectors; the honest cross-collector pause metric.

Starting a recording programmatically, which is what both demos in this repository do:

try (Recording recording = new Recording()) {
    recording.enable("jdk.ZAllocationStall").withoutThreshold().withStackTrace();
    recording.setToDisk(true);
    recording.setDestination(Path.of("stalls.jfr"));
    recording.start();
    // ... workload ...
    recording.stop();
}

Reading it back without any external tool:

try (RecordingFile file = new RecordingFile(Path.of("stalls.jfr"))) {
    while (file.hasMoreEvents()) {
        RecordedEvent e = file.readEvent();
        if (e.getEventType().getName().equals("jdk.ZAllocationStall")) { ... }
    }
}

A RecordedEvent gotcha that costs an hour. getValue is declared <T> T getValue(String). Writing String.valueOf(e.getValue("type")) lets javac infer T = char[], because String.valueOf(char[]) is an applicable overload — and you get ClassCastException: class java.lang.String cannot be cast to class [C at runtime. Bind to an Object local first. Similarly RecordedEvent::getDuration is overloaded, so a method reference to it will not compile inside a Comparator.comparing(...); use an explicit lambda.

And from the command line, with the stack that was stalled:

$ jfr summary stalls.jfr
$ jfr print --events ZAllocationStall --stack-depth 10 stalls.jfr
jdk.ZAllocationStall {
  startTime = 22:44:24.809 (2026-07-30)
  duration = 2.20 ms
  type = "Small"
  size = 2.0 MB
  eventThread = "allocator-3" (javaThreadId = 43)
  stackTrace = [ ... ]
}

---

Next: 06-g1-in-jdk25.md.