[翻译]G1垃圾收集器(七) 之 G1 GC记录日志

最后一个主题,我们主要介绍使用日志信息分析G1 GC的性能。本节提供了在日志中打印关于垃圾收集的数据和信息的开关选项。

设置日志详情

有可以设置日志详情到三种不同的级别

(1) -verbosegc (等同于 -XX:+PrintGC) 设置日志到 fine 级别.

例子:

[GC pause (G1 Humongous Allocation) (young) (initial-mark) 24M- >21M(64M), 0.2349730 secs]
[GC pause (G1 Evacuation Pause) (mixed) 66M->21M(236M), 0.1625268 secs]

(2) -XX:+PrintGCDetails 设置为 finer 级别. 这个选项输出下面的信息

 

  • 平均、最大和最小的暂停时间
  • 根区域扫描, RSet 刷新(包括处理缓存信息), RSet扫描, 对象复制, 消亡(包括尝试的次数).
  • 还包括其它操作使用的时间,例如CSet的选择, 引用的处理, 引用队列的入列,还有Cset的释放
  • 显示Eden, Survivors区域以及总堆内存的占用情况

例子:

Ext Root Scanning (ms): Avg: 1.7 Min: 0.0 Max: 3.7 Diff: 3.7]
[Eden: 818M(818M)->0B(714M) Survivors: 0B->104M Heap: 836M(4096M)->409M(4096M)]

(3) -XX:+UnlockExperimentalVMOptions -XX:G1LogLevel=finest 设置到finest级别,内容就行finer级别的一样,再加上每个工作线程的信息

例子:

[Ext Root Scanning (ms): 2.1 2.4 2.0 0.0
           Avg: 1.6 Min: 0.0 Max: 2.4 Diff: 2.3]
       [Update RS (ms):  0.4  0.2  0.4  0.0
           Avg: 0.2 Min: 0.0 Max: 0.4 Diff: 0.4]
           [Processed Buffers : 5 1 10 0
           Sum: 16, Avg: 4, Min: 0, Max: 10, Diff: 10]

确定日期时刻的形式

有两个开关决定日志输出的时间形式

(1) -XX:+PrintGCTimeStamps – 距离JVM启动那一刻的时间

例子:

1.729: [GC pause (young) 46M->35M(1332M), 0.0310029 secs]

(2).-XX:+PrintGCDateStamps 为每条日志输出,加入一个具体的当时时间

2012-05-02T11:16:32.057+0200: [GC pause (young) 46M->35M(1332M), 0.0317225 secs]

理解G1的日志

要理解日志,这一章节介绍一些实际使用GC日志,输出的一些条目。下面这些例子是日志中输出的,你会得到关于这些条目已经其中的那些值的含义

注:获取更多信息,请关注Poonam Bajaj的博客

Clear CT
CSet
External Root Scanning
Free CSet
GC Worker End
GC Worker Other
Object Copy
Other
Parallel Time
Ref Eng
Ref Proc
Scanning Remembered Sets
Termination Time
Update Remembered Set
Worker Start

Parallel Time

414.557: [GC pause (young), 0.03039600 secs] [Parallel Time: 22.9 ms]
[GC Worker Start (ms): 7096.0 7096.0 7096.1 7096.1 706.1 7096.1 7096.1 7096.1 7096.2 7096.2 7096.2 7096.2
       Avg: 7096.1, Min: 7096.0, Max: 7096.2, Diff: 0.2]

Parallel Time – 主要并行处理的部分占用的世界

Worker Start – 工作线程启动的时刻

注: 日志会根据线程id排序,并且和条目一致

External Root Scanning

[Ext Root Scanning (ms): 3.1 3.4 3.4 3.0 4.2 2.0 3.6 3.2 3.4 7.7 3.7 4.4
     Avg: 3.8, Min: 2.0, Max: 7.7, Diff: 5.7]

External root scanning – 扫描外部根锁使用的时间 (举例., 就像系统指向堆内部的系统字典)

Update Remembered Set

[Update RS (ms): 0.1 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Avg: 0.0, Min: 0.0, Max: 0.1, Diff: 0.1]
   [Processed Buffers : 26 0 0 0 0 0 0 0 0 0 0 0
    Sum: 26, Avg: 2, Min: 0, Max: 26, Diff: 26]

Update Remembered Set – 一些缓存可能完成了,但是还没有被并发线程处理,所以在开始之前必须进行刷新,时间依赖于cards的密度,cards越多,时间越长。

Scanning Remembered Sets

[Scan RS (ms): 0.4 0.2 0.1 0.3 0.0 0.0 0.1 0.2 0.0 0.1 0.0 0.0 Avg: 0.1, Min: 0.0, Max: 0.4, Diff: 0.3]F

Scanning Remembered Sets – 查询指向收集区域的指针.

Object Copy

[Object Copy (ms): 16.7 16.7 16.7 16.9 16.0 18.1 16.5 16.8 16.7 12.3 16.4 15.7 Avg: 16.3, Min: 12.3, Max:  18.1, Diff: 5.8]

Object copy – 每个独立线程复制和消亡对象锁花费的时间

Termination Time

[Termination (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
0.0 Avg: 0.0, Min: 0.0, Max: 0.0, Diff: 0.0] [Termination Attempts : 1 1 1 1 1 1 1 1 1 1 1 1 Sum: 12, Avg: 1, Min: 1, Max: 1, Diff: 0]

Termination time -当一个工作线程结束了它对特定对象的复制和扫描,它就会进入终结协议(protocol)。它会偷偷的找活干,一旦干了一点活,他就会进入终结协议,这个终结会计算线程尝试偷偷工作的次数(译者注:我都不知道我翻译的是啥意思)

 

GC Worker End

[GC Worker End (ms): 7116.4 7116.3 7116.4 7116.3 7116.4 7116.3 7116.4 7116.4 7116.4 7116.4 7116.3 7116.3
    Avg: 7116.4, Min: 7116.3, Max: 7116.4, Diff:   0.1]
[GC Worker (ms): 20.4 20.3 20.3 20.2 20.3 20.2 20.2 20.2 20.3 20.2 20.1 20.1
     Avg: 20.2, Min: 20.1, Max: 20.4, Diff: 0.3]

GC worker end time – 单个GC线程结束时的时间.

GC worker time – 单个GC线程所使用的时间

GC Worker Other

[GC Worker Other (ms): 2.6 2.6 2.7 2.7 2.7 2.7 2.7 2.8 2.8 2.8 2.8 2.8
    Avg: 2.7, Min: 2.6, Max: 2.8, Diff: 0.2]

GC worker other – 每个GC线程不在前面列出的阶段中的时间,应该是很低的。在过去这个时间是很高的,并且成为JVM一些部分的瓶颈。(例如,增加分层的代码缓存占用)

Clear CT

[Clear CT: 0.6 ms]

清除扫描元数据的Rset的卡表(card table)所需要的时间

Other

[Other: 6.8 ms]

GC暂停中其它各种连续阶段的时间

CSet

[Choose CSet: 0.1 ms]

确定哪些区域需要收集锁占用的时间,通常很短,当需要选择老年代的时候,才会变的稍长些。

Ref Proc

[Ref Proc: 4.4 ms]

处理GC前面阶段产生的sofe weak等引用所使用的时间

Ref Enq

[Ref Enq: 0.1 ms]

把soft weak等引用放到待处置列表中所占用的时间。

Free CSet

[Free CSet: 2.0 ms]

释放那些已经被收集过的区域,包括他们的remembered sets所花费的时间

留言

提示:你的email不会被公布,欢迎留言^_^

*

验证码 *