← Articles · Memory and garbage collector · Ghassane LATFI · July 23, 2026

Reading GC logs without external tools

When the GC is acting up, the reflex is to send the gc.log to GCeasy or open it in JDK Mission Control. That’s fine, those tools produce clean charts in a few seconds.

But the log itself can be read. It isn’t binary, it’s lines of text, and each one tells you what happened during a collection. Once you can decode them, you understand the GC’s rhythm, you spot a leak or one Full GC too many, and you can tell whether the problem really comes from the GC or from somewhere else. All of that without installing anything, often before you even open a profiler.

We’ll read a G1 log from JDK 25, line by line. G1 is the default collector, so it’s the one you’re most likely to meet. If you don’t yet know which collector to pick or how to size the heap, start with Tuning the JVM garbage collector.

Turning on the logs

GC logging goes through the JVM’s unified logging. The useful form:

-Xlog:gc:file=gc.log:time,uptime,level,tags

One nuance that changes everything: the gc tag on its own gives one summary line per collection, which is enough in most cases. The gc* tag (with the star) additionally turns on every sub-tag, and prints the region-by-region breakdown, the internal phases and the CPU time. It’s verbose, but that’s where you go looking when the summary line no longer tells you enough:

-Xlog:gc*:file=gc.log:time,uptime,level,tags

The decorators at the end (time,uptime,level,tags) prefix every line: the timestamp, the number of seconds since the JVM started, the level and the tags. The uptime one is precious, it’s what you use to measure the intervals between collections.

The one line that sums it up

Here’s the line produced by the gc tag, one per collection. It’s the starting point for any reading:

[2026-07-20T10:15:32.412+0200][634.129s][info][gc] GC(148) Pause Young (Normal) (G1 Evacuation Pause) 1804M->216M(4096M) 8.735ms

Read it left to right:

• GC(148): the collection number. It increments every time, which lets you stitch lines back together when you’re in gc* mode.
• Pause Young (Normal): the type of collection.
• (G1 Evacuation Pause): the cause that triggered it.
• 1804M->216M(4096M): the heap used before the collection, then after, and in parentheses the total size of the heap. Here it went from 1804 MB to 216 MB on a 4 GB heap.
• 8.735ms: how long the pause lasted.

Two numbers read straight away. First, how much the collection freed: 1804 down to 216, nearly 1.6 GB reclaimed. A collection that empties well is a sign that the objects were mostly temporary, which is healthy. Then the pause duration, compared to your latency budget. 8 ms on a web service, nobody notices. 8 ms on a trading system, that’s an eternity. It all depends on the context.

The G1 pause types

The field after GC(n) says what kind of collection just happened. On G1, the main ones:

• Pause Young (Normal): a collection of the young generation. The most frequent and the shortest. G1 collects eden and the survivors, nothing else.
• Pause Young (Concurrent Start): a young collection that, on top, kicks off a concurrent marking cycle in the background. It shows up when the old generation’s occupancy crosses a threshold (the IHOP, around 45%, adjusted dynamically by default). This is G1 starting to look at the old generation to prepare its cleanup.
• Pause Young (Prepare Mixed) then a series of Pause Young (Mixed): collections that reclaim the young generation and part of the old regions flagged by the marking. That’s how G1 cleans the old generation, bit by bit, without ever stopping everything.
• Pause Remark and Pause Cleanup: two short pauses that are part of the concurrent marking cycle.
• Pause Full (G1 Compaction Pause): the Full GC. It stops the whole application and sweeps the entire heap in one go. It’s the event to avoid.

A healthy rhythm looks like this: lots of Pause Young (Normal), now and then a Concurrent Start followed by a few Mixed, and no Full GC. If a Pause Full shows up in normal operation, that’s already a signal.

The region-by-region breakdown

When the summary line isn’t enough, you switch to gc* and look at the split. G1 doesn’t manage the heap as two big blocks, but as fixed-size regions. Here’s what it prints for the collection above:

[634.129s][info][gc,heap] GC(148) Eden regions: 800->0(800)
[634.129s][info][gc,heap] GC(148) Survivor regions: 20->24(114)
[634.129s][info][gc,heap] GC(148) Old regions: 80->82
[634.129s][info][gc,heap] GC(148) Humongous regions: 2->2

Line by line:

• Eden 800->0(800): 800 eden regions were full, they’re emptied to 0, and the target for the next round is 800. After a young collection, eden always drops back to zero.
• Survivor 20->24(114): the objects that survived this collection were copied into 24 survivor regions.
• Old 80->82: two more regions in old. Those two regions are promoted objects, old enough to leave the young generation. A promotion that climbs slowly is normal. A promotion that jumps from one collection to the next is a sign of objects surviving too long, and it ends up feeding the old generation faster than G1 cleans it.
• Humongous 2->2: the huge objects. In G1, any object larger than half a region is stored separately, in dedicated regions. Here two of them weren’t collected.

A word on region size. G1 works it out at startup from the heap size, between 1 and 32 MB, aiming for about 2048 regions. On a 4 GB heap that gives 2 MB regions. Hence the arithmetic: 800 eden regions × 2 MB = 1600 MB, which matches the 1.6 GB reclaimed we read on the summary line. Everything lines up, and that’s what lets you check a hunch with a simple multiplication.

Working out the allocation rate by hand

This is the most useful number, and a tool like GCeasy computes it for you. But it’s just two subtractions.

Between two young collections, eden fills up completely. So you just take the eden size that was collected and the time elapsed between the two collections. Take GC(148) again at 634.129s, with its 1.6 GB of eden. Say the next collection, GC(149), arrives at 635.512s:

Eden collected : 1600 MB
Interval       : 635.512 - 634.129 = 1.383 s
Rate           : 1600 / 1.383 ≈ 1157 MB/s, about 1.1 GB/s

There’s your allocation rate. It’s the speed at which the code produces objects. A high, steady rate means lots of temporary objects being created, so lots of young collections, so time nibbled away by the GC. And there, no flag will save you: the real lever is in the code. To see where the allocations come from, async-profiler’s alloc mode points straight at the responsible paths, which is the subject of Profiling the JVM with async-profiler.

Spotting a problem without a profiler

Here’s what you’re looking for as you skim a gc.log, from the most serious to the most subtle.

A Full GC shows up. The line Pause Full (G1 Compaction Pause) shouldn’t exist in healthy operation:

[812.400s][info][gc] GC(201) Pause Full (G1 Compaction Pause) 3980M->3120M(4096M) 412.006ms

412 ms of pause, and above all the heap staying at 3120 MB out of 4096 afterwards. G1 failed to keep up with its Mixed collections, often because allocation is going faster than the concurrent marking, or because the heap is too small.

The heap stays full after the collection. When “after” is nearly equal to “before” on the summary line, for example 3900M->3850M(4096M), the collection freed almost nothing. Repeated over several collections, that’s either an undersized heap or a memory leak. The logical next step is an OutOfMemoryError, and there you move on to a heap dump: Diagnosing a memory leak with a heap dump.

An Evacuation Failure. It gets appended in parentheses at the end of the collection’s cause:

[788.220s][info][gc] GC(178) Pause Young (Normal) (G1 Evacuation Pause) (Evacuation Failure: Allocation) 3900M->3600M(4096M) 95.204ms

G1 ran out of free regions to copy the survivors into during the pause. It’s slow and expensive, often the last warning before a Full GC. It means the heap is too full or promotion is running away.

Humongous regions climbing. A lot of humongous regions gives away big arrays or big buffers. They fragment the heap and can trigger cycles on their own. Often it’s better to revisit the code that allocates them than the region size.

Pauses getting longer. The duration at the end of the summary line creeping past your latency budget, repeatedly and not just on one isolated spike.

The pause isn’t only GC

One trap to finish on. The duration shown on the gc line is the GC’s work. But the application is stopped from the moment all threads have reached a safepoint. And reaching that safepoint takes time too.

If one thread is stuck in a long loop with no poll point, it makes all the others wait. The GC shows 8 ms, but the application may have been frozen for much longer. To see that hidden time:

-Xlog:safepoint:file=safepoint.log:time,uptime

The output gives one line per safepoint, with durations in nanoseconds:

[635.512s] Safepoint "G1CollectForAllocation", Time since last: 219964917 ns, Reaching safepoint: 2208 ns, At safepoint: 8735000 ns, Leaving safepoint: 1625 ns, Total: 8738833 ns, Threads: 0 runnable, 10 total

At safepoint is the GC’s work, here the 8.7 ms you find again on the gc line. Reaching safepoint is the time it took to stop all the threads before starting. When that last one swells while the GC stays short, the problem isn’t the GC: it’s a thread slow to stop. You never see it if you only look at the gc line.

In short

Turn the logs on with -Xlog:gc for the essentials, -Xlog:gc* for the detail. Read the summary line first: how much the collection freed, and how long it took. Use the pause type to follow the rhythm, and be wary of the first Full GC. Drop down into the region-by-region breakdown to watch promotion and humongous objects. Work out the allocation rate by hand, it’s two subtractions. And don’t forget that the real pause includes the time to reach the safepoint. A gc.log read properly tells you where the problem is before you’ve opened a single tool.