（乾貨篇）GC日誌逐行分析+關鍵性能優化參數分析
前言
最近遇到幾個系統 young gc 時間比較長，在 young gc 長的同時，系統負載也隨時升高，所以熟讀GC日誌以及瞭解一些Jvm常見調優是必要的。html
收穫
看完應該有以下收穫linux
- 熟悉young GC日誌每一行啥意思（會看）。
- 瞭解一些關鍵GC調優參數（採坑）。
日誌分析
// GC緣由，新生代minor GC。
2019-11-09T10:14:42.496+0800: 143830.361: [GC pause (G1 Evacuation Pause) (young)
//survivor大小及對象年齡最大值是15
Desired survivor size 67108864 bytes, new threshold 15 (max 15).
- age 1: 21372336 bytes, 21372336 total
- age 2: 5495736 bytes, 26868072 total
- age 3: 30424 bytes, 26898496 total
- age 4: 116344 bytes, 27014840 total
- age 5: 22704 bytes, 27037544 total
- age 6: 81712 bytes, 27119256 total
- age 7: 17824 bytes, 27137080 total
- age 8: 172736 bytes, 27309816 total
- age 9: 348672 bytes, 27658488 total
- age 10: 361192 bytes, 28019680 total
- age 11: 153648 bytes, 28173328 total
- age 12: 37056 bytes, 28210384 total
- age 13: 81800 bytes, 28292184 total
- age 14: 6272 bytes, 28298456 total
- age 15: 31096 bytes, 28329552 total
// 發生minor GC和full GC時，全部相關region都是要回收的。而發生併發GC時，會根據目標停頓時間動態選擇部分垃圾對並多的Region回收，這一步就是選擇Region。
// pending_cards是關於RSet的Card Table。
// predicted base time是預測的掃描card table時間。
143830.362: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 13047, predicted base time: 104.33 ms, remaining time: 0.00 ms, target pause time: 100.00 ms]
// 這一步是添加Region到collection set，新生代一共496個Region，16個倖存區Region，預計收集時間是3.45 ms。
143830.362: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 496 regions, survivors: 16 regions, predicted young region time: 3.45 ms]
// 這一步是對上面兩步的總結。預計總收集時間107.78ms。
143830.362: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 496 regions, survivors: 16 regions, old: 0 regions, predicted pause time: 107.78 ms, target pause time: 100.00 ms]
//
2019-11-09T10:14:42.611+0800: 143830.477: [SoftReference, 0 refs, 0.0136201 secs]2019-11-09T10:14:42.625+0800: 143830.490: [WeakReference, 2 refs, 0.0165891 secs]2019-11-09T10:14:42.641+0800: 143830.507: [FinalReference, 609 refs, 0.0244947 secs]2019-11-09T10:14:42.666+0800: 143830.531: [PhantomReference, 1 refs, 331 refs, 0.0342801 secs]2019-11-09T10:14:42.700+0800: 143830.566: [JNI Weak Reference, 0.0000451 secs], 0.2087493 secs]
// Parallel Time: 並行收集任務在運行過程當中引起的STW（Stop The World）時間，重新生代垃圾收集開始到最後一個任務結束，共花費93.6ms
// GC Workers: 有28個線程負責垃圾收集，經過參數-XX:ParallelGCThreads設置，這個參數的值的設置，跟CPU有關，默認值 ParallelGCThreads＝8+( Processor - 8 ) ( 5/8 )，好比40核心的機器，那麼GC線程數就是28。
[Parallel Time: 93.6 ms, GC Workers: 28]
// 第一個垃圾收集線程開始工做時JVM啓動後通過的時間（min）；最後一個垃圾收集線程開始工做時JVM啓動後通過的時間（max）；diff表示min和max之間的差值。理想狀況下，你但願他們幾乎是同時開始，即diff趨近於0。
[GC Worker Start (ms): Min: 143830362.2, Avg: 143830362.7, Max: 143830363.5, Diff: 1.4]
// 掃描root集合（線程棧、JNI、全局變量、系統表等等）花費的時間，掃描root集合是垃圾收集的起點，嘗試找到是否有root集合中的節點指向當前的收集集合（CSet）
[Ext Root Scanning (ms): Min: 2.3, Avg: 8.2, Max: 16.0, Diff: 13.6, Sum: 229.4]
// 每一個分區都有本身的RSet，用來記錄其餘分區指向當前分區的指針，若是RSet有更新，G1中會有一個post-write barrier管理跨分區的引用——新的被引用的card會被標記爲dirty，並放入一個日誌緩衝區，若是這個日誌緩衝區滿了會被加入到一個全局的緩衝區，在JVM運行的過程當中還有線程在併發處理這個全局日誌緩衝區的dirty card。Update RS表示容許垃圾收集線程處理本次垃圾收集開始前沒有處理好的日誌緩衝區，這能夠確保當前分區的RSet是最新的。
[Update RS (ms): Min: 0.0, Avg: 1.4, Max: 4.0, Diff: 4.0, Sum: 39.4]
// Processed Buffers，這表示在Update RS這個過程當中處理多少個日誌緩衝區。
[Processed Buffers: Min: 0, Avg: 17.0, Max: 67, Diff: 67, Sum: 475]
//掃描每一個新生代分區的RSet，找出有多少指向當前分區的引用來自CSet。
[Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 1.6]
// 掃描代碼中的root節點（局部變量）花費的時間
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
//在疏散暫停期間，全部在CSet中的分區必須被轉移疏散，Object Copy就負責將當前分區中存活的對象拷貝到新的分區。
[Object Copy (ms): Min: 0.0, Avg: 7.6, Max: 85.5, Diff: 85.4, Sum: 212.1]
//當一個垃圾收集線程完成任務時，它就會進入一個臨界區，並嘗試幫助其餘垃圾線程完成任務（steal outstanding tasks），min表示該垃圾收集線程何時嘗試terminatie，max表示該垃圾收集回收線程何時真正terminated。
[Termination (ms): Min: 0.0, Avg: 75.2, Max: 79.0, Diff: 79.0, Sum: 2106.8]
// 若是一個垃圾收集線程成功盜取了其餘線程的任務，那麼它會再次盜取更多的任務或再次嘗試terminate，每次從新terminate的時候，這個數值就會增長
[Termination Attempts: Min: 1, Avg: 1.4, Max: 2, Diff: 1, Sum: 39]
// 垃圾收集線程在完成其餘任務的時間
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 1.0]
// 展現每一個垃圾收集線程的最小、最大、平均、差值和總共時間
[GC Worker Total (ms): Min: 91.6, Avg: 92.5, Max: 93.3, Diff: 1.7, Sum: 2590.3]
// GC Worker End：min表示最先結束的垃圾收集線程結束時該JVM啓動後的時間；max表示最晚結束的垃圾收集線程結束時該JVM啓動後的時間。理想狀況下，你但願它們快速結束，而且最好是同一時間結束。
[GC Worker End (ms): Min: 143830455.1, Avg: 143830455.2, Max: 143830455.5, Diff: 0.4]
// 新生代GC中的一些任務
[Code Root Fixup: 0.1 ms] //釋放用於管理並行垃圾收集活動的數據結構，應該接近於0，該步驟是線性執行的；
[Code Root Purge: 0.0 ms] //清理更多的數據結構，應該很快，耗時接近於0，也是線性執行
[Clear CT: 0.5 ms] //清理card table
//一些其餘的拓展功能
[Other: 114.6 ms]
[Choose CSet: 0.0 ms] //選擇要進行回收的分區放入CSet（G1選擇的標準是垃圾最多的分區優先，也就是存活對象率最低的分區優先）
[Ref Proc: 109.9 ms] // 處理Java中的各類引用——soft、weak、final、phantom、JNI等等。
[Ref Enq: 0.6 ms] // 遍歷全部的引用，將不能回收的放入pending列表
[Redirty Cards: 0.4 ms] //在回收過程當中被修改的card將會被重置爲dirty
[Humongous Register: 0.1 ms]// JDK8u60提供了一個特性，巨型對象能夠在新生代收集的時候被回收——經過G1ReclaimDeadHumongousObjectsAtYoungGC設置，默認爲true。
[Humongous Reclaim: 0.0 ms] //作下列任務的時間：確保巨型對象能夠被回收、釋放該巨型對象所佔的分區，重置分區類型，並將分區還到free列表，而且更新空閒空間大小。
[Free CSet: 0.9 ms]// 將要釋放的分區還回到free列表。
// 展現了不一樣代的大小變化，以及堆大小的自適應調整
// Eden: 992.0M(992.0M)->0.0B(982.0M)
（1）當前新生代收集觸發的緣由是Eden空間滿了，分配了992M，使用了992M；
（2）全部的Eden分區都被疏散處理了，在新生代結束後Eden分區的使用大小成爲了0.0B；
（3）Eden分區的大小縮小爲982.0M；
// Survivors: 32.0M->42.0M：因爲年輕代分區的回收處理，survivor的空間從32.0M漲到42.0M；
// Heap: 2304.3M(4096.0M)->1322.8M(4096.0M)]
（1）在本次垃圾收集活動開始的時候，堆空間總體使用量是2304.3M，堆空間的最大值是4096.0M；
（2）在本次垃圾收集結束後，堆空間的使用量是1322.8M，最大值保持不變。
[Eden: 992.0M(992.0M)->0.0B(982.0M) Survivors: 32.0M->42.0M Heap: 2304.3M(4096.0M)->1322.8M(4096.0M)]
// 本次新生代垃圾收集的時間
// user=2.81 ：垃圾收集線程在新生代垃圾收集過程當中消耗的CPU時間，這個時間跟垃圾收集線程的個數有關，可能會比real time大不少；
// sys=0.17 ：內核態線程消耗的CPU時間
// real=0.21：本次垃圾收集真正消耗的時間；
[Times: user=2.81 sys=0.17, real=0.21 secs]
2019-11-09T10:14:42.705+0800: 143830.570: Total time for which application threads were stopped: 0.2183659 seconds, Stopping threads took: 0.0012684 seconds
// 當GC發生時，每一個線程只有進入了SafePoint纔算是真正掛起，也就是真正的停頓，這個日誌的含義是整個GC過程當中STW的時間，配置了-XX:+PrintGCApplicationStoppedTime這個參數纔會打印這個信息。
// 重點：第一個0.0091676 seconds 是JVM啓動後的秒數，第二個 0.0007286 seconds是JVM發起STW的開始到結束的時間。特別地，若是是GC引起的STW，這條內容會緊挨着出如今GC log的下面。
// 這裏想搞清楚？ 請移步： https://juejin.im/post/5dc910586fb9a04a95289f28
2019-11-09T10:14:42.795+0800: 143830.660: Total time for which application threads were stopped: 0.0091676 seconds, Stopping threads took: 0.0007286 seconds
複製代碼
關鍵參數調優
注意： 下面都是簡單介紹，想深刻每個參數須要一個小時的學習。算法
-XX:-UseBiasedLocking
JDK1.6開始默認打開的偏向鎖，會嘗試把鎖賦給第一個訪問它的線程，取消同步塊上的synchronized原語。若是始終只有一條線程在訪問它，就成功略過同步操做以得到性能提高。但一旦有第二條線程訪問這把鎖，JVM就要撤銷偏向鎖恢復到未鎖定線程的狀態，若是打開安全點日誌，能夠看到很多RevokeBiasd的紀錄，像GC同樣Stop The World的幹活，雖然只是很短的停頓，但對於多線程併發的應用，取消掉它反而有性能的提高，因此建議在系統出現瓶頸的時候，作去偏向鎖優化。緩存
-XX:AutoBoxCacheMax
Integer i=3;這語句有着 int自動裝箱成Integer的過程，JDK默認只緩存 -128 ~ +127的Integer 和 Long，超出範圍的數字就要即時構建新的Integer對象。高併發的狀況下，拆箱裝箱的性能損耗不可忽略，所以建議調大這個配置，好比2w。安全
-XX:ParallelGCThreads
因爲GC操做會暫停全部的應用程序線程，JVM爲了儘可能縮短停頓時間就必須儘量地利用更多的CPU資源。這意味着，默認狀況下，JVM會在機器的每一個CPU上運行一個線程，最多同時運行8個。數據結構
一旦達到這個上限，JVM會調整算法，每超出5/8個CPU啓動一個新的線程。因此總的線程數就是（這裏的N表明CPU的核心數）： ParallelGCThreads = 8 + ((N - 8) * 5/8)多線程
有時候使用這個算法估算出來的線程數目會偏大。若是應用程序使用一個較小的堆（譬如大小爲1 GB）運行在一個八顆CPU的機器上，使用4個線程或者6個線程處理這個堆可能會更高效。在一個128顆CPU的機器上，啓動83個垃圾收集線程可能也太多了，除非系統使用的堆已經達到了最大上限。併發
-XX:+HeapDumpOnOutOfMemoryError
在Out Of Memory，JVM快死掉的時候，輸出Heap Dump到指定文件，但在容器環境（或者混部）下，在普通硬盤上會形成20秒以上的硬盤IO跑滿，也是個十足的惡鄰，影響了同一宿主機上全部其餘的服務。app
-XX:MetaspaceSize=128m -XX:MaxMetaspaceSize=512m
擴容會致使停頓，對下游影響比較大，以前support踩過這個坑，必定要觀察metaspace的大小，不夠了就趕忙調整。異步
-XX:+PrintGCApplicationStoppedTime
GC時間不長，可是下游頻繁超時，這種就有可能不是gc形成的停頓了，非GC致使的停頓，好比取消偏向鎖，code deoptimization等等，打開-XX:+PrintGCApplicationStoppedTime這個參數
注意：安全點日誌不能一直打開：
- 安全點日誌默認輸出到stdout，一是stdout日誌的整潔性，二是stdout所重定向的文件若是不在/dev/shm，可能被鎖。
- 對於一些很短的停頓，好比取消偏向鎖，打印的消耗比停頓自己還大。
- 安全點日誌是在安全點內打印的，自己加大了安全點的停頓時間。
因此安全日誌應該只在問題排查時打開。 若是在生產系統上要打開，再再增長下面四個參數： -XX:+UnlockDiagnosticVMOptions -XX: -DisplayVMOutput -XX:+LogVMOutput -XX:LogFile=/dev/shm/vm.log 打開Diagnostic（只是開放了更多的flag可選，不會主動激活某個flag），關掉輸出VM日誌到stdout，輸出到獨立文件,/dev/shm目錄（內存文件系統）。
-XX:+PerfDisableSharedMem
項目中的日誌異步寫了，當磁盤IO高的時候，服務日誌會丟棄，那麼你有沒有想到GC日誌的寫入會不會影響JVM的性能呢，會不會對GC時間形成影響呢，答案是確定的，當磁盤IO高，且正在刷page cache，這個時候就有可能形成停頓。
重點關注：real時間是否是超長，正常real時間要遠遠小於user時間（大概十分之一），當前系統是否是正在flush pageCache 到磁盤，當符合這兩種狀況的時候就及有多是IO影響的。
-Xss
-Xss256k：在堆以外，線程佔用棧內存，默認每條線程爲1M。存放方法調用出參入參的棧、局部變量、標量替換後的局部變量等，有人喜歡設小點節約內存開更多線程。但內存夠也就沒必要要設小，有人喜歡再設大點，特別是有JSON解析之類的遞歸調用時不能設過小。
-XX:ReservedCodeCacheSize
JIT編譯後二進制代碼的存放區，滿了以後就再也不編譯，默認245m。當codeCache滿了，程序將會出現明顯的卡頓，服務能力降低，此時JVM會打印出一條警告消息，並切換到interpreted-only 模式：JIT編譯器被停用，字節碼將再也不會被編譯成機器碼。所以，應用程序將繼續運行，但運行速度會下降一個數量級，直到有人注意到這個問題。
// 當服務極度卡頓，能夠懷疑這裏，能夠經過反證法驗證是否出現過這個日誌，來確認是否是這個問題
`Java HotSpot(TM) 64-Bit Server VM warning: CodeCache is full. Compiler has been disabled`
複製代碼
-XX:+AlwaysPreTouch
JAVA進程啓動的時候，雖然咱們能夠爲JVM指定合適的內存大小，可是這些內存操做系統並無真正的分配給JVM，而是等JVM訪問這些內存的時候，才真正分配，這樣會形成如下問題。
- GC的時候,新生代的對象要晉升到老年代的時候,須要內存,這個時候操做系統才真正分配內存,這樣就會加大young gc的停頓時間。
- 可能存在內存碎片的問題。
所以能夠考慮開啓這個參數，服務啓動直接開闢這些內存，配置這個參數須要看實際狀況，必須保證不出現overcommit的狀況，保證有足夠的實際內存能夠分配給每個服務，例子：R大-AlwaysPreTouch
Memory Overcommit的意思是操做系統承諾給進程的內存大小超過了實際可用的內存, 詳細分析:Linux overcommit
-XX:+UseStringDeduplication
JVM去重, 能夠節省JVM的空間, 可是有可能增長GC的時間.
開啓String去重XX:+UseStringDeduplication的利與弊 \ 聊聊G1 GC的String Deduplication
-XX:+ParallelRefProcEnabled
並行的處理Reference對象，如WeakReference，默認爲false，除非在GC log裏出現Reference處理時間較長的日誌，不然效果不會很明顯，但咱們老是要JVM儘可能的並行，因此設了也就設了。同理還有-XX:+CMSParallelInitialMarkEnabled，JDK8已默認開啓，但小版本比較低的JDK7甚至不支持。
未完待續。。。
- 1. （乾貨篇）GC日誌逐行分析+關鍵性能優化參數分析
- 2. 性能優化-可視化GC日誌分析工具
- 3. JVM GC日誌分析及性能優化
- 4. java性能優化 –gc日誌收集與分析
- 5. GC日誌分析
- 6. GC 日誌分析
- 7. gc日誌分析
- 8. GC--日誌分析
- 9. JVm性能調優4：GC日誌分析
- 10. jvm調優（8）GC日誌分析
- 更多相關文章...
- • 互聯網系統應用架構基礎分析 - 紅包項目實戰
- • 高併發系統的分析和設計 - 紅包項目實戰
- • 互聯網組織的未來：剖析GitHub員工的任性之源
- • 再有人問你分佈式事務，把這篇扔給他
-
每一个你不满意的现在，都有一个你没有努力的曾经。
- 1. （乾貨篇）GC日誌逐行分析+關鍵性能優化參數分析
- 2. 性能優化-可視化GC日誌分析工具
- 3. JVM GC日誌分析及性能優化
- 4. java性能優化 –gc日誌收集與分析
- 5. GC日誌分析
- 6. GC 日誌分析
- 7. gc日誌分析
- 8. GC--日誌分析
- 9. JVm性能調優4：GC日誌分析
- 10. jvm調優（8）GC日誌分析