JVM GC Logger

发表于 | 分类于 ， ，

Configuation

Analyze Logger

GC格式图解

实战分析

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
[GC pause (G1 Evacuation Pause) (young) 140.031: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 19075, predicted base time: 18.50 ms, remaining time: 81.50 ms, target pause time: 100.00 ms]
 140.031: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 77 regions, survivors: 6 regions, predicted young region time: 89.12 ms]
 140.031: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 77 regions, survivors: 6 regions, old: 0 regions, predicted pause time: 107.62 ms, target pause time: 100.00 ms]
, 0.1151640 secs]
   [Parallel Time: 111.6 ms, GC Workers: 4] # 标记着并行阶段的汇总信息。总共花费时间以及GC的工作线程数
      # Start时间戳信息 Diff是偏移平均时间的值。Diff越小越好，说明每个工作线程的速度都很均匀
      # Avg代表平均时间值。如果Avg跟Min,Max偏差不大是比较正常的，否则也要详细分析具体的偏差值大的任务。
      [GC Worker Start (ms): Min: 140031.5, Avg: 140031.6, Max: 140031.9, Diff: 0.4] 
      # Ext Root Scanning 外部根区扫描。外部根是堆外区。JNI引用，JVM系统目录，Classloaders等。
      [Ext Root Scanning (ms): Min: 1.1, Avg: 1.7, Max: 2.2, Diff: 1.2, Sum: 6.7] 
      # RSet
      # UpdateRS:更新RSet的时间信息。-XX:MaxGCPauseMillis参数是限制G1的暂停之间，一般RSet更新的时间小于10%的目标暂停时间是比较可取的。
      # 如果花费在RSetUpdate的时间过长，可以修改其占用总暂停时间的百分比-XX:G1RSetUpdatingPauseTimePercent。这个参数的默认值是10。
      [Update RS (ms): Min: 11.1, Avg: 12.9, Max: 16.9, Diff: 5.9, Sum: 51.6] 
        # Processed Buffers:已处理缓冲区。这个阶段处理的是在优化线程中处理dirty card分区扫描时记录的日志缓冲区。
         [Processed Buffers: Min: 14, Avg: 25.2, Max: 36, Diff: 22, Sum: 101]
      [Scan RS (ms): Min: 37.4, Avg: 41.9, Max: 44.7, Diff: 7.3, Sum: 167.7]
      # Code Root Scanning：代码跟的扫描。只有在分区的RSet有强代码根时会检查CSet的对内引用，例如常量池。
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.5, Diff: 0.5, Sum: 0.5]
      # Object Copy：该任务主要是对CSet中存活对象进行转移（复制）。对象拷贝的时间一般占用暂停时间的主要部分。
      # 如果拷贝时间和”预测暂停时间“有相差很大，也可以调整年轻代尺寸大小。
      [Object Copy (ms): Min: 52.6, Avg: 54.2, Max: 55.1, Diff: 2.5, Sum: 216.9]
      # Termination 
      # 这里的终止主要是终止工作线程。Work线程在工作终止前会检查其他工作线程的任务，如果其他work线程有没完成的任务，会抢活。
      # 如果终止时间较长，额能是某个work线程在某项任务执行时间过长。
      [Termination (ms): Min: 0.0, Avg: 0.5, Max: 0.7, Diff: 0.7, Sum: 2.2]
         [Termination Attempts: Min: 1, Avg: 2.0, Max: 4, Diff: 3, Sum: 8]
      # GC Worker Other
      # 花在GC之外的工作线程的时间，比如因为JVM的某个活动，导致GC线程被停掉。这部分消耗的时间不是真正花在GC上，只是作为log的一部分记录。
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      # GC Worker Total
      # 并行阶段的GC汇总，包含了GC以及GC Worker Other的总时间。
      [GC Worker Total (ms): Min: 111.1, Avg: 111.4, Max: 111.5, Diff: 0.4, Sum: 445.5]
      # End时间戳信息
      [GC Worker End (ms): Min: 140143.0, Avg: 140143.0, Max: 140143.0, Diff: 0.0] 
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.1 ms]
   [Clear CT: 0.5 ms]
   [Other: 3.0 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 1.0 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.7 ms]
      [Humongous Register: 0.3 ms]
      [Humongous Reclaim: 0.1 ms]
      [Free CSet: 0.3 ms]
   # 垃圾收集结果统计
   #  Eden分区GC前616.0M，GC后是0；其中括号里面的分别是GC前后Eden分区的总大小
   [Eden: 616.0M(616.0M)->0.0B(616.0M) Survivors: 48.0M->48.0M Heap: 2742.1M(13.1G)->2127.1M(13.1G)]
   # Survivors: 48.0M->48.0M，这里没有变化，如果Survivors空间的变化，空间增长了，说明有存活对象E区晋升到S区。
   # Heap: 2742.1M(13.1G)->2127.1M(13.1G)，整个堆区的GC前后空间数据，G1 GC会动态调整堆区，但这次回收中没有改变堆区的容量。
 [Times: user=0.33 sys=0.01, real=0.12 secs]
1
2
3
4
[GC pause (G1 Evacuation Pause) (young) 144.865: 
[G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 14697, predicted base time: 15.95 ms, remaining time: 84.05 ms, target pause time: 100.00 ms]
[G1Ergonomics (CSet Construction) add young regions to CSet, eden: 77 regions, survivors: 6 regions, predicted young region time: 93.31 ms]
[G1Ergonomics (CSet Construction) finish choosing CSet, eden: 77 regions, survivors: 6 regions, old: 0 regions, predicted pause time: 109.26 ms, target pause time: 100.00 ms]

Reference

https://blog.csdn.net/lijingyao8206/article/details/80566384