Verbose Garbage Collection in Java – Java中的粗略垃圾收集

最后修改: 2018年 12月 27日

中文/混合/英文(键盘快捷键：t)

1. Overview

1.概述

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.

在本教程中，我们将看看如何在Java应用程序中打开粗略的垃圾收集。首先，我们将介绍什么是粗略的垃圾收集，以及为什么它能发挥作用。

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.

要了解有关垃圾收集（GC）的更多信息以及可用的不同实现，请查看我们关于Java垃圾收集器的文章。

2. Brief Introduction to Verbose Garbage Collection

2.粗略介绍垃圾回收

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.

在调整和调试许多问题时，经常需要切换到粗略的垃圾收集记录，特别是内存问题。事实上，有人认为，为了严格监控我们的应用程序的健康状况，我们应该始终监控JVM的垃圾收集性能。

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.

正如我们将看到的，GC日志是一个非常重要的工具，可以揭示我们应用程序的堆和GC配置的潜在改进。对于每一次 GC 的发生，GC 日志提供了关于其结果和持续时间的准确数据。

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.

随着时间的推移，对这些信息的分析可以帮助我们更好地理解应用程序的行为，并帮助我们调整应用程序的性能。此外，它可以通过指定最佳堆大小、其他JVM选项和替代的GC算法，帮助优化GC频率和收集时间。

2.1. A Simple Java Program

2.1.一个简单的Java程序

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

我们将使用一个简单的Java程序来演示如何启用和解释我们的GC日志。

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().

正如我们在上面的例子中看到的，这个简单的程序将300万个String实例加载到一个Map对象中。然后我们使用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.

最后，我们从Map中删除200万个String实例。我们还明确使用System.out.println，以使解释输出更容易。

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

在下一节，我们将看到如何激活GC日志。

3. Activating “simple” GC Logging

3.激活 “简单 “的GC日志记录

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

让我们开始运行我们的程序，并通过JVM的启动参数启用verbose GC。

-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.

这里的重要参数是-verbose:gc，它以最简单的形式激活了垃圾收集信息的记录。默认情况下，GC日志被写入stdout，并且应该为每个年轻一代的GC和每个完整的GC输出一行。

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

在我们的例子中，我们通过参数-XX:+UseSerialGC指定了串行垃圾收集器，即最简单的GC实现。

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

我们还设置了1024mb的最小和最大堆大小，当然还有更多的JVM参数我们可以进行调整。

3.1. Basic Understanding of the Verbose Output

3.1.对粗体输出的基本理解

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.

在上面的输出中，我们已经可以看到很多关于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.

首先，我们可以看到，发生了四次收集，一次是完整的GC，三次是清洗年轻一代。

3.2. The Verbose Output in More Detail

3.2.更详细的 “粗话 “输出

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.

因此，如果我们取第一行，279616K->146232K(1013632K)意味着GC将占用的堆内存从279616K减少到146232K。GC时的堆容量为1013632K，GC耗时0.3318607秒。

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.

然而，尽管简单的GC日志格式可能是有用的，但它提供的细节有限。例如，我们无法得知GC是否将任何对象从年轻一代转移到了老一代，或者每次收集前后年轻一代的总大小是多少。

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

由于这个原因，详细的GC日志比简单的日志更有用。

4. Activating “detailed” GC Logging

4.激活 “详细的 “GC日志记录

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

为了激活详细的GC日志，我们使用参数-XX:+PrintGCDetails。这将给我们提供关于每个GC的更多细节，例如。

  • 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.

在下一个例子中，我们将看到如何结合-verbose:gc和这个额外的参数在我们的日志中捕获更多的详细信息。

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. 

请注意，-XX:+PrintGCDetails标志在Java 9中已被废弃，转而使用新的统一的日志机制（后面会有更多介绍）。总之，与-XX:+PrintGCDetails相当的新选项是-Xlog:gc*。

5. Interpreting the “detailed” Verbose Output

5.解释 “详细 “的粗略输出

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.

我们应该能够从简单的GC日志中认出所有的元素。但是有几个新项目。

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

5.1.解释年轻一代中的小规模GC

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

我们首先分析一下小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

5.2.解释一个完整的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.

在这个倒数第二个例子中，我们看到，对于一个由我们的系统调用触发的主要集合（Full GC），使用的收集器是Tenured。

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

我们看到的最后一条额外信息是遵循相同模式的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. 

Metaspace是Java 8中引入的一个新的内存空间，是本地内存的一个区域。

5.3. Java Heap Breakdown Analysis

5.3.Java堆的分解分析

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.

我们可以看到，伊甸园空间有35%的足迹，终身制有52%的足迹。此外，还包括元数据空间和班级空间的总结。

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

从上述例子中，我们现在可以确切地了解在GC事件中JVM内部的内存消耗情况。

6. Adding Date and Time Information

6.添加日期和时间信息

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.

当我们需要将GC日志数据与其他来源的数据进行关联时，这些额外的信息可能非常有用，或者它可以简单地帮助促进搜索。

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:

现在，每一行都以写入的绝对日期和时间开始，然后是反映自JVM启动以来以秒为单位的实时时间的时间戳。

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:

请注意，这些调整标志在Java 9中已被删除。 新的替代方法是。

-Xlog:gc*::time

7. Logging to a File

7.记录到一个文件

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

正如我们已经看到的，默认情况下，GC日志被写到stdout。一个更实用的解决方案是指定一个输出文件。

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

我们可以通过使用参数-Xloggc:<file>来实现，其中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:

与其他调整标志类似，Java 9废除了-Xloggc标志，改用新的统一日志。更具体地说，现在记录到文件的替代方案是。

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

8. Java 9: Unified JVM Logging

8.Java 9：统一的JVM日志

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.

从Java 9开始，大部分与GC相关的调整标志已经被弃用，转而使用统一的日志选项-Xlog:gc。然而，–verbose:gc选项在Java 9和更新的版本中仍然有效。

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

例如，从Java 9开始，新的统一日志系统中的-verbose:gc标志的等价物是。

-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:

这将把所有信息级别的GC日志记录到标准输出。也可以使用-Xlog:gc=<level>语法来改变日志级别。例如，要查看所有调试级别的日志。

-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=<level>:<output>语法改变输出目的地。默认情况下，输出是stdout，但我们可以将其改为stderr甚至是一个文件。

-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.

在这里，我们要在每个日志语句中打印进程的ID、运行时间和当前的时间戳。

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

要查看统一JVM日志的更多示例，请参见JEP 158标准。

9. A Tool to Analyze GC Logs

9.分析GC日志的工具

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.

使用文本编辑器来分析GC日志可能会很费时且相当乏味。根据JVM的版本和使用的GC算法，GC日志的格式可能有所不同。

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!

一定要看看Universal GC Log Analyzer!

10. Conclusion

10.结论

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

总而言之，在本教程中，我们已经详细地探讨了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.

首先，我们开始介绍什么是粗略的垃圾收集，以及为什么我们可能想要使用它。然后，我们使用一个简单的Java应用程序看了几个例子。我们从最简单的启用GC日志开始，然后探索几个更详细的例子以及如何解释输出。

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

最后，我们探讨了记录时间和日期信息的几个额外选项，以及如何将信息写入日志文件。

The code examples can be found over on GitHub.

代码实例可以在GitHub上找到over。