Java garbage collection in its own log: eight checks you can run

This post is the short version of my video. Watch it here: Java Garbage Collection, Drawn

The video draws the heap on a board and moves objects through it. This page is the worksheet for it: the full program, the flag for each view of the collector, and the arithmetic that ties the log back to the drawing. Several of the sums below are not in the video.

Everything here ran on Oracle JDK 25.0.1 on an M4 Max laptop. It is one run on one machine, so expect other numbers on yours.

The flags, in one table

The program

import java.lang.management.ManagementFactory;
import java.util.HashMap;
import java.util.Map;

public class MapDemo {
    static byte[] last;   // keeps the JIT from removing the allocation

    public static void main(String[] args) {
        Map<Integer, byte[]> cache = new HashMap<>();
        Map<Integer, byte[]> longLived = new HashMap<>();
        for (int k = 0; args.length > 0 && k < Integer.parseInt(args[0]); k++)
            longLived.put(k, new byte[1024]);
        long allocated = 0, start = System.nanoTime();
        for (int i = 0; i < 40_000_000; i++) {
            last = new byte[1024];            // garbage on the next turn
            allocated += 1024;
            if (i % 100 == 0) {               // every 100th goes into the map
                cache.put((i / 100) % 5_000, new byte[1024]);
                allocated += 1024;
            }
        }
        double seconds = (System.nanoTime() - start) / 1e9;
        System.out.printf("allocated %.1f GB in a %d MB heap in %.1f s, the map holds %,d entries%n",
                allocated / 1e9, Runtime.getRuntime().maxMemory() >> 20, seconds,
                cache.size() + longLived.size());
        for (var gc : ManagementFactory.getGarbageCollectorMXBeans())
            System.out.printf("  %-26s %,6d collections  %,6d ms%n",
                    gc.getName(), gc.getCollectionCount(), gc.getCollectionTime());
    }
}MapDemo.java

Two kinds of object come out of that loop. Forty million arrays are dead one iteration later. Four hundred thousand go into a map with 5,000 keys, so each of those stays reachable until 5,000 newer entries have been written. The optional argument fills a second map that is never emptied; it is used further down to give the collectors real work.

1. Count the collections

javac MapDemo.java && java -Xmx64m -XX:+UseSerialGC MapDemo

allocated 41.4 GB in a 61 MB heap in 2.2 s, the map holds 5,000 entries
  Copy                        2,349 collections     146 ms
  MarkSweepCompact               10 collections      18 msoutput

41.4 GB went through a heap that cannot hold more than 64 MB, and the program paused for 164 ms in total out of 2.2 seconds. Copy is the young collection and MarkSweepCompact is the full one.

Those two names belong to Serial. Other collectors report under other names, which matters if you read these counters from a dashboard:

For ZGC, “Cycles” is work done while the program runs and “Pauses” is the time it was actually stopped. A monitoring rule that adds up every row will overstate ZGC’s pauses by a wide margin.

2. Why 64 MB shows up as 61

The program asked for 64 MB and maxMemory() answers 61. Print the layout to see where the rest is:

java -Xmx64m -XX:+UseSerialGC -Xlog:gc+heap MapDemo | grep "GC(40)"

GC(40) DefNew: 18677K(19648K)->1206K(19648K) Eden: 17472K(17472K)->0K(17472K) From: 1205K(2176K)->1206K(2176K)
GC(40) Tenured: 7188K(43712K)->7360K(43712K)output

DefNew is listed as 19,648 K, which is Eden plus one survivor space. The second survivor space is always empty between collections, so the JVM leaves it out of the usable total: 65,536 − 2,176 = 63,360 K, or 61.9 MB, and the program’s integer shift cuts that down to 61.

The proportions come from two defaults you can print:

java -XX:+PrintFlagsFinal -version | grep -E " (NewRatio|SurvivorRatio|MaxTenuringThreshold|TargetSurvivorRatio) "

uintx NewRatio                 = 2
uintx SurvivorRatio            = 8
 uint MaxTenuringThreshold     = 15
 uint TargetSurvivorRatio      = 50output

NewRatio=2 makes tenured twice the size of the young generation (43,712 against 21,824). SurvivorRatio=8 makes Eden eight times one survivor space (17,472 against 2,176).

3. How to read one pause line

java -Xmx64m -XX:+UseSerialGC -Xlog:gc MapDemo | sed -n 1,3p

[0.004s][info][gc] Using Serial
[0.014s][info][gc] GC(0) Pause Young (Allocation Failure) 18M->1M(61M) 0.191ms
[0.015s][info][gc] GC(1) Pause Young (Allocation Failure) 18M->1M(61M) 0.107msoutput

Seventeen megabytes of garbage disappear in a tenth of a millisecond because a young collection copies the survivors and never touches the rest.

4. Watch objects get older

java -Xmx64m -XX:+UseSerialGC -Xlog:gc+age=trace MapDemo | grep "GC(40)"

GC(40) Desired survivor size 1114112 bytes, new threshold 7 (max threshold 15)
GC(40) Age table:
GC(40) - age   1:     177840 bytes,     177840 total
GC(40) - age   2:     175760 bytes,     353600 total
GC(40) - age   3:     176800 bytes,     530400 total
GC(40) - age   4:     175760 bytes,     706160 total
GC(40) - age   5:     176800 bytes,     882960 total
GC(40) - age   6:     175760 bytes,    1058720 total
GC(40) - age   7:     176800 bytes,    1235520 totaloutput

Each row is the set of map entries that entered during one Eden fill and are still referenced. You can count them:

• A byte[1024] occupies 1,040 bytes: 1,024 of data and a 16-byte header.
• Eden holds 17,472 K, which is about 17,200 such arrays.
• One in every 101 allocations is a map entry, so about 170 per fill.
• 170 × 1,040 = 176,800 bytes, which is the figure in rows 3, 5 and 7. The other rows are 169 and 171 entries.

The first line explains why the limit is seven and not the maximum of fifteen. “Desired survivor size” is half of one survivor space (TargetSurvivorRatio=50): 2,176 K ÷ 2 = 1,114,112 bytes. The running total crosses that between age 6 (1,058,720) and age 7 (1,235,520), so the JVM lowers the threshold to 7 and promotes everything that reaches it. The threshold is recalculated at every collection; it is a result of how full the survivor space is, not a fixed setting.

5. Predict the full collection

Section 2 showed tenured growing from 7,188 K to 7,360 K in one collection: 172 K, one promoted group. With that rate you can estimate when tenured fills up, before looking:

• Tenured is 43,712 K and about 8 MB of it is live (the 5,000 map entries and the map itself).
• That leaves roughly 36 MB to fill, at about 172 K per young collection.
• 36,000 ÷ 172 ≈ 210 young collections between full ones.

java -Xmx64m -XX:+UseSerialGC -Xlog:gc MapDemo | grep "Pause Full" | head -2

[0.270s][info][gc] GC(252) Pause Full (Allocation Failure) 60M->8M(61M) 2.477ms
[0.482s][info][gc] GC(462) Pause Full (Allocation Failure) 60M->8M(61M) 2.686msoutput

Collections 252 and 462 are 210 apart. The first one arrives a little later because tenured starts empty. What a full collection frees here is entries that were promoted and then overwritten in the map: garbage that young collections cannot reach.

6. Give the collectors something to carry

A 2.5 ms full pause says little, because only 8 MB was alive. The argument below keeps two million extra arrays alive for the whole run, about 2 GB, in a 4 GB heap:

for gc in Serial Parallel G1 Z; do
  java -Xmx4g -XX:+Use${gc}GC -Xlog:gc,gc+phases:file=$gc.log MapDemo 2000000 | head -1
done

The pauses are summarised with a few lines of Python that read every Pause line of a log:

import re, sys
print(f"{'collector':<12}{'pauses':>8}{'longest':>11}{'total paused':>15}")
for path in sys.argv[1:]:
    ms = [float(m.group(1)) for line in open(path)
          if 'Pause' in line and (m := re.search(r'([\d.]+)ms\s*$', line))]
    if ms:
        name = path.split('/')[-1].split('.')[0]
        print(f"{name:<12}{len(ms):>8,}{max(ms):>9.2f} ms{sum(ms):>12.0f} ms")pauses.py

Three things in that table are easy to miss:

• ZGC had the most pauses and the least pause time. Its 109 stops add up to less than a millisecond. Counting pauses tells you nothing; add up their length.
• Parallel was the slowest in this run, in both total time and longest pause. I did not investigate why, so treat it as an observation about this program on this machine and not as a ranking.
• Run time barely moved between Serial, G1 and ZGC. The difference between them is in the longest single stop, which is the number a user of a web service feels.

7. Take the collector away

time java -Xmx64m -XX:+UnlockExperimentalVMOptions -XX:+UseEpsilonGC MapDemo

Terminating due to java.lang.OutOfMemoryError: Java heap space

real	0m0.026soutput

Epsilon allocates and never frees. Sixty-four megabytes last 26 milliseconds. It is meant for performance tests where you want to measure code with no collector in the picture.

8. Find out what your own Java uses

java -Xlog:gc -version 2>&1 | grep Using

On JDK 21, 23, 25 and 27 this printed Using G1 on my machine. Two things change that answer without any flag from you:

java -XX:ActiveProcessorCount=1 -Xlog:gc -version 2>&1 | grep Using

[0.003s][info][gc] Using Serialoutput

With one CPU visible, the JVM chooses Serial. A container limited to one core can be in that situation, so run the command inside the container, not on the host.

The second thing is the build. -XX:+UseShenandoahGC fails on Oracle’s JDK 25 with “Option not supported” and works on the OpenJDK 23 build I have installed.

Options also come and go between versions. The same command on four JDKs:

java -XX:+UseZGC -XX:-ZGenerational -version

A start script copied from an old project can therefore stop a new JVM from booting. -XX:+UseConcMarkSweepGC fails the same way on JDK 25; CMS itself was removed in JDK 14.

Collectors by Java version

What this page does not cover

• How G1, ZGC and Shenandoah work inside. The video draws regions and concurrent moving; here they only appear as rows in a table.
• Tuning. Nothing above changes a default except the heap size and the collector. The point was to read what the JVM already does.
• Real workloads. This program allocates one object size at a fixed rate. Your service does neither, so measure it with the same flags before choosing anything.

Sources

• JEP 248: Make G1 the default garbage collector
• JEP 291 and JEP 363: CMS deprecated, then removed
• JEP 318: Epsilon
• JEP 377, JEP 439, JEP 474, JEP 490: ZGC
• JEP 379, JEP 404, JEP 521: Shenandoah
• Unified JVM logging (-Xlog), JEP 158