您的位置:首页 > 其它

一次CMS GC问题排查过程(理解原理+读懂GC日志) (顶)

2015-12-03 10:27 891 查看
这个是之前处理过的一个线上问题,处理过程断断续续,经历了两周多的时间,中间各种尝试,总结如下。这篇文章分三部分:
1、问题的场景和处理过程;2、GC的一些理论东西;3、看懂GC的日志
先说一下问题吧
问题场景:线上机器在半夜会推送一个700M左右的数据,这个时候有个数据置换的过程,也就是说有700M*2的数据在heap区域中,线上系统超时比较多,导致了很严重(严重程度就不说了)的问题。
问题原因:看日志,系统接口超时的时候,系统出现了FullGC,这个时候stop-the-world了,也就停机了。分析gc的日志,发现有promotionfailed,根据FullGC触发的条件,这个时候就会出现FullGC了。日志如下:
1
2
2013
-
11
-27T03:
00
:
53.638
+
0800
:
35333.562
:[GC
35333.562
:[ParNew
(promotionfailed):1877376K->1877376K(1877376K),
15.7989680
secs]
35349.361
:[CMS:2144171K->2129287K(2146304K),
10.4200280
sec

s]3514052K->2129287K(4023680K),[CMSPerm:119979K->118652K(190132K)],
26.2193500
secs][Times:user=
30.35
sys=
5.19
,real=
26.22
secs]

问题解决:中间调整过几次,先搞了几台机器做了验证,后来逐步推广的。
1、调大heap区,由原来的4g,调整到5g,young区的大小不变,还是2g,这时候old区就由2g变为3g了(这样保证old区有足够的空间);
2、设置-XX:UseCMSInitiatingOccupancyOnly,其实这个不关这个问题,只是发现半夜CMS进行的有点频繁,就禁止掉了悲观策略;
3、设置CMS区回收的比例,从80%调整到75%,让old区尽早的进行,有足够的空间剩余;

为什么要有GC(垃圾回收)?


JVM通过GC来回收堆和方法区中的内存,GC的基本原理就是找到程序中不再被使用的对象,然后回收掉这些对象占用的内存。

主要的收集器有哪些?
引用计数器和跟踪计数器两种。
引用计数器记录对象是否被引用,当计数器为零时,说明对象已经不再被使用,可以进行回收。java中的对象有复杂的引用关系,不是很适合引用计数器,所以sunjdk中并没有实现这种GC方式。
跟踪收集器,全局记录数据的引用状态,基于一定的条件触发。执行的时候,从根集合开始扫描对象的引用关系,主要有复制(copying)、标记-清除(Mark-Sweep)、标记-压缩(Mark-Compact)那种算法。

跟踪计数器的三种算法简介?
复制:从根集合搜扫描出存活的对象,然后将存活的对象复制到一块新的未使用的空间中,当要回收的空间中存活的对象较少时,比较高效;
标记清除:从根集合开始扫描,对存活的对象进行标记,比较完毕后,再扫描整个空间中未标记的对象,然后进行回收,不需要对对象进行移动;
标记压缩:标记形式和“标记清除”一样,但是回收不存活的对象后,会把所有存活的对象在内存空间中进行移动,好处是减少了内存碎片,缺点是成本比较高;

java内存区域的形式是啥样的?
这里就不再介绍了,之前有一篇文章中专门介绍这个的(http://iamzhongyong.iteye.com/blog/1333100)。

新生代可用的GC?
新生代中对象存活的时间比较短,因此给予Copying算法实现,Eden区域存放新创建的对象,S0和S1区其中一块用于存放在MinorGC的时候作为复制存活对象的目标空间,另外一块清空。
串行GC(SerialGC)比较适合单CPU的情况,可以通过-XX:UseSerialGC来强行制定;
并行回收GC(ParallelScavenge),启动的时候按照设置的参数来划定Eden/S0/S1区域的大小,但是在运行时,会根据MinorGC的频率、消耗时间来动态调整三个区域的大小,可以用过-XX:UseAdaptiveSizePolicy来固定大小,不进行动态调整;
并行GC(ParNew)划分Eden、S1、S0的区域上和串行GC一样。并行GC需要配合旧生代使用CMSGC(这是他和并行回收GC的不同)(如果配置了CMSGC的方式,那么新生代默认采取的就是并行GC的方式);

啥时候会触发MinorGC?
当Eden区域分配内存时,发现空间不足,JVM就会触发MinorGC,程序中System.gc()也可以来触发。

旧生代可用的GC方式有哪几种?
串行GC(SerialMSC)、并行GC(ParallelMSC)、并发GC(CMS);

关于CMS?
采用CMS时候,新生代必须使用SerialGC或者ParNewGC两种。CMS共有七个步骤,只有InitialMarking和FinalMarking两个阶段是stop-the-world的,其他步骤均和应用并行进行。持久代的GC也采用CMS,通过-XX:CMSPermGenSweepingEnabled-XX:CMSClassUnloadingEnabled来制定。在采用cms
gc的情况下,ygc变慢的原因通常是由于oldgen出现了大量的碎片。

为啥CMS会有内存碎片,如何避免?
由于在CMS的回收步骤中,没有对内存进行压缩,所以会有内存碎片出现,CMS提供了一个整理碎片的功能,通过-XX:UseCompactAtFullCollection来启动此功能,启动这个功能后,默认每次执行FullGC的时候会进行整理(也可以通过-XX:CMSFullGCsBeforeCompaction=n来制定多少次FullGC之后来执行整理),整理碎片会stop-the-world.

啥时候会触发CMSGC?
1、旧生代或者持久代已经使用的空间达到设定的百分比时(CMSInitiatingOccupancyFraction这个设置old区,perm区也可以设置);
2、JVM自动触发(JVM的动态策略,也就是悲观策略)(基于之前GC的频率以及旧生代的增长趋势来评估决定什么时候开始执行),如果不希望JVM自行决定,可以通过-XX:UseCMSInitiatingOccupancyOnly=true来制定;
3、设置了-XX:CMSClassUnloadingE考虑nabled这个则考虑Perm区;

啥时候会触发FullGC?
一、旧生代空间不足:java.lang.outOfMemoryError:javaheapspace;
二、Perm空间满:java.lang.outOfMemoryError:PermGenspace;
三、CMSGC时出现promotionfailed和concurrentmodefailure(Concurrentmodefailure发生的原因一般是CMS正在进行,但是由于old区内存不足,需要尽快回收old区里面的死的java对象,这个时候foregroundgc需要被触发,停止所有的java线程,同时终止CMS,直接进行MSC。);
四、统计得到的minorGC晋升到旧生代的平均大小大于旧生代的剩余空间;
五、主动触发FullGC(执行jmap-histo:live[pid])来避免碎片问题;

为啥heap小于3g不建议使用CMSGC这种方式?
http://hellojava.info/?p=142毕大师的这篇文章讲的很清楚。
1、触发比例不好设置,设置大了,那么剩余的空间就少了很多,设置小了,那old区还没放置多少东西,就要进行回收了;
2、CMS进行的时候,是并行的,也就意味着如果过于频繁的话,会和应用的强占CPU;
3、CMS会有内存碎片问题;
4、YGC的速率变慢(由于CMSGC的实现原理,导致对象从新生代晋升到旧生代时,寻找哪里能放下的这个步骤比ParallelOldGC是慢一些的,因此就导致了YGC速度会有一定程度的下降。);

JVM的悲观策略是啥?
所谓的悲观策略(http://tmalltesting.com/archives/663我们性能测试团队一个同学分析的案例),就是JVM不按照JVM指定的参数来进行CMS
GC,而是根据内存情况以及之前回收的方式动态调整,自行进行GC。旧生代剩余的空间(available)大于新生代中使用的空间(max_promotion_in_bytes),或者大于之前平均晋升的old的大小(av_promo),返回false。cmsgc是每隔一个周期(默认2s)就会做一次这个检查,如果为false,则不执行YGC,而触发cmsgc。

我们经常使用的是啥GC方式?
针对目前线上机器的情况(8G的物流内存),heap区一般设置在4g或者5g左右,一般是使用CMSGC,这时候:
young区使用ParNew(并行GC),Old+Perm(需要单独设置)使用CMS,整个堆(young+old+perm)使用MSC((MarkSweepCompact)是CMSGC算法的FullGC算法,单线程回收整个堆,回收过程有严格的步骤。压缩,所以回收完理论上任何Generation都不会有内存碎片)压缩回收的方式。

读懂GC日志?
基本上都是这种格式:回收前区域占用的大小->回收后区域占用的大小(区域设置的大小),占用的时间

1、promotionfailed的一段日志
1
2
2013
-
11
-27T03:
00
:
53.638
+
0800
:
35333.562
:[GC
35333.562
:[ParNew
(promotionfailed):1877376K->1877376K(1877376K),
15.7989680
secs]
35349.361
:[CMS:2144171K->2129287K(2146304K),
10.4200280
sec

s]3514052K->2129287K(4023680K),[CMSPerm:119979K->118652K(190132K)],
26.2193500
secs][Times:user=
30.35
sys=
5.19
,real=
26.22
secs]

解释如下:
1
2
3
4
5
1877376K->1877376K(1877376K),
15.7989680
secsyoung区

2144171K->2129287K(2146304K),
10.4200280
secold区情况

3514052K->2129287K(4023680K)heap区情况

119979K->118652K(190132K)],
26.2193500
secsperm区情况

[Times:user=
30.35
sys=
5.19
,real=
26.22
secs]整个过程的时间消耗

2、一段正常的CMS的日志
1
2
3
4
5
6
7
8
9
10
11
12
13
14
2013
-
11
-27T04:
00
:
12.819
+
0800
:
38892.743
:[GC[
1
CMS-initial-mark:
1547313K(2146304K)]1734957K(4023680K),
0.1390860
secs][Times:user=
0.14
sys=
0.00
,real=
0.14
secs]

2013
-
11
-27T04:
00
:
12.958
+
0800
:
38892.883
:[CMS-concurrent-mark-start]

2013
-
11
-27T04:
00
:
19.231
+
0800
:
38899.155
:[CMS-concurrent-mark:
6.255
/
6.272
secs]
[Times:user=
8.49
sys=
1.57
,real=
6.27
secs]

2013
-
11
-27T04:
00
:
19.231
+
0800
:
38899.155
:[CMS-concurrent-preclean-start]

2013
-
11
-27T04:
00
:
19.250
+
0800
:
38899.175
:[CMS-concurrent-preclean:
0.018
/
0.019
secs]
[Times:user=
0.02
sys=
0.00
,real=
0.02
secs]

2013
-
11
-27T04:
00
:
19.250
+
0800
:
38899.175
:[CMS-concurrent-abortable-preclean-start]

CMS:abortprecleanduetotime
2013
-
11
-27T04:
00
:
25.252
+
0800
:
38905.176
:
[CMS-concurrent-abortable-preclean:
5.993
/
6.002
secs][Times:user=
6.97
sys=
2.16
,real=
6.00
secs]

2013
-
11
-27T04:
00
:
25.253
+
0800
:
38905.177
:[GC[YGoccupancy:
573705
K
(
1877376
K)]
38905.177
:[Rescan(parallel),
0.3685690
secs]
38905.546
:[weakrefsprocessing,
0.0024100
secs]
38905.548
:
[cla

ssunloading,
0.0177600
secs]
38905.566
:[scrubsymbol&stringtables,
0.0154090
secs][
1
CMS-remark:1547313K(2146304K)]2121018K(4023680K),
0.4229380
secs]
[Times:user=
1.41
sys=
0.01
,real=

0.43
secs]

2013
-
11
-27T04:
00
:
25.676
+
0800
:
38905.601
:[CMS-concurrent-sweep-start]

2013
-
11
-27T04:
00
:
26.436
+
0800
:
38906.360
:[CMS-concurrent-sweep:
0.759
/
0.760
secs]
[Times:user=
1.06
sys=
0.48
,real=
0.76
secs]

2013
-
11
-27T04:
00
:
26.436
+
0800
:
38906.360
:[CMS-concurrent-reset-start]

2013
-
11
-27T04:
00
:
26.441
+
0800
:
38906.365
:[CMS-concurrent-reset:
0.005
/
0.005
secs]
[Times:user=
0.00
sys=
0.00
,real=
0.00
secs]

这个是一个正常的CMS的日志,共分为七个步骤,重点关注initial-mark和remark这两个阶段,因为这两个是停机的。
A、[GC[1CMS-initial-mark:1547313K(2146304K)]1734957K(4023680K),0.1390860secs][Times:user=0.14sys=0.00,real=0.14secs]
各个数据依次表示标记前后old区的所有对象占内存大小和old的capacity,整个JavaHeap(不包括perm)所有对象占内存总的大小和JavaHeap的capacity。
B、2013-11-27T04:00:25.253+0800:38905.177:[GC[YGoccupancy:573705K(1877376K)]38905.177:[Rescan(parallel),0.3685690secs]38905.546:[weakrefsprocessing,0.0024100secs]38905.548:[class
unloading,0.0177600secs]38905.566:[scrubsymbol&stringtables,0.0154090secs][1CMS-remark:1547313K(2146304K)]2121018K(4023680K),0.4229380secs][Times:user=1.41sys=0.01,real=0.43secs]
Rescan(parallel)表示的是多线程处理young区和多线程扫描old+perm的卡表的总时间,parallel表示多GC线程并行。
weakrefsprocessing处理old区的弱引用的总时间,用于回收nativememory。
classunloading回收SystemDictionary消耗的总时间。

3、一段正常的YoungGC的日志
1
2
2013
-
11
-27T04:
00
:
07.345
+
0800
:
38887.270
:[GC
38887.270
:[ParNew:
1791076K->170624K(1877376K),
0.2324440
secs]2988366K->1413629K(4023680K),
0.2326470
secs][Times:user=
0.80
sys=
0.00
,real=
0
.

23
secs]

ParNew这个表明是并行的回收方式,具体的分别是young区、整个heap区的情况;

4、一段通过system.gc产生的FullGC日志
1
2013
-
07
-21T17:
44
:
01.554
+
0800
:
50.568
:[FullGC(System)
50.568
:[CMS:
943772K->220K(2596864K),
2.3424070
secs]1477000K->220K(4061184K),[CMSPerm:3361K->3361K(98304K)],
2.3425410
secs][Times:user=
2.33
sys=
0.01
,
real=
2.34
secs]
解释如下:
FullGC(System)意味着这是个system.gc调用产生的MSC。
“943772K->220K(2596864K),2.3424070secs”表示:这次MSC前后old区内总对象大小,old的capacity及这次MSC耗时。
“1477000K->220K(4061184K)”表示:这次MSC前后JavaHeap内总对象大小,JavaHeap的capacity。
“3361K->3361K(98304K)],2.3425410secs”表示:这次MSC前后Perm区内总对象大小,Perm区的capacity。

5、一个特殊的GC日志,根据动态计算直接进行的FullGC(MSC的方式)
1
2013
-
03
-13T13:
48
:
06.349
+
0800
:
7.092
:[GC
7.092
:[ParNew:471872K->471872K(471872K),
0.0000420
secs]
7.092
:
[CMS:366666K->524287K(524288K),
27.0023450
secs]838538K->829914K(996160K),[CMSPerm:3196K->3195K(131072K)],
27.0025170
secs]
ParNew的时间特别短,jvm在minorgc前会首先确认old是不是足够大,如果不够大,这次younggc直接返回,进行MSC。

参考文章:
http://kenwublog.com/docs/java6-jvm-options-chinese-edition.htm
JVM参数大全
http://tmalltesting.com/archives/663悲观策略
http://hellojava.info/?p=142CMSGC不建议3G的原因
毕玄的《分布式java基础》

转载于:http://itindex.net/detail/47030-cms-gc-问题
内容来自用户分享和网络整理,不保证内容的准确性,如有侵权内容,可联系管理员处理 点击这里给我发消息
标签: