Beyond Pause Times: Deep Dive into G1 GC Log Analysis for Java Performance Tuning

Many engineers only look at the final pause time in G1 GC logs — e.g., Pause Young (G1 Evacuation Pause) 38.742ms — and judge performance based on that single number. This is like diagnosing a fever by only reading a thermometer: it tells you something is wrong, but not why. The real value in G1 logs lies in the cause, heap delta, phase breakdown, and danger signals.

Enable Sufficient Logging Without Overhead

JDK 8 and JDK 9+ use different logging flags. For JDK 8, a common combination is:

-XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps -Xloggc:/path/to/gc.log -XX:+PrintTLAB

For JDK 9+, use the unified logging system:

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

Add specific tags only when needed (e.g., gc+tlab=trace, gc+remset=debug, gc+humongous=debug, gc+ergo=debug, stringdedup*=debug). Avoid enabling all trace levels in production — logging itself adds pressure.

38ms Is Just the Sum: Phase-by-Phase Breakdown

A Young GC pause comprises multiple phases. Example log snippet:

[GC pause (G1 Evacuation Pause) (young), 0.0387420 secs]
  [Parallel Time: 32.8 ms, GC Workers: 8]
    [GC Worker Start (ms): Min: 1234.5, Avg: 1234.6, Max: 1234.8, Diff: 0.3]
    [Ext Root Scanning (ms): Min: 2.1, Avg: 2.3, Max: 2.6, Diff: 0.5]
    [Update RS (ms): Min: 3.2, Avg: 4.1, Max: 5.8, Diff: 2.6]
    [Processed Buffers: Min: 12, Avg: 18.3, Max: 28, Diff: 16, Sum: 146]
    [Scan RS (ms): Min: 1.8, Avg: 2.2, Max: 2.9, Diff: 1.1]
    [Code Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2]
    [Object Copy (ms): Min: 18.2, Avg: 20.5, Max: 22.1, Diff: 3.9]
    [Termination (ms): Min: 0.1, Avg: 0.2, Max: 0.3, Diff: 0.2]
    [GC Worker Other (ms): Min: 0.1, Avg: 0.2, Max: 0.3, Diff: 0.2]
    [GC Worker Total (ms): Min: 32.5, Avg: 32.7, Max: 32.9, Diff: 0.4]
    [GC Worker End (ms): Min: 1267.2, Avg: 1267.3, Max: 1267.4, Diff: 0.2]
  [Code Root Fixup: 0.2 ms]
  [Code Root Purge: 0.1 ms]
  [Clear CT: 1.2 ms]
  [Other: 4.6 ms]
    [Choose CSet: 0.1 ms]
    [Ref Proc: 2.8 ms]
    [Ref Enq: 0.2 ms]
    [Redirty Cards: 0.8 ms]
    [Humongous Register: 0.1 ms]
    [Humongous Reclaim: 0.2 ms]
    [Free CSet: 0.4 ms]
  [Eden: 512.0M(512.0M)->0.0B(460.0M) Survivors: 52.0M->104.0M Heap: 1.2G(2.0G)->0.8G(2.0G)]
[Times: user=0.26 sys=0.01, real=0.04 secs]

1. Parallel Time — Where the Pause Time Goes

Ext Root Scanning: More Roots, Slower Scan

Scans external roots (thread stacks, JNI handles, global variables). High time (>10ms) suggests:

Too many threads (each stack must be scanned)

Deep stacks (recursion, deep call chains)

Many JNI references (native code holding Java objects)

Update RS: The Hidden Cost of Write Barriers

Updates Remembered Sets (RSet) by processing dirty cards. High Update RS (>10ms) indicates:

Write barrier overhead accumulation — application threads frequently modify references, generating many dirty cards

Cross-region references — Old→Young, Young→Young

Refinement threads falling behind — background refinement can't keep up, backlog processed during STW

Optimization: reduce unnecessary reference writes; check -XX:G1ConcRefinementThreads; monitor Processed Buffers count (large values = severe backlog).

Scan RS: Cross-Region Reference Density

Scans RSets to find cross-region references. Usually 1–3ms. High values mean too many cross-region entries, possibly from Old-region caches/pools referencing Young objects or deep reference chains.

Object Copy: Live Objects = Slow Evacuation

Copies surviving objects from the Collection Set (CSet) to new regions. Core work of Young GC. High Object Copy (>50% of pause) means:

Many live objects — too many objects survive Eden

Premature promotion — Survivor fills up, objects promoted to Old, increasing copy cost

Optimization: reduce object allocation; audit object lifecycles; tune Survivor size to avoid early promotion.

2. Don't Ignore 'Other' — Serial Phases Hide Time

Ref Proc: Weak References Slow GC

Processes Soft/Weak/Phantom references. High (>5ms) suggests:

Many weak/soft references — e.g., Guava Cache, Caffeine

Finalizer-heavy objects — overridden finalize() requires extra processing

Optimization: evaluate necessity of weak references; replace finalize() with Cleaner or try-with-resources.

Clear CT: Card Table Cleanup

Clears card table marks. Usually 1–2ms. Slow if card table is huge (large heap, many regions).

Heap Delta: Did the GC Actually Reclaim Memory?

[Eden: 512.0M(512.0M)->0.0B(460.0M) Survivors: 52.0M->104.0M Heap: 1.2G(2.0G)->0.8G(2.0G)]

Shows Eden cleared (normal), Survivor doubled (survivors promoted), heap dropped 400MB. Warning signs:

Eden not cleared → evacuation failure (to-space exhausted)

Survivor exploding → memory leak or long-lived request-scoped objects

Heap barely shrinks → low reclamation efficiency, most objects live

GC Cause: Why Did This Pause Happen?

Evacuation Pause — Normal Young GC, But Dig Deeper

Triggered by Eden full. Investigate: Eden size, allocation rate, survivor count.

Humongous Allocation — Large Objects Creating Pressure

Large object (>50% region size) allocation triggers GC. Investigate: source of large objects (big JSON, arrays, strings); consider splitting, streaming, reuse; check region size.

Metadata GC Threshold — Problem May Be Outside Java Heap

Metaspace threshold reached. Investigate: classloader leaks (dynamic proxies, hot reload, Groovy/JSP); -XX:MaxMetaspaceSize setting.

GCLocker — JNI Critical Sections Delay GC

GC triggered after JNI critical section exits. Investigate: JNI call frequency; heavy native I/O, crypto, file ops.

Allocation Failure — Memory Pressure Critical

Allocation cannot be satisfied. Investigate: heap too small; memory leak; humongous fragmentation.

Concurrent Marking Is Not Pause-Free

Concurrent marking runs in background but has two STW phases:

Initial Mark — Short But Mandatory Stop

Marks GC Roots directly. Usually 1–5ms; can reach 10ms+ with many roots (many threads, globals).

Remark — The Real STW Amplifier

Processes SATB buffers (reference changes during concurrent mark). Usually 5–20ms. If application mutates references heavily during concurrent mark, SATB buffers grow, Remark slows. Log pattern:

[GC concurrent-mark-start]
...
[GC concurrent-mark-end, 2.345 secs]
[GC remark, 0.0234 secs]

If remark >50ms: check if application creates/modifies objects heavily during concurrent mark; tune -XX:G1ConcMarkStepDurationMillis. Concurrent marking also consumes CPU — if CPU saturated, throughput drops without visible pause increase.

Case Study: 40ms Young GC Dragging P99 to 500ms

Order service: P99 ~200ms, spikes to 500ms. Young GC avg 40ms. Log showed:

[Update RS (ms): Min: 3.2, Avg: 12.8, Max: 28.3, Diff: 25.1]
[Processed Buffers: Min: 45, Avg: 123, Max: 287, Diff: 242]

High Update RS + high Processed Buffers = dirty card backlog. Code revealed:

Map<Long, Order> orderCache = new ConcurrentHashMap<>();
public void updateOrder(Order order) {
    orderCache.put(order.getId(), order);
    // every update modifies reference
}

Map in Old region; every put modifies cross-region reference → write barrier → dirty cards. Thousands of updates/sec at peak. Fixes:

Batch updates — reduce put frequency

Immutable objects — avoid mutating Order fields

Segmented cache — split large map into smaller maps, reduce per-region pressure

Result: Update RS <3ms, P99 stabilized at 150ms. Root cause only visible via phase breakdown.

Translate Log Signals to Code Problems

GC logs are for every Java developer, not just JVM engineers. Key mappings: Update RS high → check reference writes, refinement threads Object Copy high → check live objects, object lifecycles Ref Proc high → check weak references, finalizers Humongous Allocation → check large objects remark high → check mutation rate during concurrent mark

Logs don't tell you which line to change, but they narrow the search. GC tuning is engineering: logs show where it's slow, code shows why , parameters are final fine-tuning.

Mixed GC: Why It's Slower Than Young GC

Mixed GC collects Young + part of Old. Log example:

[GC pause (G1 Evacuation Pause) (mixed), 0.0856420 secs]
  [Parallel Time: 78.2 ms, GC Workers: 8]
    [Update RS (ms): Min: 8.3, Avg: 14.2, Max: 22.8, Diff: 14.5]
    [Scan RS (ms): Min: 4.2, Avg: 6.8, Max: 9.1, Diff: 4.9]
    [Object Copy (ms): Min: 52.1, Avg: 58.5, Max: 64.2, Diff: 12.1]
  [Eden: 512.0M(512.0M)->0.0B(512.0M) Survivors: 52.0M->52.0M Heap: 2.8G(4.0G)->1.9G(4.0G)]

Key differences:

Scan RS longer — must scan Old RSets for cross-region refs

Object Copy longer — copies Old live objects, not just Young

Heap drop larger — reclaims Old, so delta bigger

If Mixed GC >100ms, focus on: Scan RS (Old cross-region refs), Object Copy (Old live objects), CSet size (how many Old regions selected). Tuning params:

-XX:G1MixedGCCountTarget=8   # spread over 8 Mixed GCs
-XX:G1OldCSetRegionThresholdPercent=10  # max 10% Old per Mixed GC

But if Old is full of live objects, splitting doesn't help — root cause is why Old has so many live objects .

Five Danger Signals from GC Logs

Signal 1: Eden Fills Fast, Most Objects Die

Eden: 512.0M(512.0M)->0.0B(512.0M)
Heap: 1.2G(4.0G)->0.5G(4.0G)

Young GC frequent (e.g., every 2s) but heap drops 700MB. Inference: high allocation rate, short-lived objects. Healthy. If throughput hurt, increase Eden ( -XX:G1NewSizePercent).

Signal 2: Eden Not Cleared — to-space exhausted

Eden: 512.0M(512.0M)->128.0M(512.0M)  // Eden not cleared
to-space exhausted

Inference: evacuation failure — Survivor/Old lacks space for survivors. Causes: Survivor too small; Old fragmentation (humongous); survivors exceed prediction. Dangerous — often leads to Full GC.

Signal 3: Survivor Growing, Heap Not Shrinking

GC 1: Survivors: 32M->64M, Heap: 1.5G->1.2G
GC 2: Survivors: 64M->96M, Heap: 1.7G->1.5G
GC 3: Survivors: 96M->128M, Heap: 1.9G->1.8G

Inference: objects surviving multiple GCs, piling in Survivor. Either long-lived request objects or leak. Check: object age distribution (JFR/Allocation Profiler); ThreadLocal leaks; cache growth.

Signal 4: Update RS + Scan RS Both High

[Update RS (ms): Avg: 18.3]
[Scan RS (ms): Avg: 12.5]

Combined 30ms+ = half pause. Inference: many cross-region refs, RSet maintenance costly. Causes: Old large Map/List frequently referencing Young; deep reference graphs; refinement misconfigured. Check: heap dump for Old hotspots; mutation frequency; immutable redesign.

Signal 5: Frequent Humongous Allocation, Old Growing

GC pause (G1 Humongous Allocation)
Heap: 1.5G(4.0G)->2.1G(4.0G)  // Old grew 600MB

Inference: large objects directly allocated in Old, raising occupancy. Check: which endpoints create big JSON/arrays/strings; can they be split, streamed, reused?

Concurrent Mark → Mixed GC Cadence

Normal rhythm:

Old usage hits IHOP (default 45%) → concurrent mark starts

Concurrent mark ends → knows which Old regions are garbage-rich

Next Young GC becomes Mixed GC → collects Young + some Old

Log pattern:

[GC concurrent-mark-start]
...
[GC concurrent-mark-end]
[GC pause (G1 Evacuation Pause) (mixed)]
[GC pause (G1 Evacuation Pause) (mixed)]
[GC pause (G1 Evacuation Pause) (mixed)]

Abnormal pattern:

[GC concurrent-mark-start]
[GC pause (G1 Evacuation Pause) (young)]  // Young GC before mark ends
[GC concurrent-mark-end]
[GC pause (G1 Evacuation Pause) (mixed)]
[GC concurrent-mark-start]  // new mark starts immediately

Inference: Old pressure high, reclamation can't keep up with allocation. Causes: excessive promotion, frequent humongous allocation. Unfixed → Full GC.

user/sys/real: GC Efficiency Health Check

[Times: user=0.26 sys=0.01, real=0.04 secs]

user — GC threads' user-mode CPU time sum

sys — GC threads' kernel-mode CPU time sum

real — wall-clock pause time

With 8 GC threads, ideal: user ≈ real * 8. Example: real=0.04s → user≈0.32s.

If user low (e.g., 0.15s): parallelism insufficient — check -XX:ParallelGCThreads; CPU cores; serial bottlenecks.

If sys high (e.g., 0.08s): kernel overhead — frequent mmap/munmap; page faults (heap too large, physical memory low); I/O pressure (logging, heap dumps).

High real + low user → parallelism/blocking issue. High user + normal real → GC work itself heavy → optimize allocation.

Conclusion: From Log to Code, Not Parameter Tweaking

GC logs are the black box. Don't just read the final pause. Analyze:

Cause — why GC triggered

Phase breakdown — which phase is slowest

Heap delta — reclamation efficiency

Concurrent mark — frequency and duration

user/sys/real — GC efficiency

Reverse-engineer code issues:

Update RS high → excessive reference writes

Scan RS high → cross-region reference density

Object Copy high → too many live objects

Humongous Allocation → large object creation

to-space exhausted → space shortage

Logs narrow the scope; code understanding completes the fix. GC tuning isn't magic — it's engineering. Logs tell you where it's slow, code tells you why , parameters are the last touch. Never reverse that order.