记一次JVM GC日志分析

这几天在准备升级JDK版本到1.6,对目前线上JVM(版本是1.5.0_08-b03) GC日志进行了分析,发现一些参数设置不太合理的地方,有待后续通过数据来进行验证。

1.原始GC日志(通过JVM配置GC Print参数获取GC日志)

695.775: [GC 695.776: [ParNew: 130944K->0K(131008K), 0.0174100 secs] 432961K->302710K(786368K), 0.0175930 secs]697.323: [GC [1 CMS-initial-mark: 302710K(655360K)] 348624K(786368K), 0.1140530 secs]697.438: [CMS-concurrent-mark-start]699.494: [GC 699.494: [ParNew: 130944K->0K(131008K), 0.0115290 secs] 433654K->303891K(786368K), 0.0116990 secs]701.381: [CMS-concurrent-mark: 1.204/3.944 secs]701.381: [CMS-concurrent-preclean-start]701.382: [CMS-concurrent-preclean: 0.000/0.000 secs]701.420: [CMS-concurrent-abortable-preclean-start]701.420: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs]703.302: [GC 703.302: [ParNew: 130944K->0K(131008K), 0.0161480 secs] 434835K->305889K(786368K), 0.0163490 secs]705.202: [GC[YG occupancy: 68582 K (131008 K)]705.202: [Rescan (parallel) , 0.1094800 secs]705.312: [weak refs processing, 0.0446420 secs] [1 CMS-remark: 305889K(655360K)] 374472K(786368K), 0.1543650 secs]705.360: [CMS-concurrent-sweep-start]705.644: [CMS-concurrent-sweep: 0.284/0.284 secs]705.644: [CMS-concurrent-reset-start]705.654: [CMS-concurrent-reset: 0.010/0.010 secs]706.985: [GC 706.985: [ParNew: 130924K->0K(131008K), 0.0193060 secs] 432106K->302870K(786368K), 0.0195480 secs]708.540: [GC [1 CMS-initial-mark: 302870K(655360K)] 350092K(786368K), 0.1140590 secs]708.654: [CMS-concurrent-mark-start]710.647: [GC 710.647: [ParNew: 130944K->0K(131008K), 0.0081390 secs] 433814K->303960K(786368K), 0.0083430 secs]712.560: [CMS-concurrent-mark: 1.314/3.906 secs]712.560: [CMS-concurrent-preclean-start]712.560: [CMS-concurrent-preclean: 0.000/0.000 secs]712.615: [CMS-concurrent-abortable-preclean-start]712.615: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs]713.567: [GC 713.567: [ParNew: 130944K->0K(131008K), 0.0104890 secs] 434904K->305163K(786368K), 0.0107090 secs]715.109: [GC[YG occupancy: 68948 K (131008 K)]715.109: [Rescan (parallel) , 0.0884690 secs]715.198: [weak refs processing, 0.0441790 secs] [1 CMS-remark: 305163K(655360K)] 374111K(786368K), 0.1329350 secs]715.243: [CMS-concurrent-sweep-start]715.445: [CMS-concurrent-sweep: 0.203/0.203 secs]715.445: [CMS-concurrent-reset-start]715.454: [CMS-concurrent-reset: 0.009/0.009 secs]

2.日志分析报告

针对原始GC日志,分别用下面两种工具做了分析,其中gcviewer分析还是比较具体的,就是解析日志时会有些异常,但不影响最后的结果。

(1)通过gcviewer分析:

图1(顶部的黑色线都代表Full GC,也可以理解为Major GC,是根据日志中的CMS GC统计的;底部灰色线代表的是Minor GC)

图2

图3

可以看到Full GC非常多,占所有pause时间比达到65.9%,这是有问题的,GC应该尽可能在年轻代完成,而不是到年老代,这个在第3部分参数说明中会提到。

(2)通过GarbageCat分析:

========================================SUMMARY:========================================# GC Events: 172925GC Event Types: CMS_INITIAL_MARK, CMS_CONCURRENT, CMS_SERIAL_OLD_CONCURRENT_MODE_FAILURE, PAR_NEW, CMS_REMARKMax Heap Space: 1079084KMax Heap Occupancy: 716725KMax Perm Space: 98304KMax Perm Occupancy: 8993KThroughput: 97%Max Pause: 426 msTotal Pause: 9033244 msFirst Timestamp: 250 msLast Timestamp: 342994691 ms

从这里主要看pause time时间,分析报告中还有一部分不能处理的,这些日志现在还没找到最终原因:

========================================30 UNIDENTIFIED LOG LINE(S):========================================39629.723: [Full GC 39629.723: [CMS[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor6720]40724.189: [Full GC 40724.189: [CMS[Unloading class sun.reflect.GeneratedMethodAccessor1945]40785.929: [Full GC 40785.929: [CMS (concurrent mode failure)[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor10169]40922.428: [Full GC 40922.428: [CMS (concurrent mode failure)[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor10175]124477.019: [Full GC 124477.019: [CMS[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor33989]124997.427: [Full GC 124997.427: [CMS[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor34622]125059.257: [Full GC 125059.257: [CMS (concurrent mode failure)[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor34638]125348.006: [Full GC 125348.006: [CMS[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor34644]125940.674: [Full GC 125940.674: [CMS[Unloading class sun.reflect.GeneratedMethodAccessor2017]126047.093: [Full GC 126047.093: [CMS[Unloading class sun.reflect.GeneratedMethodAccessor5743]128938.724: [Full GC 128938.724: [CMS[Unloading class sun.reflect.GeneratedMethodAccessor5715]209586.704: [Full GC 209586.704: [CMS[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor58696]210272.871: [Full GC 210272.872: [CMS (concurrent mode failure)[Unloading class sun.reflect.GeneratedMethodAccessor5749]211428.317: [Full GC 211428.318: [CMS[Unloading class sun.reflect.GeneratedMethodAccessor7545]212198.995: [Full GC 212198.995: [CMS (concurrent mode failure)[Unloading class sun.reflect.GeneratedMethodAccessor5806]212408.355: [Full GC 212408.355: [CMS[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor58795]212525.304: [Full GC 212525.304: [CMS[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor58807]212819.763: [Full GC 212819.763: [CMS[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor58817]212881.623: [Full GC 212881.623: [CMS (concurrent mode failure)[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor58821]214567.777: [Full GC 214567.778: [CMS[Unloading class sun.reflect.GeneratedMethodAccessor1643]214980.856: [Full GC 214980.856: [CMS[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor58897]215119.546: [Full GC 215119.546: [CMS (concurrent mode failure)[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor58903]294794.469: [Full GC 294794.469: [CMS[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor81521]298186.036: [Full GC 298186.036: [CMS (concurrent mode failure)[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor81595]300171.660: [Full GC 300171.660: [CMS (concurrent mode failure)[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor81708]300318.420: [Full GC 300318.420: [CMS (concurrent mode failure)[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor81738]300380.550: [Full GC 300380.550: [CMS (concurrent mode failure)[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor81772]300756.398: [Full GC 300756.398: [CMS (concurrent mode failure)[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor81744]300818.348: [Full GC 300818.348: [CMS (concurrent mode failure)[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor81788]301812.025: [Full GC 301812.025: [CMS[Unloading class sun.reflect.GeneratedMethodAccessor10606]

3.问题根源(当前参数配置及说明,其中红色标注的是设置不妥的地方)

都成为命途中美丽的点缀,看天,看雪,安安静静,不言不语都是好风景。

记一次JVM GC日志分析

相关文章:

你感兴趣的文章:

标签云: