This is part 5 of a multi-part series on memory leaks in Java. If you missed any of the last posts, you can find them here:
- Part 1 – Overview of memory leaks
- Part 2 – The static modifier and anonymous inner classes
- Part 3 – String interning and string concatenation
- Part 4 – Missing equals() and hashCode() methods
In the last few posts, we looked at some of the potential causes of memory leaks.
In this post, we’ll look at using the verbose output from the garbage collector to find memory problems.
Introduction
Before we can fix any memory problems, we obviously need to see what the garbage collector (GC) is doing while our application runs. One of the easiest ways is to switch on verbose output from the garbage collector during runtime.
The GC log is an important tool for revealing any GC and heap configuration issues. For each GC event, the log provides information about what the collector is doing and how long it takes. We can then use this data to determine potential solutions.
We will understand the behaviour of our application better when we analyse the GC logs. They can help us tune our application for the best GC performance. This will help us choose optimal heap sizes, GC frequency and collection times, and even different GC algorithms.
Verbose GC Output
There are a variety of different flags we can use to switch on verbose GC output. The -verbose:gc flag is supported in all Java versions (at least up to Java 21 EA). Different versions of Java have different sets of flags.
To print basic GC messages, use either the -verbose:gc, -XX:+PrintGC or -Xlog:gc flag (depending on the Java version being used).
To print very detailed GC messages, use the -XX:+PrintGCDetails flag. This flag has been deprecated and replaced with the -Xlog:gc* flag.
To log the GC details to a file, use the -Xloggc:filename.log flag. The name of the log file is specified after the colon. This flag has been changed to -Xlog:gc:filename.log.
To include time and date stamps on each message, use the -XX:+PrintGCDateStamps and -XX:+PrintGCTimeStamps flags. These flags work for versions up to Java 8. From Java 9, use the -Xlog:gc::time or -Xlog:gc*::time flags.
To use an alternative garbage collector algorithm, use one of the following flags:
- -XX:+UseSerialGC (best choice for small, simple applications).
- -XX:+UseParallelGC (parallel scavenge/throughput GC improves performance by using multiple processors).
- -XX:+UseParNewGC (the CMS GC has been deprecated from Java 9 and removed from Java 14).
- -XX:+UseG1GC (the G1 GC has replaced the CMS GC, as it has more efficient performance).
Example Code
Here’s a very simple code example. It contains a call to System.gc() which explicitly calls the garbage collector.
/**
* A simple program that prints some memory statistics before and
* after explicitly invoking the garbage collector.
*
* For verbose/detailed GC messages, use the -verbose:gc,
* -XX:+PrintGC or -Xlog:gc flag.
*
*/
import java.util.Locale;
public class GCTest1
{
public static void main(String args[])
{
final String fmt = "%-7s heap size = %,14d bytes%n";
// getting a reference to the JVM runtime
Runtime r = Runtime.getRuntime();
// printing out number of processors for interest's sake
System.out.printf ("Number of processors = %d%n",
r.availableProcessors());
// printing out information about the heap memory
final Locale locale = Locale.ENGLISH;
System.out.printf (locale, fmt, "Maximum", r.maxMemory());
System.out.printf (locale, fmt, "Current", r.totalMemory());
System.out.printf (locale, fmt, "Free", r.freeMemory());
// explicitly run the garbage collector to free memory
System.gc();
// print current and free memory again to see the GC effect
System.out.printf (locale, fmt, "Current", r.totalMemory());
System.out.printf (locale, fmt, "Free", r.freeMemory());
}
} // end of classRunning the program with java -XX:+UseSerialGC -Xlog:gc GCTest1 generates an output similar to the following:
[0.004s][info][gc] Using Serial
Number of processors = 16
Maximum heap size = 4,111,269,888 bytes
Current heap size = 257,490,944 bytes
Free heap size = 250,386,560 bytes
[0.048s][info][gc] GC(0) Pause Full (System.gc()) 6M->0M(245M) 1.705ms
Current heap size = 257,622,016 bytes
Free heap size = 255,250,256 bytesThe verbose GC message are the two:
[0.004s][info][gc] Using Serial
[0.048s][info][gc] GC(0) Pause Full (System.gc()) 6M->0M(245M) 1.705msThe first [info][gc] message specifies the garbage collector algorithm used.
The second specifies that the first GC event GC(0) took place 0.048 seconds after the program started. It was a full garbage collection initiated by the System.gc() call. The last part of the message 6M->0M(245M) 1.705ms says the collector cleared 6 Mbytes from the heap (6M->0M), which took 1.705 milliseconds. The heap size after the event was 245 Mbytes.
We can change the garbage collector used. Try running the program with java -XX:+UseG1GC -Xlog:gc GCTest1. The G1 garbage collector is the default GC from Java 9 onwards.
The -Xlog:gc flag is the same as the -verbose:gc flag. Re-run the program using the -Xlog:gc* flag. This gives a much more detailed output similar to the following. A bit of judicious editing has been done: some lines have been omitted, some lines have been split and a few extra open lines have been added for clarity:
[0.005s][info][gc] Using Serial
[0.005s][info][gc,init] Version: 17.0.2+8-LTS (release)
[0.005s][info][gc,init] CPUs: 16 total, 16 available
[0.005s][info][gc,init] Memory: 16219M
[0.005s][info][gc,init] Large Page Support: Disabled
[0.005s][info][gc,init] NUMA Support: Disabled
[0.005s][info][gc,init] Compressed Oops: Enabled (Zero based)
[0.006s][info][gc,init] Heap Min Capacity: 8M
[0.006s][info][gc,init] Heap Initial Capacity: 254M
[0.006s][info][gc,init] Heap Max Capacity: 4056M
[0.006s][info][gc,init] Pre-touch: Disabled
Number of processors = 16
Maximum heap size = 4,111,269,888 bytes
Current heap size = 257,490,944 bytes
Free heap size = 250,386,560 bytes
[0.046s][info][gc,start ] GC(0) Pause Full (System.gc())
[0.046s][info][gc,phases,start] GC(0) Phase 1: Mark live objects
[0.047s][info][gc,phases ] GC(0) Phase 1: Mark live objects 0.768ms
[0.047s][info][gc,phases,start] GC(0) Phase 2: Compute new object
addresses
[0.047s][info][gc,phases ] GC(0) Phase 2: Compute new object
addresses 0.300ms
[0.047s][info][gc,phases,start] GC(0) Phase 3: Adjust pointers
[0.047s][info][gc,phases ] GC(0) Phase 3: Adjust pointers 0.442ms
[0.048s][info][gc,phases,start] GC(0) Phase 4: Move objects
[0.048s][info][gc,phases ] GC(0) Phase 4: Move objects 0.463ms
[0.048s][info][gc,heap ] GC(0) DefNew: 6937K(78016K)->0K(78144K)
Eden: 6937K(69376K)->0K(69504K) From: 0K(8640K)->0K(8640K)
[0.048s][info][gc,heap ] GC(0) Tenured: 0K(173440K)->926K(173440K)
[0.048s][info][gc,metaspace ] GC(0) Metaspace: 363K(576K)->363K(576K)
NonClass: 337K(448K)->337K(448K) Class: 25K(128K)->25K(128K)
[0.048s][info][gc ] GC(0) Pause Full (System.gc())
6M->0M(245M) 2.609ms
[0.048s][info][gc,cpu ] GC(0) User=0.00s Sys=0.00s Real=0.00s
Current heap size = 257,622,016 bytes
Free heap size = 255,250,256 bytes
[0.049s][info][gc,heap,exit ] Heap
[0.049s][info][gc,heap,exit ] def new generation total 78144K,
used 1853K [0x0000000702800000, 0x0000000707cc0000, 0x0000000757000000)
[0.049s][info][gc,heap,exit ] eden space 69504K, 2% used
[0x0000000702800000, 0x00000007029cf740, 0x0000000706be0000)
[0.049s][info][gc,heap,exit ] from space 8640K, 0% used
[0x0000000706be0000, 0x0000000706be0000, 0x0000000707450000)
[0.050s][info][gc,heap,exit ] to space 8640K, 0% used
[0x0000000707450000, 0x0000000707450000, 0x0000000707cc0000)
[0.050s][info][gc,heap,exit ] tenured generation total 173440K,
used 926K [0x0000000757000000, 0x0000000761960000, 0x0000000800000000)
[0.050s][info][gc,heap,exit ] the space 173440K, 0% used
[0.050s][info][gc,heap,exit ] Metaspace used 364K,
committed 576K, reserved 1056768K
[0.050s][info][gc,heap,exit ] class space used 25K,
committed 128K, reserved 1048576KAs we can see, there’s a vast amount of extra information that we get by using the -Xlog:gc* flag. As can be imagined, this extra data will be overwhelming with a large non-trivial application.
We will then rather log the verbose output to a file using the -Xlog:gc:filename.log flag.
But what will we do with this log file? It’s tedious and time-consuming to analyse GC logs using only a text editor. Depending on the JVM version and the GC algorithm used, the GC log formats can differ, sometimes quite substantially.
Analysing GC Logs
There is an excellent free tool called GCEasy that analyses the GC logs. It provides graphical metrics about potential garbage collection problems. You can upload the log file, and the tool will analyse it for free. There is a limit to the number of free downloads per month. There is a commercial pricing plan that changes these limits. It also provides potential recommendations to fix GC problems.
Another powerful free tool for analysing GC logs is GCViewer. It is open source, so you can also get involved in further development. It is a fork of Tagtraum Industries GCViewer which has been in development for many years.
Conclusion
In the next post, we’ll take a look at using profilers and heap dumps to identify memory and GC issues.
Please share your comments.
Stay safe and keep learning!