How to Generate and Interpret GC Logs

⏱ Time to Read: 9 minutes

TL;DR

Enable GC Logs: Use JVM flags (-XX:+PrintGCDetails, -Xlog:gc*) to capture detailed GC logs.
Understand GC Events: Differentiate between Young GC, Old GC (Full GC), CMS GC, and G1 GC to see how they impact your app.
Analyze Logs: Track GC events alongside application logs to identify memory-heavy operations.
Optimize Performance: Adjust heap size, choose the right GC algorithm, and set pause time goals based on your findings.

If you’re diving into Java performance optimization, understanding and analyzing Garbage Collection (GC) logs is essential. GC logs provide insights into memory management and help identify bottlenecks in your application. This guide walks you through generating GC logs in Java, understanding the parameters, and analyzing the output to optimize your Java app.

Enabling GC Logging in Java

Configuring GC logging in Java involves passing specific parameters to the JVM. The setup differs slightly between Java 8 and earlier versions and Java 9 and later.

Java 8 and Older

In Java 8, you can enable GC logging with the following flags:

-XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -Xloggc:<path-to-log-file>

-XX:+PrintGC: Enables basic GC logging, providing a summary of each GC event.
- Example log:
[GC 12.345: [DefNew: 1024K->64K(2048K), 0.0054 secs] 4096K->2056K(8192K), 0.0056 secs] Here, we see the DefNew event, showing memory usage before and after GC.
-XX:+PrintGCDetails: Adds detailed GC information, such as heap generation details (Young and Old).
- Example:
[GC 1.234: [ParNew: 1024K->64K(2048K), 0.0034 secs] 4096K->2056K(8192K), 0.0035 secs] ParNew indicates the New Generation was processed, showing memory reduction.
-XX:+PrintGCTimeStamps: Adds timestamps for each GC event.
- Example:
5.678: [GC 5.678: [DefNew: 1024K->512K(2048K), 0.0032 secs]] This shows the timestamp (5.678) for tracking the event timing.
-Xloggc:<path-to-log-file>: Specifies the output file for GC logs.

Combined example:

java -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -Xloggc:/path/to/gc.log -jar your-app.jar

Java 9 and Later

Java 9 simplifies GC logging with the -Xlog parameter:

-Xlog:gc*:file=<path-to-log-file>:time

gc*: Captures all GC events (like heap changes and collection phases).
- Example log:
[0.123s][info][gc] GC(0) Pause Young (G1 Evacuation Pause) 10M->5M(128M) 1.234ms Here, Pause Young (G1 Evacuation Pause) denotes a Young GC pause, showing memory reduction and pause time.
file=<path-to-log-file>: Sets the output file for logs.
time: Adds timestamps to each event.

Combined example:

java -Xlog:gc*:file=/path/to/gc.log:time -jar your-app.jar

Additional Options for Enhanced Logging

Add these options for more control:

-XX:+UseGCLogFileRotation: Rotates log files when they reach a set size.
-XX:NumberOfGCLogFiles=<n>: Keeps up to <n> rotated files.
-XX:GCLogFileSize=<size>: Sets the maximum size for each log file.

This configuration, for example, keeps up to five log files, each maxing out at 10 MB:

java -Xlog:gc*:file=/path/to/gc.log:time -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=10M -jar your-app.jar

Understanding Different Types of GC Events

Here’s a quick reference table of common GC events, their meanings, and actions you can take to improve performance and memory management.

GC Event	Meaning	Common Performance Measures
Young GC (Minor GC)	Cleans the Young Generation where short-lived objects are stored.	– Reduce object creation in high-frequency methods. – Use object pooling for frequently created objects. – Increase Eden space if GC is too frequent.
Old GC (Major/Full GC)	Cleans the Old Generation for long-lived objects; often causes a noticeable pause.	– Increase Old Generation size. – Tune `-XX:MaxGCPauseMillis` for G1 GC. – Examine long-lived objects and consider alternative storage or caching mechanisms.
CMS (Concurrent Mark Sweep)	Concurrently marks and sweeps objects across generations, aiming to minimize pause times.	– Increase heap size for memory-intensive applications. – Fine-tune `-XX:CMSInitiatingOccupancyFraction` to control when CMS starts. – Reduce overall memory footprint.
G1 Evacuation Pause	Pauses to evacuate and compact regions in the G1 GC, aiming to clean up regions with most garbage.	– Set `-XX:G1HeapRegionSize` to an appropriate value. – Adjust `-XX:MaxGCPauseMillis` to manage acceptable pause times. – Increase heap size if evacuation is too frequent.
ZGC Pause	Pauses are minimal; only marks and compacts in background, minimizing latency.	– Use ZGC if you require extremely low-latency GC for large heaps. – Monitor ZGC to ensure it’s within expected limits. – Ensure your JVM is updated (Java 11+).
Parallel GC	A “throughput-first” collector that performs GC using multiple threads to reduce pause times.	– Use for applications prioritizing throughput over low latency. – Adjust `-XX:ParallelGCThreads` based on CPU cores. – Increase Young Generation size if pauses are frequent.

By referring to these common events and measures, you can tailor your approach to garbage collection management based on your application’s specific needs and workload. Each adjustment can help you achieve optimal performance or lower memory usage.

How to Correlate GC Events with Application Code

To identify memory-heavy portions in your code, start by correlating GC events with specific workloads.

Track Code Execution and GC Logs: Log timestamps for specific application workloads (e.g., API calls, heavy computations). Compare these with GC logs to see if GC events spike during specific operations.
Look for Repeated Patterns: For example, if a specific GC type occurs frequently after a certain method, it may signal excessive object creation or retention.
Identify Long GC Pauses: Long GC pauses during peak operations often indicate that objects are staying in memory too long. Examine the code to see if you can reduce object allocation, improve caching, or use more memory-efficient data structures.
Analyze Heap Occupancy: If Old Generation fills quickly (often seen with Full GC events), review parts of your code that retain data structures or objects. If possible, modify these areas to reduce memory usage.

Sample GC Log Breakdown

Consider this GC log entry:

[0.123s][info][gc] GC(0) Pause Young (G1 Evacuation Pause) 16M->4M(256M) 2.567ms

Timestamp (0.123s): The time since JVM start.
GC Type (Pause Young): Indicates a Young Generation collection.
Action (G1 Evacuation Pause): Specifies the type of action within G1 GC.
Memory Reduction (16M->4M(256M)): Shows memory usage reduced from 16 MB to 4 MB.
Pause Time (2.567ms): The duration of the GC pause—key for assessing impact on performance.

Tools for Analyzing GC Logs

Parsing GC logs manually can be overwhelming. Several tools help simplify analysis:

GCViewer: Visualizes GC logs for Java, providing graphs and summaries.
GCEasy: An online tool offering in-depth GC log analysis, including graphs and recommendations.
Eclipse MAT: A memory analyzer tool that helps identify memory leaks and heavy memory consumers when used with heap dumps.

The highlights and how to use each tool deserves an article of its own. Join our mailing list to receive updates of when this and other useful articles are published!

Combining Application Logs with GC Logs

To correlate your code with GC events, you can log application events with timestamps and align them with timestamps in the GC logs. By tracking when specific methods, requests, or processes are executed, you can compare these events with the timing of GC activities. Here’s how to approach it:

Use Application Logging with Precise Timestamps:

Ensure that your application logs include precise timestamps, ideally down to the millisecond, to closely match the timestamps in your GC logs.
You can achieve this with Java logging frameworks like Log4j or SLF4J. Configure the timestamp format to show the same level of detail as the GC log timestamps. Example Log4j Configuration:

   log4j.appender.console.layout.ConversionPattern=%d{HH:mm:ss.SSS} %-5p %c{1}:%L - %m%n

This pattern will include milliseconds, making it easier to align with GC event times.

Log Key Application Events:

Log critical points in your application, such as:
- Start and end of significant methods or transactions.
- Entry and exit points for memory-heavy operations.
- Allocation of large objects or collections.
Adding this context allows you to see if a GC event occurs during or after a specific operation, which may indicate high memory usage or frequent object creation. Example:

   logger.info("Starting data processing task at {}", System.currentTimeMillis());

Enable GC Logging:

Enable GC logging as described earlier (using -Xlog:gc* for Java 9+ or -XX:+PrintGCDetails for Java 8).
Ensure the log file path is set, and keep rotation parameters (-XX:+UseGCLogFileRotation, -XX:NumberOfGCLogFiles, -XX:GCLogFileSize) if needed for long-running applications.

Automating Correlation with Java Flight Recorder (JFR)

For more advanced scenarios, Java Flight Recorder (JFR) provides a way to record both application and JVM-level events, including GC. JFR records events directly within the JVM, offering a consolidated view of application behavior alongside GC metrics.

Enable JFR:

Use the following JVM flags to enable JFR:
bash -XX:StartFlightRecording=duration=60s,filename=recording.jfr
This example creates a recording for 60 seconds and saves it to recording.jfr.

Use JFR to Analyze Code and GC Interactions:

JFR records data on method calls, object allocation rates, GC events, and more, enabling you to view where GC events align with application behavior.
Load the .jfr file in tools like JDK Mission Control to analyze the recording visually. You can see precisely which methods run during GC events, object allocation hot spots, and GC pauses. JFR is particularly useful when troubleshooting issues in production as it’s lightweight and doesn’t add significant overhead.

Again, the use of JFR deserves a separate article and we won’t dive in just yet. Stay tuned!

Wrapping Up

Generating and interpreting GC logs can reveal critical performance issues and help optimize Java applications. By understanding the types of GC events, how to correlate them with application behavior, and using the right tools, you can make targeted improvements to keep your app performing at its best. Start with GC logging, analyze the data, and optimize your JVM settings—your Java app’s efficiency depends on it!