Skip to content
JavaAgentic

Type at least two characters. Try “RAG”, “pgvector” or “tool calling”.

Reading GC Logs and Tuning Without Guessing

Enabling unified GC logging, reading a G1 log line by line, calculating allocation and promotion rates, identifying every Full GC cause, and the tuning changes that are usually wrong.

Advanced6 min readUpdated
On this page

GC tuning done by copying flags from a blog post is how most applications end up slower. Tuning done from a log is a short, mechanical process. This page is about reading the log.

Key Takeaways

  • Turn logging on in production permanently. It costs well under 1% and cannot be reconstructed afterwards.
  • Three numbers matter: allocation rate, promotion rate, and throughput (time not spent in GC).
  • Frequent young GCs are usually fine. Frequent Full GCs are not.
  • Pause Full (Allocation Failure) means the old generation could not be freed — a leak, or a heap genuinely too small.
  • Fix allocation before you touch flags. Most GC problems are application problems.

Turning it on

Java 9 and later — unified logging
-Xlog:gc*:file=/var/log/app/gc.log:time,uptime,level,tags:filecount=5,filesize=20M
 
# Add safepoint detail when investigating long pauses with short GC times
-Xlog:gc*,safepoint:file=gc.log:time,uptime,level,tags
 
# Heap dump on OOM — do this at the same time, it costs nothing until it fires
-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/var/log/app/

The pre-Java-9 flags (-XX:+PrintGCDetails, -XX:+PrintGCDateStamps, -XX:+UseGCLogFileRotation) were removed and now prevent the JVM from starting. Knowing the unified -Xlog syntax is itself a useful signal that you have worked on a modern runtime.

Reading a G1 log

a young collection
[2026-08-08T09:14:22.481+0000][12.418s][info][gc,start] GC(47) Pause Young (Normal) (G1 Evacuation Pause)
[2026-08-08T09:14:22.512+0000][12.449s][info][gc,phases] GC(47)   Pre Evacuate Collection Set: 0.1ms
[2026-08-08T09:14:22.512+0000][12.449s][info][gc,phases] GC(47)   Evacuate Collection Set: 27.4ms
[2026-08-08T09:14:22.512+0000][12.449s][info][gc,heap] GC(47) Eden regions: 148->0(140)
[2026-08-08T09:14:22.512+0000][12.449s][info][gc,heap] GC(47) Survivor regions: 6->14(20)
[2026-08-08T09:14:22.512+0000][12.449s][info][gc,heap] GC(47) Old regions: 210->218
[2026-08-08T09:14:22.512+0000][12.449s][info][gc] GC(47) Pause Young (Normal) 1472M->940M(4096M) 31.2ms

Everything you need is in the last line plus the region counts:

  • 1472M->940M(4096M) — heap before, after, and total. 532MB reclaimed.
  • 31.2ms — the stop-the-world pause.
  • Eden 148->0(140) — eden emptied, and G1 shrank the target from 148 to 140 regions to keep inside the pause goal.
  • Old regions: 210->218 — eight regions were promoted. This is the number to watch.

A young collection that empties eden, moves a little into survivors and promotes almost nothing is healthy. Promotion on every collection means objects are outliving the young generation, which eventually forces old-generation work.

what a problem looks like
[45.2s] GC(210) Pause Young (Concurrent Start) (G1 Humongous Allocation) 3800M->3720M(4096M) 89ms
[45.9s] GC(211) Pause Young (Normal) (G1 Evacuation Pause)                3900M->3850M(4096M) 102ms
[46.4s] GC(212) Pause Full (G1 Compaction Pause) (Allocation Failure)     3990M->3910M(4096M) 4210ms
[47.1s] GC(213) Pause Full (G1 Compaction Pause) (Allocation Failure)     3995M->3950M(4096M) 4480ms

Three tells, all pointing the same way: collections reclaim almost nothing (3990→3910 is 2%), Full GCs are back-to-back, and occupancy after each one keeps climbing. This is a memory leak, not a tuning problem — see The seven classic memory leaks.

The three numbers

Allocation rate — how fast the application produces garbage.

computing it
Eden emptied at GC(47) at 12.418s: 148 regions × 4MB = 592MB
Eden emptied at GC(48) at 13.104s: 145 regions × 4MB = 580MB
Interval: 0.686s
Allocation rate ≈ 580MB / 0.686s ≈ 845 MB/s

Under about 1GB/s per core is comfortable. Above that, young collections become frequent enough that GC threads compete with application threads for CPU. Reducing allocation is almost always a bigger win than any flag: fewer intermediate collections in a hot path, primitive arrays instead of boxed lists, reused buffers, and streams that do not materialise a list at every stage.

Promotion rate — how fast data moves into the old generation. From the log, the change in old regions per unit time. High promotion means either a genuinely large working set, or a young generation too small for objects to die before being tenured. This is the number that predicts Full GCs.

Throughput — the fraction of wall-clock time not spent paused. Sum the pause times over a window and divide. Above 95% is healthy; below 90% means GC is a first-order cost.

Full GC causes

Cause in the logMeaning
Allocation Failure after concurrent markingOld generation full — leak or undersized heap
Metadata GC ThresholdMetaspace pressure — classloader leak or too many generated classes
System.gc()Someone called it. Add -XX:+DisableExplicitGC
G1 Humongous AllocationLarge objects cannot find contiguous regions
ErgonomicsThe collector decided a full compaction was needed
Heap Dump Initiated GCA tool triggered it — not an application problem

System.gc() is worth checking for explicitly. It is called by some libraries (older versions of RMI do it on a timer, and some direct-buffer cleanup paths request it), and each call is a full stop-the-world compaction.

What to tune, in order

1. Reduce allocation. Profile with JFR's allocation events or async-profiler's alloc mode, find the top allocating call sites, and fix them. This is the highest-leverage change available and it requires no flags.

2. Size the heap correctly. Aim for the old generation to sit at roughly 30% occupancy after a full collection. Too small and you get constant Full GCs; too large and each collection takes longer and the machine wastes memory. Setting -Xms equal to -Xmx avoids repeated heap resizing and the full collections that sometimes accompany it.

3. Adjust the pause target — carefully. -XX:MaxGCPauseMillis between 100 and 200 is a sensible range for G1. Lower values shrink the young generation, increase collection frequency, raise promotion and usually make p99 latency worse.

4. Change collector only with a measurement. Moving to ZGC because pauses matter is legitimate. Moving because a blog post said it is faster is not.

Tooling

beyond reading the raw log
# GCEasy or GCViewer — upload the log for graphs of pause distribution and heap after GC
# JFR — GC events correlated with allocation, locks and I/O in one recording
jcmd <pid> JFR.start duration=120s filename=rec.jfr settings=profile
 
# Live view
jstat -gcutil <pid> 1000        # S0 S1 E O M CCS YGC YGCT FGC FGCT GCT

jstat -gcutil is the fastest way to check a running process during an incident: the O column (old-generation percentage) rising monotonically across full collections is a leak, and FGC climbing is the count of full collections.

Correlating with application latency

The last and most important skill is deciding whether GC actually caused the latency you are chasing. Take the timestamps of your p99 outliers from application metrics and line them up against pause timestamps in the log. If they do not coincide, GC is not the cause, and the usual real answers are a slow dependency, a lock, or the container being CPU-throttled.

That method is worked through end to end in Latency spikes: proving it was or was not GC.

What gets asked

"How would you diagnose a GC problem?" — the answer is a process, not a flag: enable unified logging, compute allocation and promotion rates, look at whether Full GCs are reclaiming anything, and only then consider changing the configuration. Being able to say "the first thing I check is whether occupancy after each Full GC is rising, because that distinguishes a leak from an undersized heap" is the answer that lands.

Frequently Asked Questions

How do I enable GC logging in modern Java?
Use unified logging: -Xlog:gc*:file=gc.log:time,uptime,level,tags:filecount=5,filesize=20M. The old flags — PrintGCDetails, PrintGCDateStamps, UseGCLogFileRotation — were removed in Java 9. Logging is cheap enough, well under one percent overhead, that it should be on permanently in production. A GC log you do not have when the incident happens cannot be recreated.
What is a healthy allocation rate?
Below roughly 1GB per second per core is comfortable for most applications; above that, GC starts to dominate. Compute it from the log by taking the eden occupancy dropped at each young collection and dividing by the interval between collections. A high allocation rate is almost always more worth fixing than the collector configuration, because it is a property of your code rather than of the JVM.
My application pauses for two seconds occasionally. Is it GC?
Check the log before assuming. Correlate the pause timestamps with GC events; if there is no GC at that moment, look at safepoint pauses with -Xlog:safepoint, at the OS for swapping and CPU throttling, and at your own locks. A very common false positive is a container being CPU-throttled by its cgroup quota, which stalls every thread including the GC ones and looks exactly like a long pause.

Related tutorials