Verbose Garbage Collection in Java

1. Overview

In this tutorial, we’ll take a look at how to turn on verbose garbage collection in a Java application. We’ll begin by introducing what verbose garbage collection is and why it can be useful.

Next, we’ll look at several different examples and we’ll learn about the different configuration options available. Additionally, we’ll also focus on how to interpret the output of our verbose logs.

To learn more about Garbage Collection (GC) and the different implementations available, check out our article on Java Garbage Collectors.

2. Brief Introduction to Verbose Garbage Collection

Switching on verbose garbage collection logging is often required when tuning and debugging many issues, particularly memory problems. In fact, some would argue that in order to strictly monitor our application health, we should always monitor the JVM’s Garbage Collection performance.

As we’ll see, the GC log is a very important tool for revealing potential improvements to the heap and GC configuration of our application. For each GC happening, the GC log provides exact data about its results and duration.

Over time, analysis of this information can help us better understand the behavior of our application and help us tune our application’s performance. Moreover, it can help optimize GC frequency and collection times by specifying the best heap sizes, other JVM options, and alternate GC algorithms.

2.1. A Simple Java Program

We’ll use a straightforward Java program to demonstrate how to enable and interpret our GC logs:

public class Application {

    private static Map<String, String> stringContainer = new HashMap<>();

    public static void main(String[] args) {
        System.out.println("Start of program!");
        String stringWithPrefix = "stringWithPrefix";

        // Load Java Heap with 3 M java.lang.String instances
        for (int i = 0; i < 3000000; i++) {
            String newString = stringWithPrefix + i;
            stringContainer.put(newString, newString);
        }
        System.out.println("MAP size: " + stringContainer.size());

        // Explicit GC!
        System.gc();

        // Remove 2 M out of 3 M
        for (int i = 0; i < 2000000; i++) {
            String newString = stringWithPrefix + i;
            stringContainer.remove(newString);
        }

        System.out.println("MAP size: " + stringContainer.size());
        System.out.println("End of program!");
    }
}

As we can see in the above example, this simple program loads 3 million String instances into a Map object. We then make an explicit call to the garbage collector using System.gc().

Finally, we remove 2 million of the String instances from the Map. We also explicitly use System.out.println to make interpreting the output easier.

In the next section, we’ll see how to activate GC logging.

3. Activating “simple” GC Logging

Let’s begin by running our program and enabling verbose GC via our JVM start-up arguments:

-XX:+UseSerialGC -Xms1024m -Xmx1024m -verbose:gc

The important argument here is the -verbose:gc, which activates the logging of garbage collection information in its simplest form. By default, the GC log is written to stdout and should output a line for every young generation GC and every full GC.

For the purposes of our example, we’ve specified the serial garbage collector, the simplest GC implementation, via the argument -XX:+UseSerialGC.

We’ve also set a minimal and maximal heap size of 1024mb, but there are, of course, more JVM parameters we can tune.

3.1. Basic Understanding of the Verbose Output

Now let’s take a look at the output of our simple program:

Start of program!
[GC (Allocation Failure)  279616K->146232K(1013632K), 0.3318607 secs]
[GC (Allocation Failure)  425848K->295442K(1013632K), 0.4266943 secs]
MAP size: 3000000
[Full GC (System.gc())  434341K->368279K(1013632K), 0.5420611 secs]
[GC (Allocation Failure)  647895K->368280K(1013632K), 0.0075449 secs]
MAP size: 1000000
End of program!

In the above output, we can already see a lot of useful information about what is going on inside the JVM.

At first, this output can look pretty daunting, but let’s now go through it step by step.

First of all, we can see that four collections took place, one Full GC and three cleaning Young generations.

3.2. The Verbose Output in More Detail

Let’s decompose the output lines in more detail to understand exactly what is going on:

1. GC or Full GC – The type of Garbage Collection, either GC or Full GC to distinguish a minor or full garbage collection
2. (Allocation Failure) or (System.gc()) – The cause of the collection – Allocation Failure indicates that no more space was left in Eden to allocate our objects
3. 279616K->146232K – The occupied heap memory before and after the GC, respectively (separated by an arrow)
4. (1013632K) – The current capacity of the heap
5. 0.3318607 secs – The duration of the GC event in seconds

Thus, if we take the first line, 279616K->146232K(1013632K) means that the GC reduced the occupied heap memory from 279616K to 146232K. The heap capacity at the time of GC was 1013632K, and the GC took 0.3318607 seconds.

However, although the simple GC logging format can be useful, it provides limited details. For example, we cannot tell if the GC moved any objects from the young to the old generation or what was the total size of the young generation before and after each collection.

For that reason, detailed GC logging is more useful than the simple one.

4. Activating “detailed” GC Logging

To activate the detailed GC logging, we use the argument -XX:+PrintGCDetails. This will give us more details about each GC, such as:

• Size of the young and old generation before and after each GC
• The time it takes for a GC to happen in young and old generation
• The Size of objects promoted at every GC
• A summary of the size of the total heap

In the next example, we’ll see how to capture even more detailed information in our logs combining -verbose:gc with this extra argument.

Please note that the -XX:+PrintGCDetails flag has been deprecated in Java 9, in favor of the new unified logging mechanism (more on this later). Anyway, the new equivalent of the -XX:+PrintGCDetails is the -Xlog:gc* option. 

5. Interpreting the “detailed” Verbose Output

Let’s run our sample program again:

-XX:+UseSerialGC -Xms1024m -Xmx1024m -verbose:gc -XX:+PrintGCDetails

This time the output is rather more verbose:

Start of program!
[GC (Allocation Failure) [DefNew: 279616K->34944K(314560K), 0.3626923 secs] 279616K->146232K(1013632K), 0.3627492 secs] [Times: user=0.33 sys=0.03, real=0.36 secs] 
[GC (Allocation Failure) [DefNew: 314560K->34943K(314560K), 0.4589079 secs] 425848K->295442K(1013632K), 0.4589526 secs] [Times: user=0.41 sys=0.05, real=0.46 secs] 
MAP size: 3000000
[Full GC (System.gc()) [Tenured: 260498K->368281K(699072K), 0.5580183 secs] 434341K->368281K(1013632K), [Metaspace: 2624K->2624K(1056768K)], 0.5580738 secs] [Times: user=0.50 sys=0.06, real=0.56 secs] 
[GC (Allocation Failure) [DefNew: 279616K->0K(314560K), 0.0076722 secs] 647897K->368281K(1013632K), 0.0077169 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
MAP size: 1000000
End of program!
Heap
 def new generation   total 314560K, used 100261K [0x00000000c0000000, 0x00000000d5550000, 0x00000000d5550000)
  eden space 279616K,  35% used [0x00000000c0000000, 0x00000000c61e9370, 0x00000000d1110000)
  from space 34944K,   0% used [0x00000000d3330000, 0x00000000d3330188, 0x00000000d5550000)
  to   space 34944K,   0% used [0x00000000d1110000, 0x00000000d1110000, 0x00000000d3330000)
 tenured generation   total 699072K, used 368281K [0x00000000d5550000, 0x0000000100000000, 0x0000000100000000)
   the space 699072K,  52% used [0x00000000d5550000, 0x00000000ebcf65e0, 0x00000000ebcf6600, 0x0000000100000000)
 Metaspace       used 2637K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 283K, capacity 386K, committed 512K, reserved 1048576K

We should be able to recognize all of the elements from the simple GC log. But there are several new items.

Let’s now consider the new items in the output which are highlighted in blue in the next section:

5.1. Interpreting a Minor GC in Young Generation

We’ll begin by analyzing the new parts in a minor GC:

• [GC (Allocation Failure) [DefNew: 279616K->34944K(314560K), 0.3626923 secs] 279616K->146232K(1013632K), 0.3627492 secs] [Times: user=0.33 sys=0.03, real=0.36 secs]

As before we’ll break the lines down into parts:

1. DefNew – Name of the garbage collector used. This not so obvious name stands for the single-threaded mark-copy stop-the-world garbage collector and is what is used to clean the Young generation
2. 279616K->34944K – Usage of the Young generation before and after collection
3. (314560K) – The total size of the Young generation
4. 0.3626923 secs – The duration in seconds
5. [Times: user=0.33 sys=0.03, real=0.36 secs] – Duration of the GC event, measured in different categories

Now let’s explain the different categories:

• user – The total CPU time that was consumed by Garbage Collector
• sys – The time spent in OS calls or waiting for system events
• real – This is all elapsed time including time slices used by other processes

Since we’re running our example using the Serial Garbage Collector, which always uses just a single thread, real-time is equal to the sum of user and system times.

5.2. Interpreting a Full GC

In this penultimate example, we see that for a major collection (Full GC), which was triggered by our system call, the collector used was Tenured.

The final piece of additional information we see is a breakdown following the same pattern for the Metaspace:

[Metaspace: 2624K->2624K(1056768K)], 0.5580738 secs]

Metaspace is a new memory space introduced in Java 8 and is an area of native memory. 

5.3. Java Heap Breakdown Analysis

The final part of the output includes a breakdown of the heap including a memory footprint summary for each part of memory.

We can see that Eden space had a 35% footprint and Tenured had a 52% footprint. A summary for Metadata space and class space is also included.

From the above examples, we can now understand exactly what was happening with memory consumption inside the JVM during the GC events.

6. Adding Date and Time Information

No good log is complete without date and time information.

This extra information can be highly useful when we need to correlate GC log data with data from other sources, or it can simply help facilitate searching.

We can add the following two arguments when we run our application to get date and time information to appear in our logs:

-XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps

Each line now starts with the absolute date and time when it was written followed by a timestamp reflecting the real-time passed in seconds since the JVM started:

2018-12-11T02:55:23.518+0100: 2.601: [GC (Allocation ...

Please note that these tuning flags have been removed in Java 9. The new alternative is:

-Xlog:gc*::time

7. Logging to a File

As we’ve already seen, by default the GC log is written to stdout. A more practical solution is to specify an output file.

We can do this by using the argument -Xloggc:<file> where file is the absolute path to our output file:

-Xloggc:/path/to/file/gc.log

Similar to other tuning flags, Java 9 deprecated the -Xloggc flag in favor of the new unified logging. To be more specific, now the alternative for logging to a file is:

-Xlog:gc:/path/to/file/gc.log

8. Java 9: Unified JVM Logging

As of Java 9, most of the GC related tuning flags have been deprecated in favor of the unified logging option -Xlog:gc. The –verbose:gc option, however, still works in Java 9 and newer version.

For instance, as of Java 9, the equivalent of the -verbose:gc flag in the new unified logging system is:

-Xlog:gc

This will log all the info level GC logs to the standard output. It’s also possible to use the -Xlog:gc=<level> syntax to change the log level. For instance, to see all debug level logs:

-Xlog:gc=debug

As we saw earlier, we can change the output destination via the -Xlog:gc=<level>:<output> syntax. By default, the output is stdout, but we can change it to stderr or even a file:

-Xlog:gc=debug:file=gc.txt

Also, it’s possible to add a few more fields to the output using decorators. For instance:

-Xlog:gc=debug::pid,time,uptime

Here we’re printing the process id, uptime, and current timestamp in each log statement.

To see more examples of the Unified JVM Logging, see the JEP 158 standard.

9. A Tool to Analyze GC Logs

It can be time-consuming and quite tedious to analyze GC logs using a text editor. Depending on the JVM version and the GC algorithm that is used, the GC log format could differ.

There is a very good free graphical analysis tool that analyzes the Garbage collection logs, provides many metrics about potential Garbage Collection problems, and even provides potential solutions to these problems.

Definitely check out the Universal GC Log Analyzer!

10. Conclusion

To summarize, in this tutorial, we’ve explored in detail verbose garbage collection in Java.

First, we started by introducing what verbose garbage collection is and why we might want to use it. We then looked at several examples using a simple Java application. We began with enabling GC logging in its simplest form before exploring several more detailed examples and how to interpret the output.

Finally, we explored several extra options for logging time and date information and how to write information to a log file.