Reading GC Logs in Java

GC logs are the most useful tool for understanding how a Java program uses memory. With one flag, the JVM writes a line for every garbage collection: what kind it was, why it ran, how much heap was used before and after, and how long the application was paused. Since Java 9, all JVM logging uses the unified logging option -Xlog. In this lesson, you will turn on GC logging, read real log lines, and learn what patterns to look for.

Turning on GC Logging

The old options -XX:+PrintGCDetails and -Xloggc no longer work.

Example: A Real GC Log

This program creates 2,000 arrays of 100 KB and keeps every tenth one. It was run with a 64 MB heap and GC logging:

import java.util.ArrayList;
import java.util.List;
 
public class Garbage {
    public static void main(String[] args) {
        List<byte[]> keep = new ArrayList<>();
        for (int i = 0; i < 2_000; i++) {
            byte[] chunk = new byte[100_000];
            if (i % 10 == 0) {
                keep.add(chunk);
            }
        }
        System.out.println("Kept " + keep.size() + " chunks");
    }
}

java -Xlog:gc -Xmx64m Garbage.java

[0.003s][info][gc] Using G1
[0.012s][info][gc] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 35M->4M(64M) 0.401ms
[0.013s][info][gc] GC(1) Pause Young (Normal) (G1 Evacuation Pause) 30M->7M(64M) 0.327ms
[0.013s][info][gc] GC(2) Pause Young (Normal) (G1 Evacuation Pause) 37M->10M(64M) 0.227ms
[0.014s][info][gc] GC(3) Pause Young (Normal) (G1 Evacuation Pause) 43M->13M(64M) 0.481ms
[0.015s][info][gc] GC(4) Pause Young (Normal) (G1 Evacuation Pause) 46M->16M(64M) 0.355ms
[0.015s][info][gc] GC(5) Pause Young (Normal) (G1 Evacuation Pause) 50M->20M(64M) 0.301ms
Kept 200 chunks

How to Read a Line

Explanation: Each young collection reclaims most of the heap, but the "after" value climbs steadily (4M, 7M, 10M ... 20M) because every tenth array is kept. In a long-running program, an "after" value that keeps rising across many collections is a classic sign of a memory leak.

The Detailed Log

-Xlog:gc* adds much more detail. A real excerpt for the first collection above:

[0.016s][info][gc,start    ] GC(0) Pause Young (Normal) (G1 Evacuation Pause)
[0.017s][info][gc,task     ] GC(0) Using 2 workers of 9 for evacuation
[0.017s][info][gc,phases   ] GC(0)   Evacuate Collection Set: 0.35ms
[0.017s][info][gc,heap     ] GC(0) Eden regions: 34->0(26)
[0.017s][info][gc,heap     ] GC(0) Survivor regions: 0->4(5)
[0.017s][info][gc,heap     ] GC(0) Old regions: 2->2
[0.017s][info][gc          ] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 35M->4M(64M) 0.521ms

It shows that eden was emptied (34 regions to 0), live objects moved into 4 survivor regions, and the old generation didn't change.

Patterns to Look For

Common Mistakes

Using -XX:+PrintGCDetails. It was removed in Java 9; use -Xlog:gc*.

Judging from a single collection. Look at trends over many collections.

Ignoring the cause. "Allocation Failure", "Evacuation Pause" and "System.gc()" mean different things.

Practice

1. Easy: Run Garbage with -Xlog:gc -Xmx32m and note how the number of collections changes.
2. Harder: Change Garbage to keep every array, run it with -Xlog:gc -Xmx64m, and describe the log right before the OutOfMemoryError.

Key Takeaways