Reading GC Logs: Metrics, Safepoints and Tuning Profiles

Choosing a collector is the start; running it well means reading what it tells you. This part covers GC logging, the metrics worth watching, safepoints as a hidden source of pauses, and tuning profiles for four typical workloads.

Tuning and Monitoring - Reading the Sheet Music

Essential GC Logging

# Unified logging (Java 9+)
java -Xlog:gc*:file=gc.log:time,uptime,level,tags:filecount=10,filesize=100m ...

# Key metrics to monitor
java -Xlog:gc+heap=info,gc+phases=debug,gc+age=trace ...

Critical Metrics

Common Problems and Solutions

Problem: Frequent Full GCs

• Cause: Heap too small, memory leak, or premature promotion
• Solution: Increase heap, tune young generation size, check for leaks

Problem: Long Pause Times with G1

• Cause: Heap too large, humongous objects, or target too aggressive
• Solution: Reduce heap, increase region size, raise pause target

Problem: ZGC Using Too Much CPU

• Cause: Allocation rate exceeds collection rate
• Solution: Reduce allocation, add heap, or tune concurrent threads

Problem: OutOfMemoryError despite free heap

• Cause: Native memory exhaustion (metaspace, direct buffers)
• Solution: Raise MaxMetaspaceSize, review direct buffer usage

Safepoints - The Hidden Pause Driver

The article has focused on GC pauses, but GC is only one operation that requires your application to pause. Understanding safepoints completes the picture of JVM latency.

A safepoint is a point in program execution where all application threads must pause so the JVM can perform operations that require a consistent view of the heap and thread stacks. These operations include:

• Garbage Collection (stop-the-world phases)
• Deoptimization (reverting optimized code to interpreted mode)
• Class redefinition (hotswap during debugging)
• Thread dumps and heap dumps
• JVMTI operations (profiling, debugging)

The Time-to-Safepoint (TTSP) Problem

When a safepoint operation is requested, the JVM must wait for all application threads to reach a safepoint. This delay is called Time-to-Safepoint (TTSP). Even with ZGC’s sub-millisecond GC pauses, a long TTSP can result in multi-second application pauses.

What causes long TTSP?

1. Counted loops without safepoint polls - Tight loops executing billions of iterations without method calls or allocations don’t check for pending safepoints. Since Java 10, with G1, ZGC and Shenandoah the JIT splits such loops and adds a poll every 1,000 iterations (loop strip mining), so today this mostly hits Serial and Parallel, where it is off by default
2. Large array copies - System.arraycopy() over large arrays blocks until completion
3. JNI calls - Native code cannot be interrupted
4. Memory-mapped I/O operations - Reading large mapped files synchronously

Diagnosing TTSP Issues

# Enable safepoint logging (verbose)
java -Xlog:safepoint*:file=safepoint.log:time,uptime,level,tags:filecount=10,filesize=100m ...

# Key fields in unified log output:
# "Reaching safepoint" = TTSP (time waiting for threads)
# "At safepoint" = VM operation time (GC, deopt, etc.)
# High "Reaching safepoint" with low "At safepoint" = TTSP problem

Interpreting safepoint logs:

Modern unified logging (-Xlog:safepoint*) outputs entries showing the time breakdown for each safepoint operation. Look for these phases:

• Reaching safepoint - Time waiting for all threads to reach a safepoint (TTSP)
• At safepoint - Time spent performing the actual VM operation (GC, deoptimization, etc.)
• Total - Combined time from request to completion

If “Reaching safepoint” time exceeds your latency budget while “At safepoint” time is low, you have a TTSP problem, not a GC problem.

Fixing TTSP Issues

1. Add Thread.yield() or Thread.sleep(0) in tight loops processing large datasets
2. Chunk large array operations - Process 1MB at a time instead of 1GB
3. Use async file I/O instead of blocking memory-mapped operations
4. Review JNI usage - Native code cannot be interrupted; minimize time spent in JNI calls

Modern JVMs (Java 10+) use polling-page-based safepoint mechanisms, making timer-based tuning largely unnecessary. TTSP issues require application-level fixes rather than JVM flags.

Workload-Specific Tuning Profiles

Selecting the right collector is only the beginning - configuring it for your specific workload pattern is what separates production-ready applications from those that fail under load. Different workload archetypes have fundamentally different allocation patterns, object lifetimes, and latency requirements.

Here are four archetypal workload patterns with specific tuning recommendations:

Profile 1: High-Frequency REST API

Characteristics: Massive volume of short-lived request/response objects, strict latency SLAs (p99 < 100ms)

Collector Choice: ZGC (generational, Java 23+) or Shenandoah (Java 25+)

Recommended Configuration:

java -XX:+UseZGC \
     -XX:+AlwaysPreTouch \
     -XX:MaxRAMPercentage=75.0 \
     -Xms4g -Xmx4g \
     -jar api-service.jar

Tuning Notes:

• ZGC needs no pause target: its pauses stay short at any heap size, so the heap size is the main knob
• Pre-touch pages to avoid allocation pauses during traffic spikes
• Monitor allocation rate - if > 1GB/s, consider increasing heap or optimizing object creation

Profile 2: Stateful WebSocket/Streaming Service

Characteristics: Long-lived connections (minutes to hours), gradual old generation growth, steady-state allocation

Collector Choice: G1 GC or Shenandoah

Recommended Configuration:

java -XX:+UseG1GC \
     -XX:MaxGCPauseMillis=100 \
     -XX:G1HeapRegionSize=16m \
     -XX:InitiatingHeapOccupancyPercent=35 \
     -XX:+UseStringDeduplication \
     -Xms8g -Xmx8g \
     -jar streaming-service.jar

Tuning Notes:

• Larger regions (16MB) reduce region management overhead for long sessions
• Lower IHOP (35%) starts old gen collection earlier, preventing full GC
• String deduplication helps with repeated JSON payloads in WebSocket frames
• Monitor tenuring threshold - long-lived session objects should promote quickly to old gen

Profile 3: Data Pipeline / ETL / Batch Processing

Characteristics: Throughput priority, predictable object lifetimes, large working sets, temporary spikes

Collector Choice: Parallel GC

Recommended Configuration:

java -XX:+UseParallelGC \
     -XX:ParallelGCThreads=16 \
     -XX:GCTimeRatio=19 \
     -XX:MaxGCPauseMillis=1000 \
     -Xms32g -Xmx32g \
     -jar etl-job.jar

Tuning Notes:

• Maximize throughput over latency (1s pauses acceptable for batch)
• Match GC threads to available CPU cores
• Large heap accommodates working set without premature promotion
• Monitor GC overhead - should be < 5% of total runtime

Profile 4: Machine Learning Inference Service

Characteristics: Large primitive arrays, off-heap buffers (DirectByteBuffer), irregular allocation spikes, mixed object sizes

Collector Choice: ZGC (large heap support) or G1 with humongous region tuning

Recommended Configuration:

java -XX:+UseZGC \
     -XX:MaxDirectMemorySize=8g \
     -XX:+UseLargePages \
     -XX:+AlwaysPreTouch \
     -XX:MaxRAMPercentage=80.0 \
     -Xms24g -Xmx24g \
     -jar ml-inference.jar

Tuning Notes:

• Large pages improve TLB performance for array access
• Monitor direct memory separately from heap - native OOM can occur despite free heap
• ZGC’s scalability to 16TB heaps handles large model weights efficiently
• Consider off-heap memory management (Foreign Memory API) for model tensors to reduce GC pressure

Key Diagnostic Commands:

# Check direct buffer usage
jcmd <pid> VM.native_memory summary

# Monitor allocation rate in real-time
jstat -gc <pid> 1s | awk '{print $6}'  # EU (Eden Used) - Column 6

# Profile allocation by object type
java -XX:StartFlightRecording=filename=allocation-profile.jfr,duration=60s \
     -XX:FlightRecorderOptions=stackdepth=128 \
     -XX:+UnlockDiagnosticVMOptions \
     -XX:+DebugNonSafepoints ...