2. 程式人生 > >JVM層GC調優（下）

JVM層GC調優（下）

阿新 • • 發佈：2018-07-26
日誌分析工具 f11 hub xpl aec 發現 gen sta abc

GC日誌格式

本文是 JVM層GC調優（上） 的後續，在上一篇文章中，我們介紹了JVM的內存結構、常見的垃圾回收算法以及垃圾收集器和不同收集器中的一些GC調優參數。所以通過上文，我們也對GC相關的內容有了一定的了解。

但是光知道一些調優參數是沒用的，我們需要能夠從GC的日誌中去分析可以調優的地方，這樣才能使用這些參數去進行相應的調整，所以本小節將介紹一下不同收集器的GC日誌格式。

我們這裏以Tomcat為例，首先需要在Tomcat的catalina.sh腳本文件中加入打印GC日誌的相關參數，如下：

[root@01server ~]# vim /usr/local/tomcat-8.5.32/bin/catalina.sh
JAVA_OPTS="$JAVA_OPTS -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -Xloggc:$CATALINA_HOME/logs/gc.log -XX:+PrintHeapAtGC -XX:+PrintTenuringDistribution"
[root@01server ~]# shutdown.sh  # 重啟Tomcat
...
[root@01server ~]# startup.sh 
...
[root@01server ~]# ls /usr/local/tomcat-8.5.32/logs/ |grep gc.log  # 有生成gc.log這個文件代表成功
gc.log
[root@01server ~]#

參數說明：

  • -XX:+PrintGCDetails 打印GC的詳細信息
  • -XX:+PrintGCTimeStamps、-XX:+PrintGCDateStamps 打印GC的時間
  • -Xloggc:$CATALINA_HOME/logs/gc.log 指定GC日誌文件所存放的路徑
  • -XX:+PrintHeapAtGC 在GC發生的前後打印堆信息
  • -XX:+PrintTenuringDistribution 打印對象的年齡信息

默認情況下，JDK1.8使用的是Parallel GC，以下是我們設置了參數後，所輸出的日誌格式片段如下：

{Heap before GC invocations=1 (full 0):  # GC發生前的堆信息
 PSYoungGen      total 4608K, used 4088K [0x00000000fad00000, 0x00000000fb200000, 0x0000000100000000)
  eden space 4096K, 99% used [0x00000000fad00000,0x00000000fb0fe340,0x00000000fb100000)
  from space 512K, 0% used [0x00000000fb180000,0x00000000fb180000,0x00000000fb200000)
  to   space 512K, 0% used [0x00000000fb100000,0x00000000fb100000,0x00000000fb180000)
 ParOldGen       total 11264K, used 0K [0x00000000f0600000, 0x00000000f1100000, 0x00000000fad00000)
  object space 11264K, 0% used [0x00000000f0600000,0x00000000f0600000,0x00000000f1100000)
 Metaspace       used 5773K, capacity 5904K, committed 6144K, reserved 1056768K
  class space    used 646K, capacity 696K, committed 768K, reserved 1048576K
# GC的詳細信息
2018-07-25T21:07:10.876+0800: 0.293: [GC (Allocation Failure)
Desired survivor size 524288 bytes, new threshold 7 (max 15)
[PSYoungGen: 4088K->496K(4608K)] 4088K->1599K(15872K), 0.0045483 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
Heap after GC invocations=1 (full 0):  # GC發生後的堆信息
 PSYoungGen      total 4608K, used 496K [0x00000000fad00000, 0x00000000fb600000, 0x0000000100000000)
  eden space 4096K, 0% used [0x00000000fad00000,0x00000000fad00000,0x00000000fb100000)
  from space 512K, 96% used [0x00000000fb100000,0x00000000fb17c010,0x00000000fb180000)
  to   space 512K, 0% used [0x00000000fb580000,0x00000000fb580000,0x00000000fb600000)
 ParOldGen       total 11264K, used 1103K [0x00000000f0600000, 0x00000000f1100000, 0x00000000fad00000)
  object space 11264K, 9% used [0x00000000f0600000,0x00000000f0713ce0,0x00000000f1100000)
 Metaspace       used 5773K, capacity 5904K, committed 6144K, reserved 1056768K
  class space    used 646K, capacity 696K, committed 768K, reserved 1048576K
}

註：如果默認不是使用Parallel GC的話，可以加上這個參數啟用：-XX:+UseParallelGC

我們主要關註GC的詳細信息，所以我就截取這一部分進行一個簡單的說明：

2018-07-25T21:07:10.876+0800: 0.293:  # GC發生的時間
[GC (Allocation Failure)  # 觸發GC的原因
Desired survivor size 524288 bytes,  # 期望存活對象的大小為524288字節
new threshold 7 (max 15)  # 存活的對象年齡為7，最大值為15，表示年齡大於15歲則會晉升到老年代
[PSYoungGen:  # GC發生的區域，可以看到這裏是Young區
4088K->496K(4608K)]  # GC後的Young區內存占用大小從4088K減小到了496K，括號裏的4608K是Young區的總大小
4088K->1599K(15872K), # GC後堆的內存占用大小從4088K減小到了1599K，括號裏的15872K是堆的總大小
0.0045483 secs]  # 本次GC總耗費的時間，單位為秒
[Times: user=0.01 sys=0.00, real=0.00 secs]  # 本次GC所耗費的時間的統計信息，user是用戶態耗費的時間，sys是內核態耗費的時間，real是整個過程實際花費的時間。單位為秒

知道了如何去查看Parallel GC的日誌格式後，我們再來看看CMS GC的日誌格式。同樣的，到catalina.sh中配置啟用CMS GC，如下示例：

[root@01server ~]# vim /usr/local/tomcat-8.5.32/bin/catalina.sh
JAVA_OPTS="$JAVA_OPTS -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -Xloggc:$CATALINA_HOME/logs/gc.log -XX:+PrintHeapAtGC -XX:+PrintTenuringDistribution -XX:+UseConcMarkSweepGC"
[root@01server ~]# shutdown.sh  # 重啟Tomcat
...
[root@01server ~]# startup.sh 
...
[root@01server ~]#

啟用CMS GC後，所輸出的日誌格式片段如下：

{Heap before GC invocations=0 (full 0):  # GC發生前的堆信息
 par new generation   total 4928K, used 4416K [0x00000000f0600000, 0x00000000f0b50000, 0x00000000f58a0000)
  eden space 4416K, 100% used [0x00000000f0600000, 0x00000000f0a50000, 0x00000000f0a50000)
  from space 512K,   0% used [0x00000000f0a50000, 0x00000000f0a50000, 0x00000000f0ad0000)
  to   space 512K,   0% used [0x00000000f0ad0000, 0x00000000f0ad0000, 0x00000000f0b50000)
 concurrent mark-sweep generation total 10944K, used 0K [0x00000000f58a0000, 0x00000000f6350000, 0x0000000100000000)
 Metaspace       used 5828K, capacity 5968K, committed 6144K, reserved 1056768K
  class space    used 655K, capacity 696K, committed 768K, reserved 1048576K
# GC的詳細信息
2018-07-26T10:13:12.984+0800: 0.296: [GC (Allocation Failure) 2018-07-26T10:13:12.985+0800: 0.296: [ParNew
Desired survivor size 262144 bytes, new threshold 1 (max 6)
- age   1:     521072 bytes,     521072 total
: 4416K->512K(4928K), 0.0082787 secs] 4416K->1598K(15872K), 0.0083763 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
Heap after GC invocations=1 (full 0):  # GC發生後的堆信息
 par new generation   total 4928K, used 512K [0x00000000f0600000, 0x00000000f0b50000, 0x00000000f58a0000)
  eden space 4416K,   0% used [0x00000000f0600000, 0x00000000f0600000, 0x00000000f0a50000)
  from space 512K, 100% used [0x00000000f0ad0000, 0x00000000f0b50000, 0x00000000f0b50000)
  to   space 512K,   0% used [0x00000000f0a50000, 0x00000000f0a50000, 0x00000000f0ad0000)
 concurrent mark-sweep generation total 10944K, used 1086K [0x00000000f58a0000, 0x00000000f6350000, 0x0000000100000000)
 Metaspace       used 5828K, capacity 5968K, committed 6144K, reserved 1056768K
  class space    used 655K, capacity 696K, committed 768K, reserved 1048576K
}
# 老年代GC的詳細信息
2018-07-26T10:13:14.275+0800: 1.586: [GC (CMS Initial Mark) [1 CMS-initial-mark: 6375K(10944K)] 7541K(15872K), 0.0017697 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2018-07-26T10:13:14.277+0800: 1.588: [CMS-concurrent-mark-start]
2018-07-26T10:13:14.288+0800: 1.599: [CMS-concurrent-mark: 0.011/0.011 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
2018-07-26T10:13:14.288+0800: 1.599: [CMS-concurrent-preclean-start]
2018-07-26T10:13:14.288+0800: 1.599: [CMS-concurrent-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2018-07-26T10:13:14.303+0800: 1.614: [GC (CMS Final Remark) [YG occupancy: 1645 K (4928 K)]2018-07-26T10:13:14.303+0800: 1.614: [Rescan (parallel) , 0.0018194 secs]2018-07-26T10:13:14.304+0800: 1.616: [weak refs processing, 0.0002306 secs]2018-07-26T10:13:14.305+0800: 1.616: [class unloading, 0.0019443 secs]2018-07-26T10:13:14.307+0800: 1.618: [scrub symbol table, 0.0011837 secs]2018-07-26T10:13:14.308+0800: 1.619: [scrub string table, 0.0003768 secs][1 CMS-remark: 6375K(10944K)] 8020K(15872K), 0.0058148 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2018-07-26T10:13:14.316+0800: 1.628: [CMS-concurrent-sweep-start]
2018-07-26T10:13:14.318+0800: 1.630: [CMS-concurrent-sweep: 0.002/0.002 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2018-07-26T10:13:14.318+0800: 1.630: [CMS-concurrent-reset-start]
2018-07-26T10:13:14.319+0800: 1.631: [CMS-concurrent-reset: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

同樣的，我們主要關註GC的詳細信息，所以我就截取這一部分進行一個簡單的說明：

2018-07-26T10:13:12.984+0800: 0.296:  # GC發生的時間
[GC (Allocation Failure) # 觸發GC的原因，只是GC的話就表示的是Young GC，Full GC會顯示為Full GC
2018-07-26T10:13:12.985+0800: 0.296:  # GC發生的時間
[ParNew  # 搭配的年輕代收集器為ParNew，因為CMS是老年代的收集器
Desired survivor size 262144 bytes,  # 期望存活對象的大小為262144字節
new threshold 1 (max 6)  # 存活的對象年齡為1，最大值為6，表示年齡大於6歲則會晉升到老年代
- age   1:   # 當前存活對象的年齡  
521072 bytes,     521072 total  # 存活對象所占的Young區內存大小，單位為字節
: 4416K->512K(4928K),  # GC後的Young區內存占用大小從4416K減小到了512K，括號裏的4928K是Young區的總大小
0.0082787 secs] # 本次Yong GC所耗費的時間，單位為秒
4416K->1598K(15872K),  # GC後堆的內存占用大小從4416K減小到了1598K，括號裏的15872K是堆的總大小
0.0083763 secs] # 本次GC總耗費的時間，單位為秒
[Times: user=0.00 sys=0.00, real=0.01 secs] # 本次GC所耗費的時間的統計信息，user是用戶態耗費的時間，sys是內核態耗費的時間，real是整個過程實際花費的時間。單位為秒

然後還有老年代的GC信息，以下這個片段是CMS GC特有的日誌信息格式，也就是完整的一次Full GC過程：

2018-07-26T10:13:14.275+0800: 1.586: # 標記開始的時間
[GC (CMS Initial Mark) [1 CMS-initial-mark:  # 表示初始化標記
6375K(10944K)] # 初始化標記後Old區的內存占用大小為6375K，括號裏的10944K是Old區的總大小
7541K(15872K),  # 初始化標記後堆的內存占用大小為7541K，括號裏的15872K是堆的總大小 
0.0017697 secs] # 本次初始化標記所耗時
[Times: user=0.00 sys=0.00, real=0.00 secs] # 之前已介紹過了，不再贅述

2018-07-26T10:13:14.277+0800: 1.588: [CMS-concurrent-mark-start] # 開始並發標記

2018-07-26T10:13:14.288+0800: 1.599: [CMS-concurrent-mark: 0.011/0.011 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] # 並發標記結束，以及本次並發標記所耗時

2018-07-26T10:13:14.288+0800: 1.599: [CMS-concurrent-preclean-start]  # 開始標記預清理

2018-07-26T10:13:14.288+0800: 1.599: [CMS-concurrent-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] # 標記預清理結束，以及本次標記預清理所耗時

2018-07-26T10:13:14.303+0800: 1.614: [GC (CMS Final Remark)  # 收集階段，這個階段會標記老年代全部的存活對象，包括那些在並發標記階段更改的或者新創建的引用對象
[YG occupancy: 1645 K (4928 K)] # young區當前占用為1645K，括號裏的4928k是young區的總大小 
2018-07-26T10:13:14.303+0800: 1.614: [Rescan (parallel) , 0.0018194 secs]  # 在應用停止的階段完成存活對象的標記工作，以及耗時
2018-07-26T10:13:14.304+0800: 1.616: [weak refs processing, 0.0002306 secs] # 弱引用處理，以及耗時
2018-07-26T10:13:14.305+0800: 1.616: [class unloading, 0.0019443 secs]  # 類卸載，以及耗時
2018-07-26T10:13:14.307+0800: 1.618: [scrub symbol table, 0.0011837 secs] # 清理符號表，以及耗時
2018-07-26T10:13:14.308+0800: 1.619: [scrub string table, 0.0003768 secs] # 清理字符串表，以及耗時
[1 CMS-remark: 6375K(10944K)] # remark後Old區的內存占用大小為6375K，括號裏的10944K是Old區的總大小
8020K(15872K), # remark後堆的內存占用大小為8020K，括號裏的15872K是堆的總大小 
0.0058148 secs] # 本次remark所耗時
[Times: user=0.00 sys=0.00, real=0.00 secs]  # 之前已介紹過了，不再贅述

2018-07-26T10:13:14.316+0800: 1.628: [CMS-concurrent-sweep-start] # 開始清理標記

2018-07-26T10:13:14.318+0800: 1.630: [CMS-concurrent-sweep: 0.002/0.002 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] # 清理標記結束，以及本次清理標記所耗時

2018-07-26T10:13:14.318+0800: 1.630: [CMS-concurrent-reset-start]  # 開始重置標記

2018-07-26T10:13:14.319+0800: 1.631: [CMS-concurrent-reset: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] # 重置標記結束，以及本次重置標記所耗時

接下來就是G1的日誌格式，G1在JDK1.8後被廣泛使用，所以是需要好好了解一下它的日誌格式的。同樣的，需要先到catalina.sh中配置啟用G1，如下示例：

[root@01server ~]# vim /usr/local/tomcat-8.5.32/bin/catalina.sh
JAVA_OPTS="$JAVA_OPTS -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -Xloggc:$CATALINA_HOME/logs/gc.log -XX:+PrintHeapAtGC -XX:+PrintTenuringDistribution -XX:+UseG1GC"
[root@01server ~]# shutdown.sh  # 重啟Tomcat
...
[root@01server ~]# startup.sh 
...
[root@01server ~]#

啟用C1 GC後，所輸出的日誌格式片段如下，可以看到與之前的的日誌格式區別就比較大了，因為G1的垃圾回收過程也比較復雜：

{Heap before GC invocations=0 (full 0):  # GC發生前的堆信息
 garbage-first heap   total 16384K, used 3072K [0x00000000f0600000, 0x00000000f0700080, 0x0000000100000000)
  region size 1024K, 3 young (3072K), 0 survivors (0K)
 Metaspace       used 4729K, capacity 5024K, committed 5248K, reserved 1056768K
  class space    used 530K, capacity 600K, committed 640K, reserved 1048576K
# GC的詳細信息
2018-07-26T11:07:32.970+0800: 0.222: [GC pause (G1 Evacuation Pause) (young)
Desired survivor size 524288 bytes, new threshold 15 (max 15)
, 0.0039562 secs]
   [Parallel Time: 3.1 ms, GC Workers: 1]
      [GC Worker Start (ms):  222.0]
      [Ext Root Scanning (ms):  1.5]
      [Update RS (ms):  0.0]
         [Processed Buffers:  0]
      [Scan RS (ms):  0.0]
      [Code Root Scanning (ms):  0.1]
      [Object Copy (ms):  1.5]
      [Termination (ms):  0.0]
         [Termination Attempts:  1]
      [GC Worker Other (ms):  0.0]
      [GC Worker Total (ms):  3.1]
      [GC Worker End (ms):  225.1]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.0 ms]
   [Other: 0.8 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.7 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.0 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 3072.0K(3072.0K)->0.0B(2048.0K) Survivors: 0.0B->1024.0K Heap: 3072.0K(16.0M)->1206.5K(16.0M)]
Heap after GC invocations=1 (full 0):  # GC發生後的堆信息
 garbage-first heap   total 16384K, used 1206K [0x00000000f0600000, 0x00000000f0700080, 0x0000000100000000)
  region size 1024K, 1 young (1024K), 1 survivors (1024K)
 Metaspace       used 4729K, capacity 5024K, committed 5248K, reserved 1056768K
  class space    used 530K, capacity 600K, committed 640K, reserved 1048576K
}
 [Times: user=0.00 sys=0.00, real=0.01 secs] 
{Heap before GC invocations=13 (full 0): # GC發生前的堆信息
 garbage-first heap   total 16384K, used 13949K [0x00000000f0600000, 0x00000000f0700080, 0x0000000100000000)
  region size 1024K, 2 young (2048K), 1 survivors (1024K)
 Metaspace       used 14224K, capacity 14504K, committed 14848K, reserved 1062912K
  class space    used 1607K, capacity 1685K, committed 1792K, reserved 1048576K
# GC的詳細信息，這裏就觸發了全局並發標記
2018-07-26T11:07:34.649+0800: 1.901: [GC pause (G1 Evacuation Pause) (young) (initial-mark)
Desired survivor size 524288 bytes, new threshold 15 (max 15)
- age   1:     122776 bytes,     122776 total
, 0.0030431 secs]
   [Parallel Time: 2.9 ms, GC Workers: 1]
      [GC Worker Start (ms):  1901.5]
      [Ext Root Scanning (ms):  1.3]
      [Update RS (ms):  0.9]
         [Processed Buffers:  4]
      [Scan RS (ms):  0.0]
      [Code Root Scanning (ms):  0.0]
      [Object Copy (ms):  0.7]
      [Termination (ms):  0.0]
         [Termination Attempts:  1]
      [GC Worker Other (ms):  0.0]
      [GC Worker Total (ms):  2.9]
      [GC Worker End (ms):  1904.4]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.0 ms]
   [Other: 0.1 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.0 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.0 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 1024.0K(1024.0K)->0.0B(1024.0K) Survivors: 1024.0K->1024.0K Heap: 13.6M(16.0M)->12.6M(16.0M)]
Heap after GC invocations=14 (full 0): # GC發生後的堆信息
 garbage-first heap   total 16384K, used 12890K [0x00000000f0600000, 0x00000000f0700080, 0x0000000100000000)
  region size 1024K, 1 young (1024K), 1 survivors (1024K)
 Metaspace       used 14224K, capacity 14504K, committed 14848K, reserved 1062912K
  class space    used 1607K, capacity 1685K, committed 1792K, reserved 1048576K
}
 [Times: user=0.00 sys=0.00, real=0.01 secs] 
# 全局並發標記的過程
2018-07-26T11:07:34.652+0800: 1.905: [GC concurrent-root-region-scan-start]
2018-07-26T11:07:34.653+0800: 1.905: [GC concurrent-root-region-scan-end, 0.0003898 secs]
2018-07-26T11:07:34.653+0800: 1.905: [GC concurrent-mark-start]
2018-07-26T11:07:34.677+0800: 1.930: [GC concurrent-mark-end, 0.0245824 secs]
2018-07-26T11:07:34.678+0800: 1.930: [GC remark 2018-07-26T11:07:34.678+0800: 1.931: [Finalize Marking, 0.0000376 secs] 2018-07-26T11:07:34.678+0800: 1.931: [GC ref-proc, 0.0000413 secs] 2018-07-26T11:07:34.678+0800: 1.931: [Unloading, 0.0052688 secs], 0.0054642 secs]
 [Times: user=0.00 sys=0.00, real=0.01 secs] 
2018-07-26T11:07:34.684+0800: 1.936: [GC cleanup 12M->12M(16M), 0.0001071 secs]
 [Times: user=0.00 sys=0.00, real=0.00 secs]

同樣的，我們主要關註GC的詳細信息，所以我就截取這一部分進行一個簡單的說明：

2018-07-26T11:07:32.970+0800: 0.222: [GC pause (G1 Evacuation Pause) (young)  # 觸發GC的原因及觸發的是哪個區的GC
Desired survivor size 524288 bytes,  # 期望存活對象的大小為524288字節
new threshold 15 (max 15) # 當前存活的對象年齡為15，最大值為15，表示年齡大於15歲則會晉升到老年代
, 0.0039562 secs]  # GC耗時
   [Parallel Time: 3.1 ms, # 停止應用的時間
   GC Workers: 1]  # GC工作線程數
      [GC Worker Start (ms):  222.0]  # GC工作線程啟動的時間點
      [Ext Root Scanning (ms):  1.5] # 根節點掃描，以及耗時
      [Update RS (ms):  0.0]  # 每一個線程更新Remembered Sets花費的時間
         [Processed Buffers:  0] # 每一個線程處理的Update Buffers的數量
      [Scan RS (ms):  0.0]  # 每一個工作線程掃描Remembered Sets花費的時間
      [Code Root Scanning (ms):  0.1] # 根節點掃描耗時
      [Object Copy (ms):  1.5] # 每一個工作線程把Collection Sets的區域裏的活躍對象復制到另一個區域裏花費時間
      [Termination (ms):  0.0]  # 每一個工作線程提供中斷花費的時間
         [Termination Attempts:  1]  # 每一個線程提供中斷的次數
      [GC Worker Other (ms):  0.0] # 每個工作線程執行其他任務（上述未統計的內容）的耗時
      [GC Worker Total (ms):  3.1] # 每一個工作線程的總生存時間
      [GC Worker End (ms):  225.1]  # 每一個工作線程的終止時間
   [Code Root Fixup: 0.0 ms]  # 修正根節點耗時
   [Code Root Purge: 0.0 ms]  # 根節點清除耗時
   [Clear CT: 0.0 ms]  # 清理CT（Card Table）的耗時
   [Other: 0.8 ms]  # 其他任務（上述未統計的內容）的耗時
      [Choose CSet: 0.0 ms]  # 選擇分區的耗時
      [Ref Proc: 0.7 ms]  # 執行關聯（Reference objects）的耗時
      [Ref Enq: 0.0 ms]  # 將references放入ReferenceQueues的耗時
      [Redirty Cards: 0.0 ms] # 清理垃圾碎片耗時
      [Humongous Register: 0.0 ms]  # 註冊大對象耗時
      [Humongous Reclaim: 0.0 ms]  # 回收大對象耗時
      [Free CSet: 0.0 ms]  # 釋放CS（collection set）的耗時
   [Eden: 3072.0K(3072.0K)->0.0B(2048.0K)  # Eden區容量為3072.0K，使用了3072.0K，GC後變為0，容量目標大小增加到2048.0K。
   Survivors: 0.0B->1024.0K  # Survivors區在GC前為0，GC後為1024.0K
   Heap: 3072.0K(16.0M)->1206.5K(16.0M)]  # GC前，堆容量為16M，使用3072.0K。GC後，Heap容量為16M，使用1206.5K。

我們也知道，G1收集器裏還有一個全局並發標記（global concurrent marking）概念，觸發時其日誌格式如下，與CMS的標記過程有些類似，這裏截取出來做一個簡單的說明：

2018-07-26T11:07:34.649+0800: 1.901: [GC pause (G1 Evacuation Pause) (young) (initial-mark)  # 初始化標記，從根上直接可達的對象都被標記，這個階段背負著一個完整的疏散暫停

... 略 ...

2018-07-26T11:07:34.652+0800: 1.905: [GC concurrent-root-region-scan-start] # 開始並發根區掃描，掃描從初始標記階段的存活對象直接可達的根區集合
2018-07-26T11:07:34.653+0800: 1.905: [GC concurrent-root-region-scan-end, 0.0003898 secs] # 並發根區掃描結束及耗時
2018-07-26T11:07:34.653+0800: 1.905: [GC concurrent-mark-start]  # 開始並發標記存活的對象
2018-07-26T11:07:34.677+0800: 1.930: [GC concurrent-mark-end, 0.0245824 secs]  # 並發標記結束及耗時

# 這個是stop-the-world的重新標記階段。它完成了從上一個階段的標記工作(SATB buffers processing)的剩余部分。
2018-07-26T11:07:34.678+0800: 1.930: [GC remark 2018-07-26T11:07:34.678+0800: 1.931: [Finalize Marking, 0.0000376 secs]  # 完成重新標記及耗時
2018-07-26T11:07:34.678+0800: 1.931: [GC ref-proc, 0.0000413 secs] 
2018-07-26T11:07:34.678+0800: 1.931: [Unloading, 0.0052688 secs], 0.0054642 secs] # 卸載及耗時
 [Times: user=0.00 sys=0.00, real=0.01 secs] 

2018-07-26T11:07:34.684+0800: 1.936: [GC cleanup 12M->12M(16M), 0.0001071 secs]  # 獨占清理空的區域及耗時
 [Times: user=0.00 sys=0.00, real=0.00 secs]

可視化工具分析GC日誌

在上一小節中，我們已經了解了常用的幾種垃圾收集器的GC日誌格式。俗話說：工欲善其事，必先利其器。在進行GC調優之前我們需要先學習如何使用可視化的GC日誌分析工具，去分析GC的日誌格式，以此來得知該收集器的響應時間和吞吐量是多少，然後才能針對這兩個點去進行調優。這裏要介紹的工具是：

  • 在線工具：http://gceasy.io/
  • GCViewer

首先我們來看在線的工具，在瀏覽器上訪問http://gceasy.io/，然後上傳一個GC日誌文件，我這裏上傳的是 Parallel GC 收集器的日誌文件：
技術分享圖片

稍等一會後，該工具就可以幫我們分析出如下這些可視化的圖表及表格數據：
技術分享圖片

往下拉我們還可以看到交互圖：
技術分享圖片

以及各種GC時的狀態信息：
技術分享圖片

觸發GC的原因也做了一個統計：
技術分享圖片

在頁面的最上端，還可以下載本次分析的結果報告：
技術分享圖片

其他類型的垃圾收集器也是類似的，所以這裏也不再演示了，畢竟都是圖形化操作的，圖表數據也很直觀，而且在報告中也已經對各個點進行了說明。

所以接下來我們看看GCViewer的使用，這是一款開源的、用Java編寫的客戶端工具，GitHub地址如下：

https://github.com/chewiebug/GCViewer

下載壓縮包即可，下載好後進行解壓，使用cmd進入解壓後的目錄，然後使用maven命令對其進行編譯打包：

D:\GCView\GCViewer-develop>mvn clean package -Dmaven.test.skip

第一次打包的過程稍微有些慢，打包成功後，可以在target目錄下看到一個jar包，雙擊這個jar包即可運行：
技術分享圖片

打開後主界面如下：
技術分享圖片

同樣的，打開一個GC日誌文件，我這裏仍然使用Parallel GC的日誌文件作為演示：
技術分享圖片

打開後，可以看到一個概覽的圖表：
技術分享圖片

從Summary選項卡中查看吞吐量：
技術分享圖片

停頓時間則在Pause選項卡裏：
技術分享圖片

Memory選項卡裏自然就是查看內存相關的統計信息了：
技術分享圖片

查看觸發GC的原因在Event Detail選項卡裏：
技術分享圖片

關於GCViewer就介紹到這，詳細的說明可以參考官方的文檔。

Parallel GC調優

GC調優無外乎以下三個步驟：

  • 打印GC日誌
  • 根據日誌得到關鍵性能指標
  • 分析GC原因，調整JVM參數

Parallel GC調優的指導原則：

  • 除非確定，否則不要設置最大堆內存
  • 優先設置吞吐量目標
  • 如果吞吐量目標達不到，調大最大內存，不能讓OS使用Swap，如果仍然達不到，降低目標
  • 如果吞吐量能達到，但GC時間太長，則設置停頓時間的目標

現在我們來簡單的實戰一把GC調優，同樣的，還是以Tomcat為例，使用Parallel GC。首先設置一些初始參數：

[root@01server ~]# vim /usr/local/tomcat-8.5.32/bin/catalina.sh
JAVA_OPTS="$JAVA_OPTS -XX:+DisableExplicitGC -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=$CATALINA_HOME/logs/ -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -Xloggc:$CATALINA_HOME/logs/gc.log -XX:+PrintHeapAtGC -XX:+PrintTenuringDistribution -XX:+UseParallelGC"
[root@01server ~]# shutdown.sh  # 重啟Tomcat
...
[root@01server ~]# startup.sh 
...
[root@01server ~]#

重啟Tomcat完成後，把GC日誌下載到本地，然後使用上一小節所介紹到的可視化工具進行分析，首先要關註的是吞吐量和停頓時間的數據，在下圖中可以看到最大停頓時間有點長：
技術分享圖片

我們再看看各種GC的狀態信息，發現Full GC發生了三次，所以才導致最大停頓時間有點長：
技術分享圖片

然後我們看看觸發GC的原因，可以看到是Metaspace區域分配內存失敗導致的：
技術分享圖片

所以就可以得知是Metaspace區域的內存有點小了，僅僅是啟動的過程就發生了三次Full GC，那麽我們就需要給Metaspace區域調大些內存。其實在頁面頂端，該工具也很智能的提示了我們需要調整的地方：
技術分享圖片

我這裏的Metaspace區域內存大小默認為34M，所以我先給它調到64M看看。調優是一個不斷重復嘗試的過程，至於需要嘗試多少次完全取決於經驗和運氣了。在之前的初始化參數中，加入如下參數：

[root@01server ~]# vim /usr/local/tomcat-8.5.32/bin/catalina.sh
JAVA_OPTS="$JAVA_OPTS -XX:MetaspaceSize=64M ...略..."
[root@01server ~]# shutdown.sh  # 重啟Tomcat
...
[root@01server ~]# startup.sh 
...
[root@01server ~]#

再次將日誌文件上傳到可視化工具中進行分析，可以發現最大停頓時間明顯變短了：
技術分享圖片

那麽除此之外我們還可以做哪些調優呢？在本小節的開頭我們也說了，當使用Parallel GC的時候，我們可以設置吞吐量目標和停頓時間目標，讓它去自動進行調整。在之前的參數中，加入如下參數：

[root@01server ~]# vim /usr/local/tomcat-8.5.32/bin/catalina.sh
JAVA_OPTS="$JAVA_OPTS -XX:MaxGCPauseMillis=100 -XX:GCTimeRatio=99 ...略..."
[root@01server ~]# shutdown.sh  # 重啟Tomcat
...
[root@01server ~]# startup.sh 
...
[root@01server ~]#

再次將日誌文件上傳到可視化工具中進行分析，發現停頓時間變化並不大，吞吐量反而還降低了一些，實際上這點差距是很小的，畢竟這只是一個Tomcat啟動過程中的GC日誌：
技術分享圖片

但是我們會發現，調整了一些參數後，Full GC的次數是少了，但是Young GC的次數仍然沒有降下來，雖然不可以隨便修改堆的大小，但我們可以稍微修改動態擴容增量的參數。在之前的參數中，加入如下參數：

[root@01server ~]# vim /usr/local/tomcat-8.5.32/bin/catalina.sh
JAVA_OPTS="$JAVA_OPTS -XX:YoungGenerationSizeIncrement=30 ...略..."
[root@01server ~]# shutdown.sh  # 重啟Tomcat
...
[root@01server ~]# startup.sh 
...
[root@01server ~]#

再次將日誌文件上傳到可視化工具中進行分析，可以看到，稍微比之前好了那麽一些，Young GC比之前減少了兩次：
技術分享圖片

關於Parallel GC的調優就先介紹到這，實際上調優都是需要經驗來積累的，不是一蹴而就的，所以這裏也只是給出一些調優的步驟、方式而已。

G1調優

在上一小節中，我們介紹了Parallel GC的調優，而在本小節中，將介紹一下G1收集器的調優。G1 GC的最佳實踐：

  • 年輕代大小：避免使用-Xmn、-XX:NewRatio等顯式設置Young區大小，會覆蓋暫停時間目標
  • 暫停時間目標：暫停時間不要太嚴苛，其吞吐量目標是90%的應用程序時間和10%的垃圾回收時間，太嚴苛會直接影響到吞吐量

同樣的，我們先不設置任何調優參數，只是設置一些初始參數，然後再來做對比，也是以Tomcat為例（之前Parallel GC相關的參數要去掉），如下：

[root@01server ~]# vim /usr/local/tomcat-8.5.32/bin/catalina.sh
JAVA_OPTS="$JAVA_OPTS -XX:+UseG1GC -XX:+DisableExplicitGC -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=$CATALINA_HOME/logs/ -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -Xloggc:$CATALINA_HOME/logs/gc.log -XX:+PrintHeapAtGC -XX:+PrintTenuringDistribution"
[root@01server ~]# shutdown.sh  # 重啟Tomcat
...
[root@01server ~]# startup.sh 
...
[root@01server ~]#

和之前一樣，重啟Tomcat完成後，把GC日誌下載到本地，然後上傳到工具上進行分析，可以看到使用了G1後，停頓時間明顯小了很多，但吞吐量變化不大，因為G1是停頓時間優先的收集器：
技術分享圖片

從觸發GC的原因可以看到，Metaspace區域發生了一次GC，並且Young GC的次數也比較多：
技術分享圖片

同樣的，在頁面頂端，該工具也提示了我們可以調整Metaspace區域的大小：
技術分享圖片

那我們就和之前一樣，調大Metaspace區域看看：

[root@01server ~]# vim /usr/local/tomcat-8.5.32/bin/catalina.sh
JAVA_OPTS="$JAVA_OPTS -XX:MetaspaceSize=64M ...略..."
[root@01server ~]# shutdown.sh  # 重啟Tomcat
...
[root@01server ~]# startup.sh 
...
[root@01server ~]#

再次將日誌文件上傳到可視化工具中進行分析，可以看到吞吐量上去了一些：
技術分享圖片

而且也沒有再發生Full GC了：
技術分享圖片

但是從上圖中可以看到Young GC的次數依然很多，我們可以試著將堆的大小調大一些看看。如下：

[root@01server ~]# vim /usr/local/tomcat-8.5.32/bin/catalina.sh
JAVA_OPTS="$JAVA_OPTS -Xms128M -Xmx128M ...略..."
[root@01server ~]# shutdown.sh  # 重啟Tomcat
...
[root@01server ~]# startup.sh 
...
[root@01server ~]#

再次將日誌文件上傳到可視化工具中進行分析，可以看到吞吐量和停頓時間卻變長了一些：
技術分享圖片

但是Young GC的次數明顯少了很多：
技術分享圖片

我們都知道G1是停頓時間優先的收集器，所以我們可以設置一個停頓時間目標，讓G1自己自動調整去達到這個目標。如下：

[root@01server ~]# vim /usr/local/tomcat-8.5.32/bin/catalina.sh
JAVA_OPTS="$JAVA_OPTS -XX:MaxGCPauseMillis=100 ...略..."
[root@01server ~]# shutdown.sh  # 重啟Tomcat
...
[root@01server ~]# startup.sh 
...
[root@01server ~]#

再次將日誌文件上傳到可視化工具中進行分析，結果是吞吐量上去了一些，但停頓時間卻變長了一些：
技術分享圖片

因為這個Tomcat裏面也沒有跑什麽實際的應用，所以調優的變化並不是很大，但是也是有那麽一些差別的。G1收集器的調優參數無非也就這幾個，更多的是要對日誌進行分析以及經驗的積累，才能得出高效的調優方式。

參考文檔

jvm的運行時數據區

  • https://docs.oracle.com/javase/specs/jvms/se8/html/index.html

Metaspace

  • http://ifeve.com/jvm-troubleshooting-guide-4/

壓縮類空間

  • https://blog.csdn.net/jijijijwwi111/article/details/51564271

CodeCache

  • https://blog.csdn.net/yandaonan/article/details/50844806
  • http://engineering.indeedblog.com/blog/2016/09/job-search-web-app-java-8-migration/

GC調優指南：

  • https://docs.oracle.com/javase/8/docs/technotes/guides/vm/gctuning/toc.html

如何選擇垃圾收集器

  • https://docs.oracle.com/javase/8/docs/technotes/guides/vm/gctuning/collectors.html

G1最佳實踐

  • https://docs.oracle.com/javase/8/docs/technotes/guides/vm/gctuning/g1_gc_tuning.html#recommendations

G1 GC的一些關鍵技術

  • https://zhuanlan.zhihu.com/p/22591838

CMS日誌格式

  • https://blogs.oracle.com/poonam/understanding-cms-gc-logs

GC之詳解CMS收集過程和日誌分析

  • http://www.cnblogs.com/zhangxiaoguang/p/5792468.html

G1日誌格式

  • https://blogs.oracle.com/poonam/understanding-g1-gc-logs

理解G1垃圾收集器日誌理解G1垃圾收集器日誌

  • https://blog.csdn.net/zhanggang807/article/details/46011341

GC日誌分析工具

  • http://gceasy.io/

GCViewer

  • https://github.com/chewiebug/GCViewer

ZGC：

  • http://openjdk.java.net/jeps/333

JVM層GC調優（下）

相關推薦

JVM層GC調優（下）

日誌分析工具 f11 hub xpl aec 發現 gen sta abc GC日誌格式 本文是 JVM層GC調優（上） 的後續，在上一篇文章中，我們介紹了JVM的內存結構、常見的垃圾回收算法以及垃圾收集器和不同收集器中的一些GC調優參數。所以通過上文，我們也對GC相關的內

JVM層GC調優（上）

gist 記錄 meet 官方文檔 官網 核心數 這樣的 特殊 編寫 JVM內存結構簡介（jdk1.8） JVM層的GC調優是生產環境上必不可少的一個環節，因為我們需要確定這個進程可以占用多少內存，以及設定一些參數的閥值。以此來優化項目的性能和提高可用性，而且這也是在面試中

JVM GC調優（2）-----GC演算法判定物件可以被回收（部分摘自深入理解Java虛擬機器）

這次我們介紹JVM中的GC演算法 引用計數法 可達性分析法 首先我們提出四個問題 哪裡的記憶體需要回收？ 什麼時候回收？ 如何回收？ Java與C++之間有一堵由記憶體動態分配和垃圾收集技術所圍成的“高牆”， 牆外面的人想進去， 牆裡面的人卻想出來。

JVM GC調優（3）-----GC演算法（部分摘自深入理解Java虛擬機器）

介紹幾種GC演算法的思想及其發展過程： 標記-清除 複製 標記-壓縮 分代收集演算法 GC演算法主要是用於堆死亡物件的清理的集中方式，他們各有優缺點，下面我們開始做介紹 標記清除演算法 原理解析 -最基礎的收集演算法是“標記-清除”（ Mark-Swe

jvm層gc調優

jvm的記憶體結構 java 8 jvm官方文件 https://docs.oracle.com/javase/specs/jvms/se8/html/index.html 執行時資料區 官方文件：https://docs.oracle.com/javase/specs/jvms

JVM調優（二）——Linux下監控java執行緒

Linux環境下，當發現java程序佔用CPU資源非常高，且又要想更進一步查出哪一個java執行緒佔用了CPU資源時該如何做呢？ 一、採用命令列形式檢視執行緒，最終用dump進行文字分析 1、top命令既可以看程序，又可以看執行緒 1、top命令找出佔用資源厲害

Java jvm內存調優（來自小強公開課）

jvmJava jvm內存調優 Jdk：java開發工具包Jre：java運行環境，運行你編寫的java程序Jvm：java虛擬機，.class文件在虛擬機上運行 如何選擇合適的java虛擬機》》》選擇穩定的jdk（慎用新出的，新特性的）》》》根據平臺和應用，選擇合適廠商的jdk。HP-UX只能選擇HP J

JVM 堆參數調優 （四）

tin 計算 初始化 TP 12g ted out 垃圾 cit 堆參數調優 1、堆的結構 JAVA7 　　堆邏輯上分為：新生區、養老區、永久區；實際上堆只有新生區、養老區； 　　Minor GC：輕量的垃圾回收； Major GC（Full GC）：重量級垃圾

JVM調優（二）經驗參數設置

too 語言 相關 jdk5 nta 回收算法 from 情況 根據 調優設置具體解析 　　堆大小設置 　　　　JVM 中最大堆大小有三方面限制：相關操作系統的數據模型（32-bt還是64-bit）限制；系統的可用虛擬內存限制；系統的可用物理內存限制。32位系統下，一般限

JVM調優（四）常用調優方案

由於Full GC的成本要遠遠高於Minor GC，因此儘可能的將物件分配在新生代是一項明智的選擇。 大部分情況下，jvm會嘗試在eden區域分配物件，但是因為空間緊張等問題，很可能不得不將部分年輕物件提前向老年代壓縮。因此，可以為程式分配一個合理的新生代空間，以最大限度避免新物件直接進入老年代的情

JVM調優（三）垃圾收集

前言 垃圾收集器要處理的基本問題是：   哪些物件需要回收？ 何時回收這些物件？ 如何回收這些物件？   回收演算法   複製演算法(copying) 標

JVM調優（二）JVM記憶體分配引數

設定最大堆記憶體 -Xmx引數指定。最大堆是新生代和老年代的大小之和的最大值，他是java應用程式的堆上限。 使用-Xmx可以設定系統的最大堆。 設定最小堆記憶體 使用-Xms可以設定系統的最小堆空間，也就是jvm啟動時，所佔據的作業系統的記憶體大小。 設定新生代

JVM調優（一）虛擬機器的記憶體模型

前言 Java虛擬機器記憶體模型是Java程式執行的基礎，JVM虛擬機器的記憶體模型如下圖： 程式計數器 程式計數器(Program Counter Register)是一塊很小的記憶體空間。由於java是支援多執行緒的語言，當執行緒數超過cpu的數量時，執行緒之間根據時間片輪詢搶

JVM調優（三）程式程式碼調優

根據第一節所講的基礎知識，我們根據線上不同的異常情況做程式的優化。 CPU佔用高 us高 根據之前的分析，CPU us高的原因主要是執行執行緒無任何掛起動作，且一直執行，導致CPU沒有機會去排程執行其他的執行緒，造成執行緒餓死的現象。對於這種情況，常見的一種優化

JVM調優（7）問題定位和資訊列印

1.找到對應程序的pid ps -ef | grep tomcat #或者使用jps jps -lvm #檢視當前機器上執行的Java程序 jps命令格式如下： 命令格式 jps [options] [hostid] 注：如果不指定hostid就預設為當前主機或伺服器。

JVM調優（6）之引數配置

引數配置 堆大小設定 年輕代的設定很關鍵 JVM中最大堆大小有三方面限制： 相關作業系統的資料模型（32-bt還是64-bit）限制； 系統的可用虛擬記憶體限制； 系統的可用實體記憶體限制。 32位系統下，一般限制在1.5G~2G；64為

JVM調優（5）之分代

為什麼要分代 分代的垃圾回收策略，是基於這樣一個事實：不同的物件的生命週期是不一樣的。因此，不同生命週期的物件可以採取不同的收集方式，以便提高回收效率。 堆記憶體是虛擬機器管理的記憶體中最大的一塊，也是垃圾回收最頻繁的一塊區域，我們程式所有的物件例項都存放在堆記憶體中。給堆記憶體

JVM調優（4）之垃圾回收面臨的問題

如何區分垃圾 引用計數演算法： 來記錄一個物件被引用的次數，當引用計數器為0時，代表這個物件不再被使用。 優點：實現簡單，判斷效率也很高。 缺點：它很難解決物件之間相互迴圈引用的問題。 可達性分析演算法： 在主流的商用程式語言的主流實現都是通過可達性分析來判斷物件是否存活

JVM調優（3）之垃圾回收

從這篇開始我們開始探討一些jvm調優的問題。在jvm調優中一個離不開的重點是垃圾回收，當垃圾回收成為系統達到更高併發量的瓶頸時，我們就需要對jvm中如果進行“自動化”垃圾回收技術實施必要的監控和調節。 對於調優之前，我們必須要了解其執行原理，java 的垃圾收集Garbage Col

JVM調優（2）之基本概念

資料型別 Java虛擬機器中，資料型別可以分為兩類：基本型別 和 引用型別。 基本型別的變數儲存原始值，即：他代表的值就是數值本身； 引用型別的變數儲存引用值。“引用值”代表了某個物件的引用，而不是物件本身，物件本身存放在這個引用值所表示的地址的位置。 基本型別包括：