GC日志的解讀和分析
Java可以通過以下指令指定啟動GC日志的列印：
#指令 #列印GC日志詳情 #列印GC事件參數 #運作的類名，注這裡是類名不是class檔案名不要字尾
java -XX:+PrintGCDetails -XX:PrintGCDateStamps XXXX(類名)
關于jvm啟動的一些預設堆記憶體參數資訊
1. 如果目前主控端實體記憶體大于1g的情況下會預設使用1/4的實體記憶體作為jvm的堆記憶體大小
2. 如果目前主控端的實體記憶體<=1g，jvm預設會使用目前實體記憶體大小的一半為堆記憶體的大小
在啟動的時候可以通過 -Xms -Xmx 來設定堆記憶體的大小，兩個參數最好設定一樣大小，防止運作的過程jvm自調節堆記憶體大小帶來的性能抖動。
什麼是性能抖動？
2021-08-14T13:15:58.662-0800: [GC (Allocation Failure) [PSYoungGen: 65536K->10738K(76288K)] 65536K->20104K(251392K), 0.0107299 secs] [Times: user=0.02 sys=0.05, real=0.01 secs]
2021-08-14T13:15:58.686-0800: [GC (Allocation Failure) [PSYoungGen: 76274K->10737K(141824K)] 85640K->40977K(316928K), 0.0151278 secs] [Times: user=0.02 sys=0.06, real=0.02 secs]
2021-08-14T13:15:58.754-0800: [GC (Allocation Failure) [PSYoungGen: 141809K->10734K(141824K)] 172049K->80395K(316928K), 0.0263950 secs] [Times: user=0.03 sys=0.12, real=0.03 secs]
2021-08-14T13:15:58.802-0800: [GC (Allocation Failure) [PSYoungGen: 141806K->10748K(272896K)] 211467K->126140K(448000K), 0.0272760 secs] [Times: user=0.04 sys=0.13, real=0.03 secs]
2021-08-14T13:15:58.933-0800: [GC (Allocation Failure) [PSYoungGen: 272892K->10751K(272896K)] 388284K->212632K(475136K), 0.0355946 secs] [Times: user=0.05 sys=0.17, real=0.03 secs]
2021-08-14T13:15:58.969-0800: [Full GC (Ergonomics) [PSYoungGen: 10751K->0K(272896K)] [ParOldGen: 201880K->177802K(347136K)] 212632K->177802K(620032K), [Metaspace: 2679K->2679K(1056768K)], 0.0350235 secs] [Times: user=0.19 sys=0.01, real=0.04 secs]
2021-08-14T13:15:59.055-0800: [GC (Allocation Failure) [PSYoungGen: 262144K->76269K(208384K)] 439946K->258937K(555520K), 0.0382796 secs] [Times: user=0.07 sys=0.16, real=0.04 secs]
2021-08-14T13:15:59.119-0800: [GC (Allocation Failure) [PSYoungGen: 208365K->108539K(240640K)] 391033K->295700K(587776K), 0.0164485 secs] [Times: user=0.10 sys=0.00, real=0.02 secs]
2021-08-14T13:15:59.165-0800: [GC (Allocation Failure) [PSYoungGen: 240635K->108543K(225280K)] 427796K->327872K(572416K), 0.0340029 secs] [Times: user=0.14 sys=0.05, real=0.03 secs]
2021-08-14T13:15:59.223-0800: [GC (Allocation Failure) [PSYoungGen: 225225K->92407K(232960K)] 444555K->354088K(580096K), 0.0347330 secs] [Times: user=0.08 sys=0.11, real=0.03 secs]
2021-08-14T13:15:59.281-0800: [GC (Allocation Failure) [PSYoungGen: 209143K->65157K(232960K)] 470824K->377037K(580096K), 0.0409836 secs] [Times: user=0.08 sys=0.15, real=0.04 secs]
2021-08-14T13:15:59.322-0800: [Full GC (Ergonomics) [PSYoungGen: 65157K->0K(232960K)] [ParOldGen: 311879K->274485K(452096K)] 377037K->274485K(685056K), [Metaspace: 2679K->2679K(1056768K)], 0.0575322 secs] [Times: user=0.31 sys=0.01, real=0.05 secs]
2021-08-14T13:15:59.402-0800: [GC (Allocation Failure) [PSYoungGen: 116736K->37907K(232960K)] 391221K->312392K(685056K), 0.0066941 secs] [Times: user=0.04 sys=0.00, real=0.00 secs]
2021-08-14T13:15:59.437-0800: [GC (Allocation Failure) [PSYoungGen: 154643K->31976K(232960K)] 429128K->340860K(685056K), 0.0162042 secs] [Times: user=0.08 sys=0.00, real=0.02 secs]
2021-08-14T13:15:59.478-0800: [GC (Allocation Failure) [PSYoungGen: 148712K->42767K(232960K)] 457596K->378788K(685056K), 0.0175845 secs] [Times: user=0.04 sys=0.06, real=0.02 secs]
2021-08-14T13:15:59.522-0800: [GC (Allocation Failure) [PSYoungGen: 159384K->44810K(232960K)] 495405K->419897K(685056K), 0.0298354 secs] [Times: user=0.07 sys=0.08, real=0.03 secs]
2021-08-14T13:15:59.578-0800: [GC (Allocation Failure) [PSYoungGen: 161546K->36455K(232960K)] 536633K->452191K(685056K), 0.0268303 secs] [Times: user=0.06 sys=0.08, real=0.03 secs]
2021-08-14T13:15:59.604-0800: [Full GC (Ergonomics) [PSYoungGen: 36455K->0K(232960K)] [ParOldGen: 415736K->316905K(496128K)] 452191K->316905K(729088K), [Metaspace: 2679K->2679K(1056768K)], 0.0626508 secs] [Times: user=0.33 sys=0.01, real=0.06 secs]
執行結束！共生成對象次數: 7600
Heap
PSYoungGen total 232960K, used 5054K [0x00000007aab00000, 0x00000007c0000000, 0x00000007c0000000)
eden space 116736K, 4% used [0x00000007aab00000,0x00000007aafefb20,0x00000007b1d00000)
from space 116224K, 0% used [0x00000007b1d00000,0x00000007b1d00000,0x00000007b8e80000)
to space 116224K, 0% used [0x00000007b8e80000,0x00000007b8e80000,0x00000007c0000000)
ParOldGen total 496128K, used 316905K [0x0000000780000000, 0x000000079e480000, 0x00000007aab00000)
object space 496128K, 63% used [0x0000000780000000,0x000000079357a478,0x000000079e480000)
Metaspace used 2686K, capacity 4486K, committed 4864K, reserved 1056768K
class space used 294K, capacity 386K, committed 512K, reserved 1048576K
在上面的示例中，可以看到沒有配置大小的時候，JVM在啟動的時候會自動設定一個大小，然後觸發full GC以後會自動擴容目前的大小，直到達到最大值，在這個擴容的過程中，會觸發多次FullGC導緻多次的整體的STW，這個就叫性能抖動，為了保證性能穩定降低性能抖動帶來的影響，是以一般預設設定Xms和Xmx為相同的大小。
列印GC記錄檔示例：
java -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xms1g -Xmx1g GCLogAnalysis
操作疑問：
當我選用jdk8的時候，這個指令行執行ok的，但是當我把jdk環境切到11以後會出現如下錯誤：
Unrecognized VM option 'PrintGCDateStamps'
Error: Could not create the Java Virtual Machine.
Error: A fatal exception has occurred. Program will exit.
檢查發現如下：
[0.004s][warning][gc] -XX:+PrintGCDetails is deprecated. Will use -Xlog:gc* instead.
[0.019s][info ][gc,heap] Heap region size: 1M
[0.032s][info ][gc ] Using G1
[0.032s][info ][gc,heap,coops] Heap address: 0x00000007c0000000, size: 1024 MB,
是的在jdk9中已經取消了PrintGCDetails的列印指令，改用Xlog:gc*的方式進行列印，通過通過上面的記錄資訊可以看出來，jdk11預設的GC處理處理器就是G1 GC方式了
接下來看一下詳細的GC日志記錄資訊
[GC (Allocation Failure) [PSYoungGen: 65536K->10741K(76288K)] 65536K->20344K(251392K), 0.0082267 secs] [Times: user=0.01 sys=0.04, real=0.01 secs]
[Full GC (Ergonomics) [PSYoungGen: 12109K->0K(58368K)] [ParOldGen: 164920K->147554K(175104K)] 177030K->147554K(233472K), [Metaspace: 2679K->2679K(1056768K)], 0.0280932 secs] [Times: user=0.15 sys=0.01, real=0.03 secs]
以上分别是PSYongGC和FullGC的兩條記錄，下面用圖示大概說明下對應的資訊
PSYongGC
FullGC
gc的日志詳情和gc的日期參數資訊，JDK8下用預設GC算法列印參考資訊如下：
2021-08-14T12:35:23.733-0800: [GC (Allocation Failure) [PSYoungGen: 262144K->43518K(305664K)] 262144K->75447K(1005056K), 0.0334441 secs] [Times: user=0.04 sys=0.15, real=0.03 secs]
2021-08-14T12:35:23.814-0800: [GC (Allocation Failure) [PSYoungGen: 305662K->43519K(305664K)] 337591K->150441K(1005056K), 0.0591339 secs] [Times: user=0.07 sys=0.30, real=0.06 secs]
2021-08-14T12:35:23.911-0800: [GC (Allocation Failure) [PSYoungGen: 305663K->43508K(305664K)] 412585K->218083K(1005056K), 0.0459681 secs] [Times: user=0.10 sys=0.18, real=0.04 secs]
2021-08-14T12:35:24.007-0800: [GC (Allocation Failure) [PSYoungGen: 305652K->43513K(305664K)] 480227K->290175K(1005056K), 0.0466027 secs] [Times: user=0.09 sys=0.20, real=0.05 secs]
2021-08-14T12:35:24.100-0800: [GC (Allocation Failure) [PSYoungGen: 305657K->43518K(305664K)] 552319K->361546K(1005056K), 0.0423480 secs] [Times: user=0.08 sys=0.18, real=0.04 secs]
2021-08-14T12:35:24.192-0800: [GC (Allocation Failure) [PSYoungGen: 305662K->43519K(160256K)] 623690K->434804K(859648K), 0.0446934 secs] [Times: user=0.09 sys=0.19, real=0.04 secs]
2021-08-14T12:35:24.258-0800: [GC (Allocation Failure) [PSYoungGen: 160255K->72492K(232960K)] 551540K->469214K(932352K), 0.0126632 secs] [Times: user=0.06 sys=0.01, real=0.02 secs]
2021-08-14T12:35:24.293-0800: [GC (Allocation Failure) [PSYoungGen: 189188K->87874K(232960K)] 585910K->493792K(932352K), 0.0181114 secs] [Times: user=0.08 sys=0.02, real=0.02 secs]
2021-08-14T12:35:24.337-0800: [GC (Allocation Failure) [PSYoungGen: 204610K->106146K(232960K)] 610528K->528001K(932352K), 0.0295913 secs] [Times: user=0.13 sys=0.05, real=0.03 secs]
2021-08-14T12:35:24.394-0800: [GC (Allocation Failure) [PSYoungGen: 222882K->76456K(232960K)] 644737K->558662K(932352K), 0.0418105 secs] [Times: user=0.08 sys=0.13, real=0.04 secs]
2021-08-14T12:35:24.463-0800: [GC (Allocation Failure) [PSYoungGen: 193192K->41372K(232960K)] 675398K->591617K(932352K), 0.0508881 secs] [Times: user=0.07 sys=0.18, real=0.05 secs]
2021-08-14T12:35:24.536-0800: [GC (Allocation Failure) [PSYoungGen: 157926K->36011K(232960K)] 708171K->620694K(932352K), 0.0336914 secs] [Times: user=0.06 sys=0.09, real=0.03 secs]
執行結束！共生成對象次數: 8898
Heap
PSYoungGen total 232960K, used 116999K [0x00000007aab00000, 0x00000007c0000000, 0x00000007c0000000)
eden space 116736K, 69% used [0x00000007aab00000,0x00000007afa16ec0,0x00000007b1d00000)
from space 116224K, 30% used [0x00000007b8e80000,0x00000007bb1aadf0,0x00000007c0000000)
to space 116224K, 0% used [0x00000007b1d00000,0x00000007b1d00000,0x00000007b8e80000)
ParOldGen total 699392K, used 584682K [0x0000000780000000, 0x00000007aab00000, 0x00000007aab00000)
object space 699392K, 83% used [0x0000000780000000,0x00000007a3afaa30,0x00000007aab00000)
Metaspace used 2686K, capacity 4486K, committed 4864K, reserved 1056768K
class space used 294K, capacity 386K, committed 512K, reserved 1048576K
GC異常的示例
如上圖：
yong區的大小為532.56m，old區的大小為7.35G，總計堆大小為大概8G。如圖所示，yong區總共發生了481次gc耗時4分31秒平均每次GC的時間是 560ms左右，old區總共發生了118gc耗時31分22秒平均每次gc的時間是16秒，而且如上圖所示每次old區的full GC 基本沒有清空多少時間，這種高耗時低效率的gc處理就是一個嚴重的gc退化情況，此時需要檢查線程運作環境的jvm參數是否需要調整，系統本身是否發生了記憶體洩漏。
GC日志分析第三方工具
1. GCEasy
使用方式，通過浏覽器打開 http://gceasy.io，在頁面上上傳GC的日志檔案
2. GCViewer
使用方式，通過浏覽器搜尋并下載下傳jar包，然後在本地通過指令行運作,
下載下傳位址：https://github.com/chewiebug/gcviewer
參考如下圖：
GC日志解讀分析
幾個常見的GC處理日志資訊和基礎解讀見連結： https://blog.csdn.net/huxingmale/article/details/119700655
以下是我個人的一些總結：
首先jvm的堆記憶體參數隻是一個設定值，實際運作當中目前統計下來是你設定的參數的95%大小，不知道是否和記憶體大小計算有關，一般來說jvm運作大小建議至少256m，設定過小很容易觸發OOM的出現。
低記憶體（256m～以下）
在256m這個大小的堆記憶體下運作jvm，整體來說從GC運作效率來說并行GC>CMSGC>串行GC，每次處理的耗時和觸發FullGC的機率都是非常優秀的，但是從觸發FullGC這點來說不得不說CMSGC特别的強，在256M的堆記憶體環境運作下，它竟然可以一次都不觸發，整體的回收效率非常的優秀，但是因為本身針對老年代的回收上它耗費了更多的cpu資源和時間，是以略遜并行GC一籌。同時，因為并行GC有一個自适應的預設參數，可以通過日志解讀發現，當JVM啟動的時候堆記憶體是最大的251392K，
2021-08-14T14:56:24.102-0800: [GC (Allocation Failure) [PSYoungGen: 65452K->10749K(76288K)] 65452K->24321K(251392K), 0.0098329 secs] [Times: user=0.01 sys=0.05, real=0.01 secs]
但是當運作一段時間後我們會驚訝的發現
2021-08-14T14:56:24.273-0800: [GC (Allocation Failure) [PSYoungGen: 76055K->10742K(40448K)] 178632K->137696K(215552K), 0.0147039 secs] [Times: user=0.03 sys=0.05, real=0.01 secs]
沒錯，總記憶體變小了，這裡是因為自适應參數的存在，GC的過程中并行算法會根據運作情況自動配置設定年輕代中的eden區和緩沖區的大小比例，如下：
2021-08-14T14:56:24.293-0800: [GC (Allocation Failure) [PSYoungGen: 40298K->17295K(58368K)] 167252K->147144K(233472K), 0.0028745 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
2021-08-14T14:56:24.300-0800: [GC (Allocation Failure) [PSYoungGen: 46991K->26339K(58368K)] 176840K->159304K(233472K), 0.0067433 secs] [Times: user=0.03 sys=0.01, real=0.00 secs]
在執行幾次以後，jvm認為這個大小的比例是目前合理穩定的，于是儲存下來。為了驗證我這個想法，我在執行參數中加入了關閉自适應參數-XX:-UseAdaptiveSizePolicy ，于是符合預期想法，jvm運作過程中堆記憶體的整體大小不在變化。
具體差別如下圖：
未關閉自适應參數前：
Heap
PSYoungGen total 58368K, used 29202K [0x00000007bab00000, 0x00000007c0000000, 0x00000007c0000000)
eden space 29696K, 98% used [0x00000007bab00000,0x00000007bc784ab8,0x00000007bc800000)
from space 28672K, 0% used [0x00000007be400000,0x00000007be400000,0x00000007c0000000)
to space 28672K, 0% used [0x00000007bc800000,0x00000007bc800000,0x00000007be400000)
ParOldGen total 175104K, used 174912K [0x00000007b0000000, 0x00000007bab00000, 0x00000007bab00000)
object space 175104K, 99% used [0x00000007b0000000,0x00000007baad00e8,0x00000007bab00000)
Metaspace used 2686K, capacity 4486K, committed 4864K, reserved 1056768K
class space used 294K, capacity 386K, committed 512K, reserved 1048576K
關閉自适應參數後：
Heap
PSYoungGen total 76288K, used 62646K [0x00000007bab00000, 0x00000007c0000000, 0x00000007c0000000)
eden space 65536K, 95% used [0x00000007bab00000,0x00000007be82db48,0x00000007beb00000)
from space 10752K, 0% used [0x00000007beb00000,0x00000007beb00000,0x00000007bf580000)
to space 10752K, 0% used [0x00000007bf580000,0x00000007bf580000,0x00000007c0000000)
ParOldGen total 175104K, used 174706K [0x00000007b0000000, 0x00000007bab00000, 0x00000007bab00000)
object space 175104K, 99% used [0x00000007b0000000,0x00000007baa9c898,0x00000007bab00000)
Metaspace used 2686K, capacity 4486K, committed 4864K, reserved 1056768K
class space used 294K, capacity 386K, committed 512K, reserved 1048576K
第一次GC的時候
2021-08-14T16:31:58.330-0800: [GC (Allocation Failure) [PSYoungGen: 65536K->10749K(76288K)] 65536K->21765K(251392K), 0.0099438 secs] [Times: user=0.01 sys=0.05, real=0.01 secs]
中記憶體（512m-1g）
在這個堆記憶體閥值下，串行GC首先被排除，運作效率低，GC暫停時間長。由于G1GC在256M下直接就會OOM，是以起步就用了512M，在這個環境下個人感覺從現在開始G1GC的效率開始碾壓其他幾個GC了，如果說G1GC有什麼缺點的話，可能就是它的詳細GC日志比較難以解讀，從純日志層面上不如并行GC和CMSGC好解讀。
并行GC有着優秀的吞吐量和處理效率，但是GC的次數較多STW比較多，JVM的穩定性略差，CMSGC性能穩定GC次數少，但是并發銷量和吞吐量略低，是以如果是追求高并發實時響應的系統考慮選擇并行GC，最大程度的實作高響應和高吞吐；追求性能穩定的系統可以選擇CMSGC，在保持系統高效處理的同時保證足夠的性能穩定性。G1的話雖然性能非常優越，但是在這個層級上性能提升不是特别的大，日志又比較難以解讀和監控，考慮到維護成本的業務場景下，個人覺的還是優先考慮CMS GC。
大記憶體（2G～以上）
一般的java服務jvm運作記憶體其實不需要這麼高，如果需要開到這麼高的堆記憶體閥值的情況下，這個服務一般有以下特性：1. 高吞吐 2. 高并發，是以在這個層面上考慮的性能的最優化，G1GC我覺的最好的垃圾回收算法。