這幾天在做JVM調優，順手總結一下gc日誌的東西。

本次分析的gc日誌是Jboss下的gc日誌.

部分截圖：

//這一行說的是JVM是OpenJDK，以及其他資訊
OpenJDK 64-Bit Server VM (25.265-b01) for linux-amd64 JRE (1.8.0_265-b01), built on Jul 28 2020 13:27:15 by "mockbuild" with gcc 4.4.7 20120313 (Red Hat 4.4.7-23)
//記憶體對齊4K，實體記憶體，交換記憶體
Memory: 4k page, physical 32779948k(26626888k free), swap 16777212k(16777212k free)
//JVM啟動引數
CommandLine flags: -XX:CompressedClassSpaceSize=528482304 -XX:GCLogFileSize=3145728 -XX:InitialHeapSize=1366294528 -XX:MaxHeapSize=2414870528 -XX:MaxMetaspaceSize=536870912 -XX:MaxNewSize=524288000 -XX:MetaspaceSize=536870912 -XX:NewSize=524288000 -XX:NumberOfGCLogFiles=5 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:-TraceClassUnloading -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseGCLogFileRotation -XX:+UseParallelGC
2021-07-14T10:42:23.462+0800: 1.799: [GC (Allocation Failure) [PSYoungGen: 384000K->20087K(448000K)] 384000K->20103K(1271296K), 0.0220683 secs] [Times: user=0.05 sys=0.01, real=0.02 secs]
2021-07-14T10:42:25.304+0800: 3.640: [GC (Allocation Failure) [PSYoungGen: 404087K->55290K(448000K)] 404103K->55322K(1271296K), 0.0377894 secs] [Times: user=0.11 sys=0.01, real=0.04 secs]
2021-07-14T10:42:26.547+0800: 4.884: [GC (Allocation Failure) [PSYoungGen: 439290K->63969K(448000K)] 439322K->92450K(1271296K), 0.0577366 secs] [Times: user=0.25 sys=0.04, real=0.05 secs]
2021-07-14T10:42:28.723+0800: 7.059: [GC (Allocation Failure) [PSYoungGen: 447969K->63992K(448000K)] 476450K->141165K(1271296K), 0.0569773 secs] [Times: user=0.21 sys=0.02, real=0.06 secs]
2021-07-14T10:42:31.189+0800: 9.526: [GC (Allocation Failure) [PSYoungGen: 447992K->63983K(448000K)] 525165K->316222K(1271296K), 0.1188205 secs] [Times: user=0.27 sys=0.02, real=0.12 secs]
2021-07-14T10:42:43.725+0800: 22.062: [GC (Allocation Failure) [PSYoungGen: 447983K->63974K(235008K)] 700222K->411549K(1058304K), 0.0787492 secs] [Times: user=0.24 sys=0.02, real=0.08 secs]
 

看看每次gc的日誌含義：

2021-07-14T10:42:23.462+0800: 1.799: [GC (Allocation Failure) [PSYoungGen: 384000K->20087K(448000K)] 384000K->20103K(1271296K), 0.0220683 secs] [Times: user=0.05 sys=0.01, real=0.02 secs]

[GC (Allocation Failure)
發生GC的原因

[PSYoungGen: 384000K->20087K(448000K)] 
PS: Parallel Scavenge 並行掃描
YoungGen：年輕代
384000K->20087K(448000K)：gc前的Eden區大小->gc後eden區的大小(Eden區的總大小)

384000K->20103K(1271296K)：gc前堆空間大小->gc後的堆空間大小（堆空間的總大小）
0.0220683 secs：gc花費的時間

[Times: user=0.05 sys=0.01, real=0.02 secs]
時間：使用者時間， 系統時間， 實際gc時間

 

注意到日誌中時間分為了三塊：user， sys，和 real，三者的區別和含義如下：

　　real：指的是在此次GC事件中所花費的總時間；
　　user：指的是CPU工作在使用者態所花費的時間；
　　sys：指的是CPU工作在核心態所花費的時間。

　　user + sys 就是CPU花費的實際時間，注意這個值統計了所有CPU上的時間，如果程序工作在多執行緒的環境下，這個值是會超出 real 所記錄的值的，即 user + sys >= real

　　對於GC事件來說，無論是 Minor GC 還是 Full GC 的過程，都存在併發的GC演算法，如新生代的ParNew，老年代的ParallelOld，GC過程中工作負載是由多個執行緒共同完成的，這也就意味著使用這些GC演算法時，GC日誌中我們應該觀察到：user + sys > real。
譬如說：配置了ParNew且併發數為5的GC活動（-XX:+UseParNewGC -XX:ParallelGCThreads=5）中，如果user + sys的值為 2 seconds，那麼 real 的時間 就近似為 400ms(2 seconds / 5)。

正常情況下 user+sys > real

如果real 所顯示的時間 遠 大於 user + sys。一般來說，如果觀察到GC日誌裡多次出現了real時間過大，這表明JVM的GC 過程存在某些問題（等待計算資源），原因可能是下面這兩種：

• 頻繁的IO操作
• 缺乏CPU資源

繁忙的I/O操作

　　當程式存在繁忙的I/O操作（網路IO或磁碟IO）時，會讓 real 時間大幅上升。因為在記錄GC日誌的時候，你的程式進行了磁碟讀寫，如果同一時間其他IO操作較重，則此時GC事件會延遲，進而影響了最終的 real 的值。注意，如果程式本身不存在的頻繁的IO操作，同一機器上其他程序的頻繁IO也會影響 real 的最終結果。Linux環境下可以使用 sar 監視機器上的I/O，eg. sar -d -p 1，如果頻繁的IO操作的確存在，可以通過下面兩種方式改進：

• 優化程式本身的IO操作邏輯；
• 消除其他程序帶來的IO影響。

缺乏CPU資源

　　當程式本身是CPU密集型應用，或機器上其他程序佔用了大量的CPU計算資源，則有可能會出現分配不到 CPU cycles的情況，這會讓程式掛起，GC所花費的實際時間也將遠大於 user + sys 的值。

　　可以使用 top 命令觀察一下 程序的CPU利用率，同時輔以Profiler工具統計一段時間內程序的狀態分佈。如果的確是CPU資源不足，解決方法無法下面幾種：

• 優化程式內部的執行緒使用，確保無冗餘的執行緒配置；
• 增加虛擬機器或容器的CPU配置，提升機器總的計算能力。