jvm-gc-tuning

Overview

JVM garbage collection is a common hidden cause of latency tail in load tests. An application that looks CPU-bound or I/O-bound in a flame graph may instead be stalling on stop-the-world (STW) pauses. This skill walks the full diagnostic workflow from log capture through collector selection to heap sizing and tool analysis.

Upstream: pair with flame-graph-analyzer when GC frames appear as wide leaves in the async-profiler output. Downstream: hand tuned JVM flags to the load runner (k6-load-testing, gatling-load-testing) to re-run the baseline after changes.

Step 1 - Enable unified GC logging

Java 9+ replaced the legacy -XX:+PrintGCDetails family with the unified logging framework. The canonical capture command, per the Java 21 java man page:

# Minimum useful capture (info level, timestamped, rotating files)
java -Xlog:gc*:file=gc.log:time,uptime,level,tags:filecount=5,filesize=20M \
     -Xms4g -Xmx4g \
     -jar app.jar

Recommended tag set for GC diagnostics:

For a single diagnostic capture that covers all these tags:

java -Xlog:gc*,gc+phases,gc+heap,gc+age,gc+alloc+profiling=debug:file=gc_full.log:time,uptime,pid,level \
     -jar app.jar

Legacy flags (-XX:+PrintGCDetails, -XX:+PrintGCTimeStamps) still compile in Java 21 but are deprecated. Migrate to -Xlog:gc* before Java 25.

Step 2 - Read the GC log: key signals

A G1 GC log line at info level looks like:

[2.415s][info][gc] GC(3) Pause Young (Normal) (G1 Evacuation Pause) 512M->320M(2048M) 12.453ms

Fields:

Red flags to scan for first:

• Pause Full - a full-heap STW collection; almost always a misconfiguration or heap exhaustion signal.
• Pause durations consistently above MaxGCPauseMillis target - G1 is missing its goal; see Step 4.
• Heap after GC is consistently above 70-80% of capacity - heap is undersized or there is a live-set growth (possible leak).
• (G1 Humongous Allocation) triggers - objects larger than half a heap region are being allocated in the old generation directly, bypassing the young gen.

Step 3 - Select the right collector

Per the HotSpot GC Tuning Guide, Available Collectors:

Oracle's guidance: "Allow the VM to select automatically unless you have strict pause-time requirements. Adjust heap size first before changing collectors." (Available Collectors)

Pause-time vs throughput tradeoff

Per the Ergonomics section: GC throughput overhead is calculated via GCTimeRatio:

max GC time fraction = 1 / (1 + GCTimeRatio)

-XX:GCTimeRatio=19 targets at most 5% of CPU in GC (default for Parallel collector). Setting -XX:MaxGCPauseMillis too aggressively on G1 reduces young-gen size and increases GC frequency: the core tradeoff is that shorter pauses require more frequent collections.

ZGC does nearly all work concurrently, trading slightly higher CPU and memory overhead for near-removal of that tradeoff (ZGC documentation).

Step 4 - Tune G1 for a pause-time target

From the G1 GC Tuning section:

Baseline low-latency profile (target < 50 ms pauses)

-XX:+UseG1GC
-Xms4g -Xmx4g                    # fixed heap avoids resize pauses
-XX:MaxGCPauseMillis=50           # pause-time target (statistical goal, not hard cap)
-XX:GCPauseIntervalMillis=200     # measure target over 200 ms window
-XX:G1NewSizePercent=10           # smaller young gen -> shorter pauses
-XX:G1MaxNewSizePercent=30
-XX:+G1UseAdaptiveIHOP            # let G1 learn IHOP from observed marking duration

See the key G1 flags table (defaults and effects for MaxGCPauseMillis, InitiatingHeapOccupancyPercent, G1HeapRegionSize, and more) in references/gc-reference.md.

Important: G1 is not a real-time collector. The pause target is a statistical goal. Setting it below 10 ms without also switching to ZGC typically causes G1 to thrash with very frequent tiny collections.

Step 5 - Tune ZGC for sub-millisecond latency

From the ZGC section: ZGC performs all expensive work concurrently; pauses remain below 1 ms regardless of heap size. The primary tuning lever is -Xmx.

-XX:+UseZGC -XX:+ZGenerational   # generational mode recommended
-Xms8g -Xmx8g
-XX:+AlwaysPreTouch               # pre-page memory at startup (reduces first-request jitter)
-XX:SoftMaxHeapSize=7g            # soft ceiling; GC keeps heap under this when possible

ZGC does NOT benefit from manual tuning of pause-time targets - those flags are G1-specific. If ZGC pauses grow, increase -Xmx or reduce allocation rate.

Step 6 - Analyse allocation rate

High allocation rate is the primary driver of GC frequency. Allocation rate (MB/s) = heap consumed between GC events / time between events.

Compute from GC log heap lines:

# Extract heap-before values from gc.log
grep "Pause Young" gc.log \
  | awk -F'[-> ()ms]+' '{print $5, $7, $9, $10}' \
  # fields: before_MB after_MB capacity_MB pause_ms

Allocation rate signals:

To identify the allocation call sites, enable gc+alloc+profiling:

-Xlog:gc+alloc+profiling=debug:file=alloc.log:time

Or use JFR (see Step 7) which captures allocation sites with lower overhead.

Step 7 - Use Java Flight Recorder (JFR) for deep analysis

JFR provides structured GC event data with nanosecond resolution and captures allocation stack traces. Per the JFR API documentation, JFR provides more context, better timing control, and richer event information than text log files.

Enable JFR during a load test:

java -XX:StartFlightRecording=duration=120s,filename=recording.jfr,settings=profile \
     -jar app.jar

The key JFR event categories for GC analysis (jdk.GarbageCollection, jdk.ObjectAllocationInNewTLAB, jdk.ObjectAllocationOutsideTLAB, and more) are listed in references/gc-reference.md.

Analyse the .jfr file with JDK Mission Control (GUI) or the jfr CLI:

# Print GC pause summary from recording
jfr print --events jdk.GarbageCollection recording.jfr | head -100

# Print allocation call sites (top allocators)
jfr print --events jdk.ObjectAllocationInNewTLAB recording.jfr \
  | sort -t'=' -k2 -rn | head -20

Step 8 - Analyse with GCViewer

GCViewer parses GC log files and computes summary metrics (throughput, pause time statistics, allocation rate, promotion rate) from the same -Xlog:gc* output.

# Run GCViewer (requires Java)
java -jar gcviewer-1.36.jar gc.log

The key metrics GCViewer surfaces (throughput %, avg/max pause, allocation and promotion rate) and how to read them are in references/gc-reference.md.

Step 9 - Trace the GC-pause-to-latency-tail link

A GC pause does not appear in CPU flame graphs (threads are suspended). To correlate GC pauses with HTTP latency spikes:

1. Align GC log timestamps with load runner request timing. Both must use wall clock (-Xlog:gc*:decorators=time; k6 uses Unix epoch).
2. In k6 output or Gatling simulation.log, find requests whose response time exceeds p99 baseline. Note their timestamps.
3. In GC log, find Pause events that overlap those windows. A 50 ms STW pause causes all concurrent requests to stall for 50 ms.
4. If the spikes co-occur with Pause Full or Pause Young (Concurrent Start), the collector is failing to keep up with allocation rate; see Steps 4-6.
5. If spikes occur without matching GC pauses, GC is not the cause; escalate to flame-graph-analyzer for CPU profiling.

Output format

After completing the diagnostic, emit a findings block:

## JVM GC diagnosis - <service-name>

**Collector:** G1 / ZGC / Parallel / Serial
**Heap:** Xms=Ng / Xmx=Ng (fixed or dynamic)
**Log capture window:** Ns during load test at Nrps

### Pause summary
| Metric | Observed | Target |
|--------|----------|--------|
| Mean pause | Nms | MaxGCPauseMillis |
| p99 pause | Nms | - |
| Max pause (cause) | Nms (Pause Full / Humongous / ...) | - |
| Throughput (% non-GC) | N% | >95% |

### Allocation rate
N MB/s average; peak N MB/s at N rps load.
Top allocator: <class>.<method> (<evidence: JFR or alloc log>)

### Finding
<One sentence: what is wrong and why it causes latency tail.>

### Recommended changes
1. <Flag change with before/after value>
2. <Heap resize or allocation fix>

### Verification
Re-run load test with the same scenario; confirm p99 drops below threshold and
throughput % improves. Feed results to perf-budget-gate.

Anti-patterns

Limitations

• GC log timestamps use wall-clock by default; under NTP corrections they can drift relative to request timestamps. Use monotonic uptime (uptime decorator) for precise GC-to-request correlation.
• -Xlog:gc+alloc+profiling=debug adds overhead (10-15% CPU). Use JFR allocation profiling in production-representative environments instead.
• ZGC sub-millisecond claim applies to STW pauses only. Concurrent GC threads compete for CPU with application threads; under heavy load this can increase latency via CPU contention even without STW pauses.
• GCViewer does not support ZGC log format for all ZGC-specific events; use JFR for ZGC deep analysis.

References

• HotSpot GC Tuning Guide (Java 21) - introduction and goals: https://docs.oracle.com/en/java/javase/21/gctuning/introduction-garbage-collection-tuning.html
• Available Collectors + selection criteria: https://docs.oracle.com/en/java/javase/21/gctuning/available-collectors.html
• G1 GC tuning flags and mixed GC mechanics: https://docs.oracle.com/en/java/javase/21/gctuning/garbage-first-g1-garbage-collector1.html
• ZGC characteristics and configuration: https://docs.oracle.com/en/java/javase/21/gctuning/z-garbage-collector.html
• Ergonomics and GCTimeRatio formula: https://docs.oracle.com/en/java/javase/21/gctuning/ergonomics.html
• Unified logging syntax (-Xlog:gc*) in the java man page: https://docs.oracle.com/en/java/javase/21/docs/specs/man/java.html
• JFR API programmer's guide (event richness, timing, custom events): https://docs.oracle.com/en/java/javase/21/jfapi/why-use-jfr-api.html
• GCViewer open-source GC log analyser: https://github.com/chewiebug/GCViewer
• Upstream skill for CPU hot-path analysis: flame-graph-analyzer