1. 程式人生 > >JVM層GC調優(下)

JVM層GC調優(下)

日誌分析工具 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調優(下)