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

# 5. Reading the logs and the flight recording

> Runnable companion: [`analysis/.../GcLogParser.java`](../analysis/src/com/ankurm/zgc/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:

```java
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:

```java
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:

```console
$ 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](06-g1-in-jdk25.md).