7 Problems to Look out for When Analyzing Garbage Collection Logs

Last updated: January 18, 2024

Modern garbage collectors use sophisticated algorithms to manage unused memory, so you don’t have to. But when things aren’t working right, you need a way to peek under the hood and troubleshoot issues. Analyzing garbage collection (GC) logs can provide key insights into the behavior and performance of programming languages using automatic memory management, such as Java. If you suspect you’ve got a memory problem with your Java app, the GC log is the first place to look.  

Let me share the seven common app problems you can uncover by analyzing GC logs.  

Starting with JDK 9, the default GC implementation was the Garbage-First Garbage Collector (G1GC). All of the examples in this article assume you’re using JDK 9 or newer with G1GC. However, the Java world is constantly evolving, and newer versions of Java may have been released since this article was written. You should check the official Java documentation or other reliable sources to confirm the default garbage collector in the latest version of Java.  

1. GC Pauses Cause Apps to Stall 

When the garbage collector runs, it can introduce delays into your application. This is because of the way GC is implemented. G1GC will pause your app while it frees unused memory objects and compacts memory regions to reduce wasted space. These GC pauses can introduce visible delays while your app is running.  

You can inspect the GC logs to see how long your app was delayed for by using the -Xlog:safepoint command-line option. Here is an example GC log entry illustrating an app stall:  

[7.971s][info ][safepoint ] Total time for which application threads were stopped: 0.0111253 seconds, Stopping threads took: 0.0000070 seconds

This example shows the GC pause caused the app threads to stall for 11 milliseconds. If you notice your app is periodically stalling, the GC logs are a good place to look.  

2. Memory Leaks 

Even though Java implementations include a garbage collector, which automatically handles memory management, it’s still possible to introduce memory leaks into your app. One way to do this is to use the static keyword for large objects, e.g.  

static final ArrayList<Integer> alist = new ArrayList<Integer>(50000);

Adding objects to this list and forgetting to remove them later causes a memory leak which the garbage collector is unable to work around. Looking at the GC logs can help you detect when this is happening because the amount of memory the garbage collector couldn’t reclaim will continue to increase. The following GC log excerpt demonstrates how to identify if you have a memory leak:  

[22.064s][info ][gc ] GC(112) Pause Young (Normal) (G1 Evacuation Pause) 2848M->537M(3946M) 52.395ms

The item marked in red shows the size of objects currently referenced on the heap after a collection has taken place. If you have a memory leak you’ll see this value increase over time.  

3. The total heap memory size is wrong

The single most important factor affecting Java app performance is the total size of the heap. This is because the frequency of collections is inversely proportional to the size of the regions—bigger regions mean you can allocate more objects before exhausting memory, which means the garbage collector runs less frequently. At the other extreme, if the size of your heap is too small for your workload you’ll see OutOfMemoryError exceptions as your app tries and fails to allocate unused memory.  

The GC log can help you figure out whether the heap is badly sized because it displays statistics at the end of each collection.  

[12.504s][info ][gc,heap,exit ] Heap
[12.504s][info ][gc,heap,exit ] garbage-first heap total 262144K, used 171106K [0x00000000f0000000, 0x0000000100000000)
[12.504s][info ][gc,heap,exit ] region size 1024K, 19 young (19456K), 0 survivors (0K)
[12.504s][info ][gc,heap,exit ] Metaspace used 181K, capacity 4486K, committed 4864K, reserved 1056768K
[12.504s][info ][gc,heap,exit ] class space used 6K, capacity 386K, committed 512K, reserved 1048576K

Here we can see the total heap size is 256MB. Other regions are sized relative to heap, so if you’re seeing too many full collections it might be time to increase the size of the heap. The -Xms and -Xmx control the minimum and maximum size of the heap, respectively.  

4. High allocation rates can cause performance issues

The GC logs provide a way to capture how frequently your app is allocating objects. While high allocation rates aren’t necessarily a problem, they can lead to performance issues. To see whether this is affecting your app you can compare the size of the young generation after a collection and before the next one.  

For example, the following three GC log entries show the app is allocating objects at about 12.48GB/sec.  

[31.087s][info ][gc ] GC(153) Pause Young (Normal) (G1 Evacuation Pause) 3105M->794M(3946M) 55.590ms
[31.268s][info ][gc ] GC(154) Pause Young (Normal) (G1 Evacuation Pause) 3108M->798M(3946M) 55.425ms
[31.453s][info ][gc ] GC(155) Pause Young (Normal) (G1 Evacuation Pause) 3113M->802M(3946M) 55.571ms

Between 31.087s and 31.268s 2314M was allocated by the app (3108M-794M) and between 31.268s and 31.453s another 2315M was allocated (3113M-798M). This works out about 2.3GB every 200ms or 12.48GB/sec. Depending on your app’s behavior, allocating objects at that rate could negatively affect its performance.  

5. Frequent humongous allocations

Humongous allocations are allocations over 50% of the G1 region size (the region size is another statistic printed in the GC log at the end of each collection). If your app uses humongous allocations heavily it can lead to excessive memory fragmentation and OutOfMemoryError exceptions.  

You can check to see whether humongous allocations are causing problems by looking in the GC log for “humongous allocation.” Here’s an example:  

[4.765s][info ][gc ] GC(122) Pause Young (Concurrent Start) (G1 Humongous Allocation) 889M->5M(1985M) 3.339ms

If your app uses humongous allocations and you think G1GC is spending too much time managing them, you can increase the region size to avoid costly collections of humongous objects by using the -XX:G1HeapRegionSize option.  

6. Young objects are promoted too quickly

In contrast to the previous problem where objects are too large to fight in a G1 region, if the young generation size is too small minor collections will occur less frequently and instead full collections (which take more time to execute) will occur more often.  

[4.845s][info ][gc ] GC(437) Pause Full (G1 Evacuation Pause) 255M->98M(256M) 102.056ms

If you see a large number of Pause Full messages in your log you may need to use the -XX:NewRatio option to increase the size of the young generation and avoid the more costly full collections.  

7. Too few GC threads

When G1GC needs to do a full GC it spawns several workers. If you have spare CPU capacity to run more threads, you can significantly reduce GC pause times by letting G1GC use them. For example, the first GC log entry below shows the pause time when running with one thread (-XX:ParallelGCThreads=1) and the second entry shows the pause time with four threads (-XX:ParallelGCThreads=4).  

[8.194s][info ][gc ] GC(638) Pause Full (G1 Evacuation Pause) 255M->128M(256M) 242.539ms
[8.509s][info ][gc ] GC(698) Pause Full (G1 Evacuation Pause) 253M->129M(256M) 111.873ms

The results show the GC pause time was cut in half by increasing the number of threads.

Best Practices for Analyzing Garbage Collection Logs 

Analyzing garbage collection logs is a critical skill for identifying and resolving memory management issues in Java applications. Here are some best practices to follow: 

1. Regular Monitoring: Don’t wait for a performance issue to occur. Regularly monitor your garbage collection logs to understand the normal behavior of your application and identify potential issues early. 

2. Use the Right Tools: Utilize tools like VisualVM, GCViewer, or SolarWinds® Papertrail™ to analyze your GC logs. These tools can provide visualizations and insights that make it easier to interpret the log data. 

3. Understand Key Metrics: Familiarize yourself with key garbage collection metrics such as pause times, throughput, and memory footprint. Understanding these metrics is crucial for accurate analysis. 

4. Correlate with Application Behavior: Correlate garbage collection behavior with application performance and user activity. This can help you identify the root cause of issues more quickly. 

5. Document and Share Findings: Document your findings and share them with your team. This not only helps in resolving the current issue but also serves as a knowledge base for future reference. 

6. Keep Learning: Stay updated with the latest advancements in Java garbage collection and performance tuning. The Java ecosystem is continuously evolving, and staying informed will help you make better decisions. 

By following these best practices, you can ensure a proactive approach to memory management, leading to improved application performance and a better user experience. 

Tools and Resources for Garbage Collection Log Analysis 

Analyzing garbage collection logs can be made easier with the help of various tools and resources. Here’s a list to get you started: 

1. VisualVM: An all-in-one Java troubleshooting tool that can be used for memory profiling, thread analysis, and GC log analysis. 

2. GCViewer: A free, open-source tool to visualize the data stored in Java VM garbage collection logs. 

3. SolarWinds® Papertrail™: A cloud-based log management tool that can aggregate, organize, and analyze your GC logs in real-time. 

4. Oracle’s Garbage Collection Tuning Guide: The official Java Garbage Collection Tuning Guide provides in-depth knowledge and recommendations for tuning garbage collection in Java. 

5. Java Performance: The Definitive Guide: A book by Scott Oaks, providing a comprehensive guide to Java performance tuning, including garbage collection. 

6. Online Forums and Communities: Platforms like Stack Overflow, Reddit, and the official Oracle Java Community are great places to ask questions, share knowledge, and learn from the experiences of other Java developers. 

By leveraging these tools and resources, you can enhance your skills in garbage collection log analysis and ensure that your Java applications run smoothly. 

Garbage Collection Logging in Java 9 and Newer 

With Java 9 and later versions, there have been significant changes and improvements in garbage collection logging. The introduction of the Unified JVM Logging Framework has streamlined the logging output for garbage collection. This has made it easier to understand and analyze logs. Check out this detailed guide on garbage collection logs in Java 9 and newer to learn more.  

GC Logs Conclusion 

Garbage collection algorithms are sophisticated pieces of software designed to alleviate the need to manually manage your app’s memory allocations. The G1GC JVM garbage collector supports several configuration options. To get the best results, you need to tune it appropriately. By carefully analyzing your GC logs you can better understand the performance and behavior of your Java apps.  

However, analyzing GC logs by hand can be extremely time consuming. Fortunately, SolarWinds^® Papertrail^™ can automatically parse GC logs. Additionally, it provides an intuitive search syntax for combing through all of your logs from a central interface. If you want to explore Papertrail’s capabilities further, visit the SolarWinds® Papertrail™ Official Page.  

Understanding garbage collection in Java is crucial for optimizing application performance. To dive deeper into the basics and best practices of Java garbage collection, refer to the Java Garbage Collection Basics guide.