GC 列印日誌配置 求你了,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, .....
看似很美好,幾行配置就搞定了輸出檔案的問題。但是這種方式有一些問題:
-Xloggc 方式指定的日誌檔案,是覆蓋寫的方式,每次啟動都會覆蓋,歷史日誌會丟失
當超過最大分割數後,會從第0個檔案開始重新寫入,而且是覆蓋
-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 檔案的大小不會過大,完美!
最終得到的日誌檔名會像這個樣子:
- gc-2021-03-29_20-41-47.log.0
- gc-2021-03-29_20-41-47.log.1
- gc-2021-03-29_20-41-47.log.2
- gc-2021-03-29_20-41-47.log.3
- ....
最佳實踐 - 完整引數
# 必備-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
轉自:https://www.cnblogs.com/jelly12345/p/15597797.html (求你了,GC 日誌列印別再瞎配置了)