jvm GC日志解读-阿里云开发者社区

开发者社区> 开发与运维> 正文

jvm GC日志解读

简介: 0.产生日志 0.1 IDE 运行下面代码会得到gc日志。 0.2 server -Xloggc:../gclogdir/logc.txt   指定gc日志的打印位置,注意必须指定到文件,不能为目录。 当应用重启时,会产生新的gc.log,旧的gc.log自动被重命名为形如 "gc.log.20161103103532"这样的格式。 1.Parallel Scave

0.产生日志

0.1 IDE

运行下面代码会得到gc日志。

0.2 server

-Xloggc:../gclogdir/logc.txt  
指定gc日志的打印位置,注意必须指定到文件,不能为目录。
当应用重启时,会产生新的gc.log,旧的gc.log自动被重命名为形如 "gc.log.20161103103532"这样的格式。

1.Parallel Scavenge

这是一款年轻代GC器。
293.271: [GC [PSYoungGen: 300865K->6577K(310720K)] 392829K->108873K(417472K), 0.0176464 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 
每行是一次GC的信息,以本条为例,解读如下。
293.271是本次GC发生的时间,从jvm启动起开始计时,单位为秒。
GC表示这是一次Minor GC(新生代垃圾收集)。
[PSYoungGen: 300865K->6577K(310720K)] 。格式为[PSYoungGen: a->b(c)].
PSYoungGen,表示新生代使用的是多线程垃圾收集器Parallel Scavenge。a为GC前新生代已占用空间,b为GC后新生代已占用空间。新生代又细分为一个Eden区和两个Survivor区,Minor GC之后Eden区为空,b就是Survivor中已被占用的空间。括号里的c表示整个年轻代的大小。
392829K->108873K(417472K),格式为x->y(z)。x表示GC前堆的已占用空间,y表示GC后堆已占用空间,z表示堆的总大小。
由新生代和Java堆占用大小可以算出年老代占用空间,此例中就是417472K-310720K=106752K。
0.0176464 secs表示本次GC所消耗的时间。
[Times: user=0.06 sys=0.00, real=0.01 secs] 提供cpu使用及时间消耗,user是用户态消耗的cpu时间,sys是系统态消耗的cpu时间,real是实际的消耗时间。

2.Parallel Old

这是Parallel Scavenge收集器的老年代版本。
0.107: [Full GC (Ergonomics) [PSYoungGen: 1664K->0K(8192K)] [ParOldGen: 8200K->9739K(10240K)] 9864K->9739K(18432K), [Metaspace: 2508K->2508K(1056768K)], 0.0038104 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

3.CMS

2016-11-02T10:17:27.849+0800: 48234.161: [GC [1 CMS-initial-mark: 1781099K(2097152K)] 1962885K(4019584K), 0.0530810 secs] [Times: user=0.05 sys=0.00, real=0.05 secs] 
2016-11-02T10:17:27.903+0800: 48234.214: [CMS-concurrent-mark-start]
2016-11-02T10:17:30.294+0800: 48236.606: [CMS-concurrent-mark: 2.384/2.391 secs] [Times: user=2.55 sys=0.04, real=2.39 secs] 
2016-11-02T10:17:30.294+0800: 48236.606: [CMS-concurrent-preclean-start]
2016-11-02T10:17:30.303+0800: 48236.615: [CMS-concurrent-preclean: 0.009/0.009 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
2016-11-02T10:17:30.303+0800: 48236.615: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 2016-11-02T10:17:35.525+0800: 48241.836: [CMS-concurrent-abortable-preclean: 5.216/5.221 secs] [Times: user=5.41 sys=0.06, real=5.23 secs] 
2016-11-02T10:17:35.526+0800: 48241.837: [GC[YG occupancy: 289491 K (1922432 K)]48241.838: [Rescan (parallel) , 0.0558290 secs]48241.893: [weak refs processing, 0.0063180 secs]48241.900: [class unloading, 0.0323730 secs]48241.932: [scrub symbol & string tables, 0.0297790 secs] [1 CMS-remark: 1781099K(2097152K)] 2070590K(4019584K), 0.1310790 secs] [Times: user=0.26 sys=0.00, real=0.13 secs] 
2016-11-02T10:17:35.657+0800: 48241.969: [CMS-concurrent-sweep-start]
2016-11-02T10:17:36.176+0800: 48242.488: [CMS-concurrent-sweep: 0.503/0.519 secs] [Times: user=0.52 sys=0.01, real=0.52 secs] 
2016-11-02T10:17:36.176+0800: 48242.488: [CMS-concurrent-reset-start]
2016-11-02T10:17:36.183+0800: 48242.495: [CMS-concurrent-reset: 0.007/0.007 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 

一共经历 了4个阶段。需要关注的耗时为初始标记重新标记,低于0.2秒就没什么问题。
[CMS-xxx   1781099K(2097152K)] 1962885K(4019584K),形如[CMS-xxx   a(b)] c(d)
a: old区占用大小
b: old区总大小
c: heap占用大小
d: heap 总大小
[YG occupancy: 289491 K (1922432 K)] ,形如 [YG occupancy: a (b)]
a: young区占用大小
b: yong区总大小

3.1 CMS-initial-mark

此阶段暂停工作线程,用时0.05秒。

3.2 CMS-concurrent-mark

与工作线程并发运行。

3.3 CMS-remark 

此阶段暂停工作线程,用时0.13秒。

3.4 CMS-concurrent-sweep

与工作线程并发运行。

4. -XX:+PrintTenuringDistribution -XX:+PrintHeapAtGC

2016-11-03T14:41:12.877+0800: 14740.294: [GC 14740.295: [ParNew
Desired survivor size 178946048 bytes, new threshold 16 (max 20)
- age   1:   12374344 bytes,   12374344 total
- age   2:    2538032 bytes,   14912376 total
- age   3:    2081880 bytes,   16994256 total
- age   4:     290784 bytes,   17285040 total
- age   5:     787312 bytes,   18072352 total
- age   6:     450520 bytes,   18522872 total
- age   7:     335016 bytes,   18857888 total
- age   8:     661552 bytes,   19519440 total
- age   9:    1021048 bytes,   20540488 total
- age  10:     130816 bytes,   20671304 total
- age  11:     172536 bytes,   20843840 total
- age  12:     384968 bytes,   21228808 total
- age  13:     556328 bytes,   21785136 total
- age  14:      99112 bytes,   21884248 total
- age  15:   19091864 bytes,   40976112 total
: 3551236K->58224K(3844800K), 0.0259700 secs] 5186234K->1693221K(5941952K), 0.0262100 secs] [Times: user=0.08 sys=0.00, real=0.03 secs] 
Heap after GC invocations=73 (full 2):
 par new generation   total 3844800K, used 58224K [0x0000000668000000, 0x0000000768000000, 0x0000000768000000)
  eden space 3495296K,   0% used [0x0000000668000000, 0x0000000668000000, 0x000000073d560000)
  from space 349504K,  16% used [0x0000000752ab0000, 0x000000075638c030, 0x0000000768000000)
  to   space 349504K,   0% used [0x000000073d560000, 0x000000073d560000, 0x0000000752ab0000)
 concurrent mark-sweep generation total 2097152K, used 1634997K [0x0000000768000000, 0x00000007e8000000, 0x00000007e8000000)
 concurrent-mark-sweep perm gen total 274488K, used 197983K [0x00000007e8000000, 0x00000007f8c0e000, 0x0000000800000000)
}
{Heap before GC invocations=73 (full 2):
 par new generation   total 3844800K, used 3553520K [0x0000000668000000, 0x0000000768000000, 0x0000000768000000)
  eden space 3495296K, 100% used [0x0000000668000000, 0x000000073d560000, 0x000000073d560000)
  from space 349504K,  16% used [0x0000000752ab0000, 0x000000075638c030, 0x0000000768000000)
  to   space 349504K,   0% used [0x000000073d560000, 0x000000073d560000, 0x0000000752ab0000)
 concurrent mark-sweep generation total 2097152K, used 1634997K [0x0000000768000000, 0x00000007e8000000, 0x00000007e8000000)
 concurrent-mark-sweep perm gen total 274488K, used 197985K [0x00000007e8000000, 0x00000007f8c0e000, 0x0000000800000000)


版权声明:本文内容由阿里云实名注册用户自发贡献,版权归原作者所有,阿里云开发者社区不拥有其著作权,亦不承担相应法律责任。具体规则请查看《阿里云开发者社区用户服务协议》和《阿里云开发者社区知识产权保护指引》。如果您发现本社区中有涉嫌抄袭的内容,填写侵权投诉表单进行举报,一经查实,本社区将立刻删除涉嫌侵权内容。

分享:
开发与运维
使用钉钉扫一扫加入圈子
+ 订阅

集结各类场景实战经验,助你开发运维畅行无忧

其他文章