在 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 的一些有用連結：