在 Java 中启用详细的 gc 日志记录

Created: November-22, 2018

通常，jvm 的垃圾收集（gc）对用户（开发人员/工程师）是透明的。

除非用户面临内存泄漏或需要大量内存的应用程序，否则通常不需要 GC 调整 - 这两者最终都会导致内存不足异常，从而迫使用户查看问题。

第一步通常是增加内存（堆或 perm-gen / meta-space，具体取决于它是由于运行时加载还是应用程序的 libary 基础很大，或者类加载或线程中是否存在泄漏 - 处理机制）。但是，只要不可行，下一步就是试着了解出了什么问题。

如果只想在特定时刻获得快照，那么作为 jdk 一部分的 jstat 实用程序就足够了。

但是，为了更详细地理解，在每个 gc 事件之前和之后都有一个包含堆快照的日志会很有帮助。为此，用户必须使用 -verbose:gc 作为 jvm 启动参数的一部分并包括 -XX:+PrintGCDetails 和 -XX:+PrintGCTimeStamp 标志来启用详细的 gc 日志记录。

对于那些想要主动描述其应用程序的人，还有像 jvisualvm 这样的工具，它们也是 jdk 的一部分，通过它们可以深入了解应用程序的行为。

下面是一个示例程序，gc 配置和 verbose-gc 日志输出：

package com.example.so.docs.gc.logging;

import java.util.Arrays;
import java.util.Random;

public class HelloWorld {

    public static void main(String[] args) {
        sortTest();
    }
    
    private static void sortTest() {
        System.out.println("HelloWorld");
        
        int count = 3;
        while(count-- > 0) {
            int size = 1024*1024;
            int[] numbers = new int[size];
            Random random = new Random();
            for(int i=0;i<size;i++) {
                numbers[i] = random.nextInt(size);
            }
            
            Arrays.sort(numbers);
        }
        System.out.println("Done");
        
    }
    

}

GC 选项：

-server -verbose:gc  -XX:+PrintGCDetails -XX:+PrintGCTimeStamps  -Xmx10m  -XX:-PrintTenuringDistribution  -XX:MaxGCPauseMillis=250 -Xloggc:/path/to/logs/verbose_gc.log

输出：

Java HotSpot(TM) 64-Bit Server VM (25.72-b15) for windows-amd64 JRE (1.8.0_72-b15), built on Dec 22 2015 19:16:16 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 6084464k(2584100k free), swap 8130628k(3993460k free)
CommandLine flags: -XX:InitialHeapSize=10485760 -XX:MaxGCPauseMillis=250 -XX:MaxHeapSize=10485760 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:-PrintTenuringDistribution -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:-UseLargePagesIndividualAllocation -XX:+UseParallelGC 
0.398: [GC (Allocation Failure) [PSYoungGen: 483K->432K(2560K)] 4579K->4536K(9728K), 0.0012569 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
0.400: [GC (Allocation Failure) [PSYoungGen: 432K->336K(2560K)] 4536K->4440K(9728K), 0.0008121 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
0.401: [Full GC (Allocation Failure) [PSYoungGen: 336K->0K(2560K)] [ParOldGen: 4104K->294K(5632K)] 4440K->294K(8192K), [Metaspace: 2616K->2616K(1056768K)], 0.0056202 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
0.555: [GC (Allocation Failure) [PSYoungGen: 41K->0K(2560K)] 4431K->4390K(9728K), 0.0004678 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
0.555: [GC (Allocation Failure) [PSYoungGen: 0K->0K(2560K)] 4390K->4390K(9728K), 0.0003490 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
0.556: [Full GC (Allocation Failure) [PSYoungGen: 0K->0K(2560K)] [ParOldGen: 4390K->293K(5632K)] 4390K->293K(8192K), [Metaspace: 2619K->2619K(1056768K)], 0.0060187 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
Heap
 PSYoungGen      total 2560K, used 82K [0x00000000ffd00000, 0x0000000100000000, 0x0000000100000000)
  eden space 2048K, 4% used [0x00000000ffd00000,0x00000000ffd14938,0x00000000fff00000)
  from space 512K, 0% used [0x00000000fff80000,0x00000000fff80000,0x0000000100000000)
  to   space 512K, 0% used [0x00000000fff00000,0x00000000fff00000,0x00000000fff80000)
 ParOldGen       total 5632K, used 4389K [0x00000000ff600000, 0x00000000ffb80000, 0x00000000ffd00000)
  object space 5632K, 77% used [0x00000000ff600000,0x00000000ffa49670,0x00000000ffb80000)
 Metaspace       used 2625K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 282K, capacity 386K, committed 512K, reserved 1048576K

以下是关于 GC 的一些有用链接：