Reading a GC Log Line by Line

One twenty-second run, one quantity, three answers: 7616 MB/s, 8504 MB/s, 8485 MB/s.

The third is ground truth — the workload counted its own bytes, 177,944,603,200 of them. The second came from the GC log. The first also came from the GC log, from the same run, by applying the standard allocation-rate formula to the only occupancy figure the default log publishes, and it is 10.2 per cent low. The difference is not measurement noise; it is a mechanism, and the log records it plainly under a tag most people never select.

The run: JDK 26.0.2.1 (Homebrew build), macOS 26.6.2, Apple M4 Pro, G1 with -Xms512m -Xmx512m, region size 1M, a steady allocation of 1 KB blocks with one in eight retained.

One event is seven lines

-Xlog:gc prints one line per collection. That line is a summary, not the event. Under gc*, a single young collection looks like this — one collection under seven tag sets, verbatim apart from the ISO timestamps and four gc,phases lines removed for width:

[0.512s][info][gc,start    ] GC(21) Pause Young (Mixed) (G1 Evacuation Pause)
[0.512s][info][gc,task     ] GC(21) Using 10 workers of 10 for evacuation
[0.518s][info][gc,phases   ] GC(21)   Evacuate Collection Set: 5.88ms
[0.518s][info][gc,heap     ] GC(21) Eden regions: 264->0(243)
[0.518s][info][gc,heap     ] GC(21) Survivor regions: 23->35(36)
[0.518s][info][gc,heap     ] GC(21) Old regions: 148->164
[0.518s][info][gc          ] GC(21) Pause Young (Mixed) (G1 Evacuation Pause) 433M->197M(512M) 6.359ms
[0.518s][info][gc,cpu      ] GC(21) User=0.06s Sys=0.00s Real=0.01s

The last-but-one line is the whole of -Xlog:gc. 433M->197M(512M) is occupancy before, occupancy after, capacity; 6.359ms is the pause. (Mixed) says this collection took old regions as well as young ones, and (G1 Evacuation Pause) is the cause.

The line above it is the one that matters for arithmetic. Eden regions: 264->0(243) says 264 regions of eden were consumed and emptied, and the target for the next cycle is 243. At a 1M region size that is 264 MB, stated exactly rather than rounded — which the summary line’s whole-megabyte occupancy figures are not.

And as with every pause figure, 6.359ms begins after every thread has stopped. What it took to stop them is a separate cost with a separate log.

The selector is a query

-Xlog is not a verbosity dial with levels of loudness. -Xlog:help on this build gives the shape as -Xlog[:[selections][:[output][:[decorators][:output-options]]]], where the selection is a tag expression — and it is explicit about the trap:

Unless wildcard (*) is specified, only log messages tagged with exactly the tags specified will be matched.

So gc+heap matches messages tagged gc and heap and nothing else — narrower than most readers intend. gc* matches every tag set beginning with gc, which is why the same twenty seconds wrote 1,607 lines under gc and 14,704 under gc*. Six levels exist (off, trace, debug, info, warning, error) and twelve decorators, of which uptime, time, level and tags are the four worth having by default.

A selector that answers a question is therefore narrow and deliberate: -Xlog:gc,gc+heap=info:file=gc.log:uptime,level,tags produces the summary line and the region counts, and nothing else.

The arithmetic, and where it loses ten per cent

The canonical method is precise about its input: allocation rate is the difference between the young generation’s size after one collection completed and before the next one started, divided by the interval. Eden is where allocation lands, so eden occupancy is the figure the formula asks for.

-Xlog:gc does not carry it. 433M->197M(512M) is the whole heap — eden, survivors, old and humongous together — and substituting it for the young-generation number is the step almost everyone takes, because it is the only occupancy the default log offers. Summed across the 697 young collections and one full collection in this run, it gives 152,319 MB over the twenty seconds: 7616 MB/s.

The gc,heap lines carry what the formula actually wants. Summing the Eden deltas gives 170,082 MB — 8504 MB/s, against an instrumented 8485 MB/s. Accurate to 0.22 per cent.

The whole-heap substitution is 10.2 per cent low, and the missing 17,763 MB has a specific home. Subtracting occupancy assumes nothing frees memory between two young-collection lines. Something does:

Remark reclaimed 20,772 MB — 117 per cent of the shortfall, the excess being two intervals where occupancy fell rather than rose. Every megabyte the concurrent cycle frees between two young collections is a megabyte the next subtraction never sees, so a workload with more concurrent activity loses more. That is not a rounding error to shrug at; it is a systematic bias in the direction of under-reporting, which is the direction that makes a service look healthier than it is.

The same log answers a blunter question without arithmetic. 1,152 pause events totalling 6,963.6 ms over 20 s is 34.8 per cent of wall clock spent stopped — a number that needs no method at all, and one that a comparison of collector-reported pause figures would not have surfaced.

What the log does not carry

It carries the heap. Thread stacks, code cache, metaspace beyond the one-line summary, direct buffers and the rest of the resident set are outside it, which is why a process can be comfortable in every line above and still be killed for memory. The pause figures exclude the time to reach the safepoint. And the allocation rate, computed correctly, describes the past twenty seconds rather than the headroom of the next twenty.

Each of those is a different instrument. The GC log’s job is the heap, and it does that job exactly — down to the region — as long as the selector asks it the question rather than merely turning it on.