JVM实战-GC日志分析

1）GC日志分析

配置GC日志文件参数

# 未配置垃圾收集器，则默认使用 ParallelGC 
-verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:gc.log

-verbose:gc 在控制台输出GC情况
-XX:+PrintGCDetails 在控制台输出详细的GC情况
-Xloggc: filepath 将GC日志输出到指定文件中

1.1）Parallel GC日志分析

• 参数配置

-verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:gc.log -XX:+UseParallelGC 

• 特点

吞吐量优先。

• 日志分析

# Young区GC MinorGC
2020-08-05T10:23:58.715+0800: 1.110: [GC (Allocation Failure) [PSYoungGen: 65024K[Young区回收前]->8121K[Young区回收后](75776K[Young区总大小])] 65024K[整个堆回收前]->8137[整个堆回收后]K(249344K[整个堆总大小]), 0.0065560 secs] [Times: user=0.05 sys=0.08, real=0.01 secs] 

1.2）CMS日志分析

• 参数配置

-Xmx10M -Xms10M -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:cms-gc.log -XX:+UseConcMarkSweepGC 

• 特点

停顿时间优先。

• 日志分析

# 命令行JVM标志参数
CommandLine flags: -XX:InitialHeapSize=10485760 -XX:MaxHeapSize=10485760 -XX:MaxNewSize=3497984 -XX:MaxTenuringThreshold=6 -XX:NewSize=3497984 -XX:OldPLABSize=16 -XX:OldSize=6987776 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:-UseLargePagesIndividualAllocation -XX:+UseParNewGC 

# Young区GC ParNew收集器 分配失败
2020-08-05T16:54:50.386+0800: 0.130: [GC (Allocation Failure) 2020-08-05T16:54:50.386+0800: 0.130: [ParNew: 3072K[Young区回收前]->320K[Young区回收后](3072K[Young区总大小]), 0.0029042 secs] 4077K[整个堆回收前]->3390K[整个堆回收后](9920K[整个堆总大小]), 0.0029843 secs] [Times: user=0.08 sys=0.02, real=0.00 secs] 

# Old区GC CMS收集器
# 阶段一：初始标记
2020-08-05T16:54:50.394+0800: 0.138: [GC (CMS Initial Mark) [1 CMS-initial-mark: 5821K(6848K)] 6247K(9920K), 0.0002101 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
# 阶段二：在GC开始后的0.138秒处开始并行标记
2020-08-05T16:54:50.394+0800: 0.138: [CMS-concurrent-mark-start]
# 阶段二：分配失败；ParNew收集后，内存无变化；并发标记结束
2020-08-05T16:54:50.396+0800: 0.140: [GC (Allocation Failure) 2020-08-05T16:54:50.396+0800: 0.140: [ParNew: 3072K->3072K(3072K), 0.0000126 secs]2020-08-05T16:54:50.396+0800: 0.140: [CMS2020-08-05T16:54:50.408+0800: 0.152: [CMS-concurrent-mark: 0.012/0.014 secs] [Times: user=0.05 sys=0.00, real=0.01 secs] 
# 阶段二：并发模式失败，因为剩余空间无法满足新对象的分配要求
 (concurrent mode failure): 5821K->6847K(6848K), 0.0255327 secs] 8893K->7828K(9920K), [Metaspace: 3450K->3450K(1056768K)], 0.0256104 secs] [Times: user=0.06 sys=0.00, real=0.03 secs] 
# Old区 CMS收集器 Full GC 分配失败
2020-08-05T16:54:50.422+0800: 0.166: [Full GC (Allocation Failure) 2020-08-05T16:54:50.422+0800: 0.166: [CMS: 6847K->6847K(6848K), 0.0138690 secs] 9148K->9102K(9920K), [Metaspace: 3451K->3451K(1056768K)], 0.0139466 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
# 阶段一：初始标记
2020-08-05T16:54:50.451+0800: 0.195: [GC (CMS Initial Mark) [1 CMS-initial-mark: 6847K(6848K)] 9084K(9920K), 0.0025257 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
# 阶段二：并发标记开始 -- 此处OOM
2020-08-05T16:54:50.454+0800: 0.198: [CMS-concurrent-mark-start]
# 可通过下面的信息分析堆内存的分布情况
Heap
 par new generation   total 3072K, used 2392K [0x00000000ff600000, 0x00000000ff950000, 0x00000000ff950000)
  eden space 2752K,  86% used [0x00000000ff600000, 0x00000000ff856120, 0x00000000ff8b0000)
  from space 320K,   0% used [0x00000000ff900000, 0x00000000ff900000, 0x00000000ff950000)
  to   space 320K,   0% used [0x00000000ff8b0000, 0x00000000ff8b0000, 0x00000000ff900000)
 concurrent mark-sweep generation total 6848K, used 6847K [0x00000000ff950000, 0x0000000100000000, 0x0000000100000000)
 Metaspace       used 3482K, capacity 4564K, committed 4864K, reserved 1056768K
  class space    used 379K, capacity 388K, committed 512K, reserved 1048576K

错误 concurrent mode failure 分析：

出现该错误主要有两个原因：

1、在最大停顿时间内，并发收集器无法完成对不可访问对象的回收

2、剩余空间无法满足新加入对象的分配要求

解决办法就是要让年老代留有足够的空间，以保证新对象空间的分配。

1.3）G1日志分析

• 参数配置

-Xmx10M -Xms10M -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:cms-gc.log -XX:+UseG1GC

• 特点

停顿时间优先。

• 日志分析

理解G1日志格式 https://blogs.oracle.com/poonam/understanding-g1-gc-logs

# GC发生的时间，相对的时间刻，GC发生的区域young，总共花费的时间0.0033173s
2020-08-05T17:16:49.747+0800: 0.139: [GC pause (G1 Evacuation Pause) (young), 0.0033173 secs]
   # 10个并行GC线程的总运行时间2.7ms,
   [Parallel Time: 2.7 ms, GC Workers: 10]
      # GC线程的启动时间的平均值、最小值、最大值和差异
      [GC Worker Start (ms): Min: 139.0, Avg: 139.1, Max: 139.1, Diff: 0.1]
      # GC线程所花费时间的平均值、最小值、最大值和差异
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.3, Diff: 0.3, Sum: 1.5]
      # GC线程在更新记忆集上花费的时间的平均值、最小值、最大值和差异
      # Remembered Sets RS 记忆集是跟踪指向堆区域的引用的数据结构。包含与指向该区域的引用相对应的卡片。
      [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      	 # GC线程处理的更新缓冲区的数量
         [Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0]
      # GC线程扫描RS所花费的时间
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      # GC线程将活动对象从RS中的区域复制到其他区域所花费的时间
      [Object Copy (ms): Min: 2.2, Avg: 2.3, Max: 2.4, Diff: 0.2, Sum: 23.1]
      # GC线程终止所花费的时间，终止之前，它会检查其他线程的工作队列，如果其他工作队列中仍有对象引用，则会尝试窃取对象引用，如果成功窃取引用，则会处理该引用并再次提供终止
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
         [Termination Attempts: Min: 28, Avg: 32.1, Max: 39, Diff: 11, Sum: 321]
      # GC线程在执行上面我们没有考虑到的其他任务时所花费的总并行时间
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.3, Diff: 0.3, Sum: 0.8]
      # GC线程在执行上面流程时所花费的总并行时间
      [GC Worker Total (ms): Min: 2.5, Avg: 2.5, Max: 2.6, Diff: 0.1, Sum: 25.5]
      # GC线程停止的时间
      [GC Worker End (ms): Min: 141.6, Avg: 141.6, Max: 141.6, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   # 用于清除卡片表的时间，以串行模式执行
   [Clear CT: 0.1 ms]
   # 列出在其他任务上花费的时间
   [Other: 0.5 ms]
   	  # 为选择Collection Set区域所花费的时间。
      [Choose CSet: 0.0 ms]
      # 处理引用对象所花费的总时间
      [Ref Proc: 0.2 ms]
      # 将引用排队到引用队列所花费的时间
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.2 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      # 释放Collection Set区域所花费的时间
      [Free CSet: 0.0 ms]
   # 表示堆空间大小随垃圾收集暂停而变化的详细信息
   [Eden: 6144.0K(6144.0K)->0.0B(2048.0K) Survivors: 0.0B->1024.0K Heap: 6144.0K(10.0M)->3920.0K(10.0M)]
 [Times: user=0.00 sys=0.00, real=0.00 secs]