JAVA 性能调优 -- 带你解读 CMS GC 日志

2021-02-06 14:15:31   最后更新: 2021-02-06 14:15:31   访问数量:53




 

连续两篇文章,我们介绍了 java 最为常用的两大垃圾收集器 -- CMS 与 G1:

 

CMS 执行的七个阶段

 

G1 垃圾回收器的工作流程

 

在 G1 收集器的介绍中,我们提到,CMS 有着非常多的参数来控制整个流程,因此,要想进行 GC 相关的 java 性能调优,首要的基础就是要去深入了解垃圾回收相关的全部参数,在此基础上,看懂和分析 GC 日志,就成为了 java 程序员必备的一项技能。

 

本文我们就深入浅出,逐步带你走进 CMS GC 性能优化的世界。

 

 

 

 

2.1 基础参数

 

-server # 开启服务端模式,启动慢但性能更优

-Xms<size> # 初始堆内存大小,默认为物理内存的 1/64

-Xmx<size> # 最大堆内存大小,默认为物理内存的 1/4

-Xmn<size> # 新生代大小

-Xss<size> # 每个线程的堆栈大小,jdk1.5 以上默认为 1M

 

2.2 gc log 相关配置参数

 

-Xloggc:<path> # gc log 的输出路径

-XX:+PrintGC # 输出 gc log

-XX:+PrintGCDetails # 输出 gc 详细信息

-XX:+PrintGCDateStamps # 在 gc log 中记录 gc 启动时的系统时间

-XX:+PrintGCTimeStamps # 在 gc log 中记录 gc 启动时相对于 jvm 启动的相对时间

 

2.3 堆 dump 相关参数

 

-XX:+HeapDumpOnOutOfMemoryError # 当 jvm OOM 时,自动生成 dump 文件

-XX:+AlwaysPreTouch # jvm 启动时预分配物理内存

-XX:HeapDumpPath=<path> # jvm OOM 时,dump 文件输出路径

-XX:ErrorFile=<path> # jvm OOM 时,输出 hs_err_pid*.log 的位置

 

2.4 分代大小参数

 

-XX:MetaspaceSize=<size> # 元空间大小

-XX:MaxMetaspaceSize=<size> # 最大元空间大小

-XX:NewRatio=<int> # 老年代与新生代的比例,默认为 2

-XX:SurvivorRatio=<int> # eden 区与 survive 区比例,默认为 8

 

2.5 CMS 相关参数

 

-XX:+UseParNewGC # 使用 ParNew 作为新生代垃圾收集器

-XX:+UseConcMarkSweepGC # 使用 CMS 作为 minor GC 收集器

-XX:+CMSClassUnloadingEnabled # CMS 可以回收永久代

-XX:+UseCMSInitiatingOccupancyOnly # 只有当堆内存超过阈值,才运行 CMS 回收,不建议开启

-XX:CMSInitiatingOccupancyFraction=<int> # 堆满阈值,默认为 75

-XX:+UseCMSCompactAtFullCollection # full gc 后是否进行碎片整理

-XX:CMSFullGCsBeforeCompaction=<int> # 多少次 full gc 后进行一次碎片整理,默认为 5,需要与上一项配置搭配使用

-XX:+CMSConcurrentMTEnabled # 是否多线程并发回收,默认开启

-XX:ConcGCThreads=<int> # CMS 并发收集线程数,默认为 CPU 核心数

-XX:+CMSIncrementalMode # 开启 CMS 增量模式,每次回收一部分,多次执行后完成回收,不建议开启

-XX:+ExplicitGCInvokesConcurrent # 调用 System.gc() 将执行 CMS 而不是 full GC

-XX:+ExplicitGCInvokesConcurrentAndUnloadsClasses # 在上一项配置基础上,System.gc() 执行后回收范围包含永久代

-XX:+DisableExplicitGC # 禁用 System.gc()

 

 

3.1 demo 程序代码

 

下面我们通过一个 demo 程序来看看具体的 GC 日志:

 

package cn.techlog.testjava.main; public class MapPutIfAbsent { public static void main(String[] args) { int size = 1024 * 1024; for (int i = 0; i < 10; ++i) { byte[] alloc1 = new byte[size * 4]; System.out.println("alloc1"); byte[] alloc2 = new byte[size * 2]; System.out.println("alloc2"); byte[] alloc3 = new byte[size * 4]; System.out.println("alloc3"); } } }

 

 

代码看起来很简单,我们创建了个 byte[],分别占据 4M、2M、4M 空间,并将这一过程循环 10 次。

 

3.2 jvm 参数

 

接下里我们配置以下参数:

 

-server

-Xms40M

-Xmx40M # 堆内存 40MB

-Xmn20M # 新生代内存 20MB

-XX:SurvivorRatio=8 # eden 区与 survive 区比例为 8:2

-verbose:gc # 在控制台输出 gc 日志

-XX:+PrintGCDetails # 输出 gc 日志详细信息

-XX:+PrintGCDateStamps # 打印日志时间

-XX:+UseConcMarkSweepGC # 启用 CMS

 

3.3 执行日志

 

启动程序,输出了以下日志:

 

alloc1

alloc2

alloc3

alloc1

2021-02-06T12:42:47.088-0800: [GC (Allocation Failure) 2021-02-06T12:42:47.088-0800: [ParNew: 16056K->419K(18432K), 0.0084200 secs] 16056K->5852K(38912K), 0.0084561 secs] [Times: user=0.03 sys=0.01, real=0.01 secs] 

alloc2

alloc3

alloc1

alloc2

2021-02-06T12:42:47.097-0800: [GC (Allocation Failure) 2021-02-06T12:42:47.097-0800: [ParNew: 13028K->209K(18432K), 0.0099102 secs] 18461K->11787K(38912K), 0.0099420 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 

2021-02-06T12:42:47.107-0800: [GC (CMS Initial Mark) [1 CMS-initial-mark: 11577K(20480K)] 15883K(38912K), 0.0002270 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

2021-02-06T12:42:47.107-0800: [CMS-concurrent-mark-start]

alloc3

alloc1

alloc2

alloc3

2021-02-06T12:42:47.108-0800: [GC (Allocation Failure) 2021-02-06T12:42:47.108-0800: [ParNew: 14828K->14828K(18432K), 0.0000186 secs]2021-02-06T12:42:47.108-0800: [CMS2021-02-06T12:42:47.109-0800: [CMS-concurrent-mark: 0.001/0.002 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

(concurrent mode failure): 11577K->1320K(20480K), 0.0070740 secs] 26406K->1320K(38912K), [Metaspace: 7602K->7602K(1056768K)], 0.0071292 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 

alloc1

alloc2

alloc3

alloc1

2021-02-06T12:42:47.116-0800: [GC (Allocation Failure) 2021-02-06T12:42:47.116-0800: [ParNew: 15287K->17K(18432K), 0.0012768 secs] 16608K->5436K(38912K), 0.0013161 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 

alloc2

alloc3

alloc1

alloc2

2021-02-06T12:42:47.118-0800: [GC (Allocation Failure) 2021-02-06T12:42:47.118-0800: [ParNew: 12612K->4K(18432K), 0.0014321 secs] 18031K->11569K(38912K), 0.0014586 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 

2021-02-06T12:42:47.120-0800: [GC (CMS Initial Mark) [1 CMS-initial-mark: 11564K(20480K)] 15665K(38912K), 0.0001875 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

2021-02-06T12:42:47.120-0800: [CMS-concurrent-mark-start]

alloc3

alloc1

alloc2

alloc3

2021-02-06T12:42:47.121-0800: [GC (Allocation Failure) 2021-02-06T12:42:47.121-0800: [ParNew: 14633K->4K(18432K), 0.0008106 secs] 26198K->11568K(38912K), 0.0008370 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

alloc1

alloc2

alloc3

alloc1

2021-02-06T12:42:47.122-0800: [GC (Allocation Failure) 2021-02-06T12:42:47.122-0800: [ParNew: 14643K->4K(18432K), 0.0022952 secs] 26207K->15664K(38912K), 0.0023281 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 

alloc2

alloc3

2021-02-06T12:42:47.125-0800: [CMS-concurrent-mark: 0.002/0.005 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 

2021-02-06T12:42:47.125-0800: [CMS-concurrent-preclean-start]

2021-02-06T12:42:47.126-0800: [CMS-concurrent-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

2021-02-06T12:42:47.126-0800: [CMS-concurrent-abortable-preclean-start]

2021-02-06T12:42:47.126-0800: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

2021-02-06T12:42:47.126-0800: [GC (CMS Final Remark) [YG occupancy: 7115 K (18432 K)]2021-02-06T12:42:47.126-0800: [Rescan (parallel) , 0.0007304 secs]2021-02-06T12:42:47.126-0800: [weak refs processing, 0.0000118 secs]2021-02-06T12:42:47.126-0800: [class unloading, 0.0007235 secs]2021-02-06T12:42:47.127-0800: [scrub symbol table, 0.0005133 secs]2021-02-06T12:42:47.128-0800: [scrub string table, 0.0001555 secs][1 CMS-remark: 15660K(20480K)] 22776K(38912K), 0.0021777 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 

2021-02-06T12:42:47.128-0800: [CMS-concurrent-sweep-start]

2021-02-06T12:42:47.128-0800: [CMS-concurrent-sweep: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

2021-02-06T12:42:47.128-0800: [CMS-concurrent-reset-start]

2021-02-06T12:42:47.128-0800: [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

Heap

par new generation   total 18432K, used 7115K [0x00000007bd800000, 0x00000007bec00000, 0x00000007bec00000)

eden space 16384K,  43% used [0x00000007bd800000, 0x00000007bdef1db0, 0x00000007be800000)

from space 2048K,   0% used [0x00000007bea00000, 0x00000007bea01020, 0x00000007bec00000)

to   space 2048K,   0% used [0x00000007be800000, 0x00000007be800000, 0x00000007bea00000)

concurrent mark-sweep generation total 20480K, used 11562K [0x00000007bec00000, 0x00000007c0000000, 0x00000007c0000000)

Metaspace    used 7608K, capacity 7782K, committed 7936K, reserved 1056768K

class space used 877K, capacity 908K, committed 1024K, reserved 1048576K

 

3.4 日志分析

 

接下来,我们就来逐条看看上述 GC log 究竟向我们讲述了什么。

 

3.4.1 young gc

 

开始的时候,程序顺次打印出了:

 

alloc1

alloc2

alloc3

alloc1

 

分别申请了 4M、2M、4M、4M 的空间,总计 14 MB,而我们的 eden 区是 20M(新生代) * 0.8(eden 区比例) = 16M,所以恰好是可以容纳上述 14MB 的对象的。

 

接着,我们要再申请 2MB 的空间,此时 eden 区就会被占满,于是触发了第一次 young gc:

 

2021-02-06T12:42:47.116-0800: [GC (Allocation Failure) 2021-02-06T12:42:47.116-0800: [ParNew: 15287K->17K(18432K), 0.0012768 secs] 16608K->5436K(38912K), 0.0013161 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]

 

这行日志中,有以下关键信息:

 

  1. Allocation Failure -- 表示本次 GC 是由于分配空间失败引起的
  2. ParNew -- 表示使用的垃圾收集器为 ParNew
  3. 15287K->17K(18432K) -- 表示年轻代垃圾回收前占用从 15287KB 到回收后占用 17KB,年轻代总大小为 18432KB
  4. 0.0012768 secs -- 本次 GC 耗时 0.0012768 秒
  5. 16608K->5436K(38912K) -- 堆区回收前占用 16608KB,回收后占用 5436KB,堆区总占用空间为 38912KB
  6. [Times: user=0.01 sys=0.00, real=0.00 secs] -- 三个耗时分别是用户态耗时、内核态耗时和总耗时

 

3.4.2 minor gc

 

紧接着,我们的程序重复着上述过程,分配、young gc。

 

最后,程序进行了一次完整的 CMS minor GC:

 

2021-02-06T12:42:47.120-0800: [GC (CMS Initial Mark) [1 CMS-initial-mark: 11564K(20480K)] 15665K(38912K), 0.0001875 secs] [Times: user=0.00 sys=0.00, real=0.00 

2021-02-06T12:42:47.120-0800: [CMS-concurrent-mark-start]

2021-02-06T12:42:47.125-0800: [CMS-concurrent-mark: 0.002/0.005 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 

2021-02-06T12:42:47.125-0800: [CMS-concurrent-preclean-start]

2021-02-06T12:42:47.126-0800: [CMS-concurrent-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

2021-02-06T12:42:47.126-0800: [CMS-concurrent-abortable-preclean-start]

2021-02-06T12:42:47.126-0800: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

2021-02-06T12:42:47.126-0800: [GC (CMS Final Remark) [YG occupancy: 7115 K (18432 K)]2021-02-06T12:42:47.126-0800: [Rescan (parallel) , 0.0007304 secs]2021-02-06T12:42:47.126-0800: [weak refs processing, 0.0000118 secs]2021-02-06T12:42:47.126-0800: [class unloading, 0.0007235 secs]2021-02-06T12:42:47.127-0800: [scrub symbol table, 0.0005133 secs]2021-02-06T12:42:47.128-0800: [scrub string table, 0.0001555 secs][1 CMS-remark: 15660K(20480K)] 22776K(38912K), 0.0021777 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 

2021-02-06T12:42:47.128-0800: [CMS-concurrent-sweep-start]

2021-02-06T12:42:47.128-0800: [CMS-concurrent-sweep: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

2021-02-06T12:42:47.128-0800: [CMS-concurrent-reset-start]

2021-02-06T12:42:47.128-0800: [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

 

此前的文章中介绍过 CMS 执行的七个步骤,而上述日志正好对应着七个步骤每一步的开始、结束以及运行信息:

 

  1. 初始标记 -- CMS Initial Mark
  2. 并发标记 -- CMS-concurrent-mark
  3. 并发预清理 -- CMS-concurrent-preclean
  4. 并发可中断预清理 -- CMS-concurrent-abortable
  5. 最终标记 -- CMS Final Remark
  6. 并发清除 -- CMS-concurrent-sweep
  7. 并发重置 -- CMS-concurrent-reset

 

上述大部分日志信息都是关于对应流程的耗时情况,这里我们只对最终标记流程的日志进行详细解读:

 

2021-02-06T12:42:47.126-0800: [GC (CMS Final Remark) [YG occupancy: 7115 K (18432 K)]2021-02-06T12:42:47.126-0800: [Rescan (parallel) , 0.0007304 secs]2021-02-06T12:42:47.126-0800: [weak refs processing, 0.0000118 secs]2021-02-06T12:42:47.126-0800: [class unloading, 0.0007235 secs]2021-02-06T12:42:47.127-0800: [scrub symbol table, 0.0005133 secs]2021-02-06T12:42:47.128-0800: [scrub string table, 0.0001555 secs][1 CMS-remark: 15660K(20480K)] 22776K(38912K), 0.0021777 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 

 

  1. YG occupancy: 7115 K (18432 K) -- 表示年轻代占用空间为 7115 K,年轻代总空间为 18432 K
  2. Rescan (parallel) , 0.0007304 secs -- 老年代重新扫描耗时 0.0007304 秒
  3. weak refs processing, 0.0000118 secs -- 弱引用处理耗时
  4. class unloading, 0.0007235 secs -- 类加载处理耗时
  5. scrub symbol table, 0.0005133 secs -- 符号表处理耗时
  6. scrub string table, 0.0001555 secs -- 字符表处理耗时
  7. 1 CMS-remark: 15660K(20480K)] 22776K(38912K), 0.0021777 secs -- CMS 重新标记后,老年代占用 15660K,老年代总空间 20480K,堆占用空间 22776K,堆总空间 38912K,以及该阶段耗时

 

3.4.3 gc 结束后堆的空间占用情况

 

整个 CMS 垃圾收集器处理完成之后,接下来我们可以看到堆的占用情况:

 

Heap

par new generation   total 18432K, used 7115K [0x00000007bd800000, 0x00000007bec00000, 0x00000007bec00000)

eden space 16384K,  43% used [0x00000007bd800000, 0x00000007bdef1db0, 0x00000007be800000)

from space 2048K,   0% used [0x00000007bea00000, 0x00000007bea01020, 0x00000007bec00000)

to   space 2048K,   0% used [0x00000007be800000, 0x00000007be800000, 0x00000007bea00000)

concurrent mark-sweep generation total 20480K, used 11562K [0x00000007bec00000, 0x00000007c0000000, 0x00000007c0000000)

Metaspace    used 7608K, capacity 7782K, committed 7936K, reserved 1056768K

class space used 877K, capacity 908K, committed 1024K, reserved 1048576K

 

它包含了新生代、老年代、元空间的占用情况,信息非常详尽。

 

 

上述少量的日志我们可以通过肉眼查看快速定位程序做了什么,或者找到频繁 GC 的原因。

 

但对于错综复杂的线上场景,海量的日志,我们就难以这样分析了,此时,一个好用的可视化分析工具对我们来说就至关重要了。

 

这里我们介绍一个分析网站和一个本地工具,分析起问题来都非常直观。

 

4.1 GCeasy

 

GC Easy是一款在线的可视化工具,易用、功能强大,网站:http://gceasy.io/

 

 

 

我们只需要上传 gc 日志,然后点击 Analyze 按钮就可以生成分析报告了。

 

可以看到以下信息:

 

4.1.1 堆信息

 

 

 

4.1.2 关键指标

 

 

 

4.1.3 图表展示

 

 

 

4.1.4 GC 统计

 

 

 

4.2 GC Viewer

 

GC Viewer 是一款开源的 gc log 本地分析工具:

 

https://github.com/chewiebug/GCViewer

 

下载 jar 包后,直接运行即可启动。

 

 

 

如上图所示,在菜单中勾选想要查看的信息,就可以在图中查看了,而在右侧可以看到详情信息。

 

 

 

欢迎关注微信公众号,以技术为主,涉及历史、人文等多领域的学习与感悟,每周三到七篇推文,全部原创,只有干货没有鸡汤

 

 

 

https://gceasy.io/

https://github.com/chewiebug/GCViewer

http://mail-archives.apache.org/mod_mbox/cassandra-user/201103.mbox/

https://sq.163yun.com/blog/article/170355617443536896

 

 

java 专题






技术帖      log      优化      gc      cms      jjava      性能调优     


京ICP备15018585号