求你了，GC 日誌打印別再瞎配置了

先點贊再看，養成好習慣

生產環境上，或者其餘要測試 GC 問題的環境上，必定會配置上打印GC日誌的參數，便於分析 GC 相關的問題。

可是可能不少人配置的都不夠「完美」，要麼是打印的內容過少，要麼是輸出到控制檯，要麼是一個大文件被覆蓋，要麼是……

本文帶你一步一步，配置一個完美的 GC 日誌打印策略

打印內容

爲了保留足夠多的「現場證據」，最好是 GC 相關的信息打印完整。並且你的程序真的不差你GC時打印日誌I/O消耗的那點性能

打印基本 GC 信息

打印 GC 日誌的第一步，就是開啓 GC 打印的參數了，也是最基本的參數。

-XX:+PrintGCDetails -XX:+PrintGCDateStamps

打印對象分佈

爲了分析 GC 時的晉升狀況和晉升致使的高暫停，不看對象年齡分佈日誌怎麼行

-XX:+PrintTenuringDistribution

輸出內容示例：

Desired survivor size 59244544 bytes, new threshold 15 (max 15)
- age   1:     963176 bytes,     963176 total
- age   2:     791264 bytes,    1754440 total
- age   3:     210960 bytes,    1965400 total
- age   4:     167672 bytes,    2133072 total
- age   5:     172496 bytes,    2305568 total
- age   6:     107960 bytes,    2413528 total
- age   7:     205440 bytes,    2618968 total
- age   8:     185144 bytes,    2804112 total
- age   9:     195240 bytes,    2999352 total
- age  10:     169080 bytes,    3168432 total
- age  11:     114664 bytes,    3283096 total
- age  12:     168880 bytes,    3451976 total
- age  13:     167272 bytes,    3619248 total
- age  14:     387808 bytes,    4007056 total
- age  15:     168992 bytes,    4176048 total

GC後打印堆數據

每次發生 GC 時，對比一下 GC 先後的堆內存狀況，更直觀

-XX:+PrintHeapAtGC

輸出內容示例：

{Heap before GC invocations=0 (full 0):
 garbage-first heap   total 1024000K, used 324609K [0x0000000781800000, 0x0000000781901f40, 0x00000007c0000000)
  region size 1024K, 6 young (6144K), 0 survivors (0K)
 Metaspace       used 3420K, capacity 4500K, committed 4864K, reserved 1056768K
  class space    used 371K, capacity 388K, committed 512K, reserved 1048576K
Heap after GC invocations=1 (full 1):
 garbage-first heap   total 1024000K, used 21755K [0x0000000781800000, 0x0000000781901f40, 0x00000007c0000000)
  region size 1024K, 0 young (0K), 0 survivors (0K)
 Metaspace       used 3420K, capacity 4500K, committed 4864K, reserved 1056768K
  class space    used 371K, capacity 388K, committed 512K, reserved 1048576K
}

打印STW時間

暫停時間是 GC 最重要的指標，確定不能少

-XX:+PrintGCApplicationStoppedTime

輸出內容示例：

Total time for which application threads were stopped: 0.0254260 seconds, Stopping threads took: 0.0000218 seconds

打印safepoint信息

進入STW階段以前，須要要找到一個合適的 safepoint ，這個指標同樣很重要（非必選，出現 GC 問題時最好加上此參數調試）

-XX:+PrintSafepointStatistics -XX:PrintSafepointStatisticsCount=1

輸出內容示例：

vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
0.371: ParallelGCFailedAllocation       [      10          0              0    ]      [     0     0     0     0     7    ]  0   
Execute full gc...dataList has been promoted to cms old space
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
0.379: ParallelGCSystemGC               [      10          0              0    ]      [     0     0     0     0    16    ]  0   
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
0.396: no vm operation                  [       9          1              1    ]      [     0     0     0     0   341    ]  0

打印Reference處理信息

強引用/弱引用/軟引用/虛引用/finalize 方法萬一有問題，不得打印出來看看？

-XX:+PrintReferenceGC

輸出內容示例：

2021-02-19T12:41:30.462+0800: 5072726.605: [SoftReference, 0 refs, 0.0000521 secs]
2021-02-19T12:41:30.462+0800: 5072726.605: [WeakReference, 0 refs, 0.0000069 secs]
2021-02-19T12:41:30.462+0800: 5072726.605: [FinalReference, 0 refs, 0.0000056 secs]
2021-02-19T12:41:30.462+0800: 5072726.605: [PhantomReference, 0 refs, 0 refs, 0.0000059 secs]
2021-02-19T12:41:30.462+0800: 5072726.605: [JNI Weak Reference, 0.0000131 secs], 0.4635293 secs]

完整參數

# requireds
-XX:+PrintGCDetails 
-XX:+PrintGCDateStamps 
-XX:+PrintTenuringDistribution 
-XX:+PrintHeapAtGC 
-XX:+PrintReferenceGC 
-XX:+PrintGCApplicationStoppedTime

# optional
-XX:+PrintSafepointStatistics 
-XX:PrintSafepointStatisticsCount=1

輸出方式

上面只是定義了打印的內容，默認狀況下，這些日誌會輸出到控制檯（標準輸出）。那若是你的程序日誌也輸出到控制檯呢，這個日誌內容就會很亂，分析起來很麻煩。若是你是追加的方式（好比 tomcat 的 catalina.out 就是追加），這個文件會愈來愈大，分析起來就要命了。

因此須要一種分割日誌的機制，這個機制嘛……JVM天然是提供的。

JVM的日誌分割

JVM提供了幾個用於分割 GC 日誌的參數：

# GC日誌輸出的文件路徑
-Xloggc:/path/to/gc.log
# 開啓日誌文件分割
-XX:+UseGCLogFileRotation 
# 最多分割幾個文件，超過以後從頭開始寫
-XX:NumberOfGCLogFiles=14
# 每一個文件上限大小，超過就觸發分割
-XX:GCLogFileSize=100M

按照這個參數，每一個GC日誌只要超過20M就會進行分割，最多分割5個文件，文件名依次是gc.log.0,gc.log.1,gc.log.2,gc.log.3,gc.log.4, .....

看似很美好，幾行配置就搞定了輸出文件的問題。可是這種方式有一些問題：

1. -Xloggc 方式指定的日誌文件，是覆蓋寫的方式，每次啓動都會覆蓋，歷史日誌會丟失
2. 當超過最大分割數後，會從第0個文件開始從新寫入，並且是覆蓋
3. -XX:NumberOfGCLogFiles 並不能設置爲無限

這個覆蓋的問題就有點噁心了，每次啓動覆蓋以前的歷史日誌……這誰能忍？

使用時間戳命名文件

因而有另外一種解決方案。不使用 JVM 提供的日誌分割功能，而是每次啓動用時間戳命名日誌文件，這樣能夠每次啓動都使用不一樣的文件，就不會出現覆蓋的問題了。

# 使用-%t做爲日誌文件名
-XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:/path/to/gc-%t.log

# 生成的文件名是這種：gc-2021-03-29_20-41-47.log

但是這樣就完美嗎？

雖然沒有覆蓋的問題，但因爲沒有日誌分割的功能，每次啓動後只有一個GC日誌文件，單個日誌文件可能會很是巨大。過大的日誌文件分析起來是很麻煩的，必須得分割。

兩者結合

這裏只須要稍微調整一下策略，將 JVM 分割和時間戳命名兩種方案結合，就能夠獲得最優的方式了。

# GC日誌輸出的文件路徑
-Xloggc:/path/to/gc-%t.log
# 開啓日誌文件分割
-XX:+UseGCLogFileRotation 
# 最多分割幾個文件，超過以後從頭開始寫
-XX:NumberOfGCLogFiles=14
# 每一個文件上限大小，超過就觸發分割
-XX:GCLogFileSize=100M

配置時間戳做文 GC 日誌文件名的同時，也配置JVM的GC日誌分割策略。這樣一來，既保證了 GC 文件不會被覆蓋，又保證了單個 GC 文件的大小不會過大，完美！

最終獲得的日誌文件名會像這個樣子：

1. gc-2021-03-29_20-41-47.log.0
2. gc-2021-03-29_20-41-47.log.1
3. gc-2021-03-29_20-41-47.log.2
4. gc-2021-03-29_20-41-47.log.3
5. ....

最佳實踐 - 完整參數

# 必備
-XX:+PrintGCDetails 
-XX:+PrintGCDateStamps 
-XX:+PrintTenuringDistribution 
-XX:+PrintHeapAtGC 
-XX:+PrintReferenceGC 
-XX:+PrintGCApplicationStoppedTime

# 可選
-XX:+PrintSafepointStatistics 
-XX:PrintSafepointStatisticsCount=1

# GC日誌輸出的文件路徑
-Xloggc:/path/to/gc-%t.log
# 開啓日誌文件分割
-XX:+UseGCLogFileRotation 
# 最多分割幾個文件，超過以後從頭文件開始寫
-XX:NumberOfGCLogFiles=14
# 每一個文件上限大小，超過就觸發分割
-XX:GCLogFileSize=100M

原創不易，禁止未受權的轉載。若是個人文章對您有幫助，就請點贊/收藏/關注鼓勵支持一下吧❤❤❤❤❤❤