Java CMS GC 361s引发的血案

  1. 云栖社区>
  2. 博客>
  3. 正文

Java CMS GC 361s引发的血案

雪地脚印 2016-05-17 17:18:46 浏览2307
展开阅读全文

问题现象

当前项目是基于GemFire集群开发,然而我们偶尔会遇到一个节点掉出集群的情况。在分析问题过程中,我们发现在该节点(N1)掉出去之前发生了如下事件。
首先,N1最后的log时间在2015/07/23 06:25:35.544,并且直到2015/07/23 06:31:44.624(6分钟以后)在开始出现下一个log,接收到Primary Locator发出的机群中新的节点视图,处理Primary Locator给他的消息说它“Failed to respond within ack-wait-threshold”。此时它想再向N2发起连接并发送数据时,虽然重连成功,但是N2已经认为它已经不在集群中了,因而拒绝它的请求,所以它自己退出了集群:
[warning 2015/07/23 06:31:46.872 EDT #Node1 Name# <P2P message reader for #Node2# SHARED=true ORDERED=true UID=27> tid=0x127] Attempting TCP/IP reconnect to  #Node2#
[info 2015/07/23 06:31:46.977 EDT #Node1 Name# <P2P message reader for #Node2# SHARED=true ORDERED=true UID=27> tid=0x127] Successfully reconnected to member #Node2#
[severe 2015/07/23 06:31:47.007 EDT #Node1 Name# <CloserThread> tid=0x4052] Membership service failure: Channel closed: com.gemstone.gemfire.ForcedDisconnectException: This member has been forced out of the distributed system.  Reason='this member is no longer in the view but is initiating connections'

而在这6分钟期间,N2和Primary Locator之间进行了如下交互:
在2015/07/23 06:27:07.587,Primary Locator发现N1在12,437ms内没有相应它的ACK(view_ack_collection_timeout,默认12,437ms):
[warning 2015/07/23 06:27:07.587 EDT #Locator Name# <ViewHandler> tid=0xc2] failed to collect all ACKs (22) for view [#Primary Locator#] after 12,437ms, missing ACKs from [#Node1#]
并且在1分钟后,N2向Primary Locator报告N1没有响应了,因为N1在180s(ack-wait-threshold)内没有相应):
[info 2015/07/23 06:28:53.131 EDT #Locator Name# <UDP ucast receiver> tid=0x1f] Received Suspect notification for member(s) [#Node1#] from #Node2#.  Reason=Failed to respond within ack-wait-threshold
此时Primary Locator向N1发送一个are-you-dead验证消息,检查它是否真的没有响应了,并且在5127ms内N1还是没有响应,因而Primary Locator认为N1已经离开了集群:
[info 2015/07/23 06:28:58.389 EDT #Locator Name# <VERIFY_SUSPECT.TimerThread> tid=0x2356] No suspect verification response received from #Node1# in5127 milliseconds: I believe it is gone.
此时Primary Locator向集群中的其他节点发送新的节点视图,并报告N1已经crash,并且把它从JGroup View中移除:
[info 2015/07/23 06:28:58.678 EDT #Locator Name# <ViewHandler> tid=0xc2] Membership: sending new view [[#Primary Locator#] [...,#Node2#,...] crashed mbrs: [#Node1#]] (21 mbrs)
[info 2015/07/23 06:28:58.781 EDT #Locator Name# <View Message Processor> tid=0x2e] Member at #Node1# unexpectedly left the distributed cache: departed JGroups view
而在N1开始有相应的时候,Primary Locator收到其他节点的消息说N1向他们发起连接,但是它依然向他们发起了连接,所以让Primary Locator把它移除:
[warning 2015/07/23 06:31:45.015 EDT #Locator Name# <UDP ucast receiver> tid=0x1f] Membership: received request to remove #Node1# from #Node3# Reason=this member is no longer in the view but is initiating connections.
[warning 2015/07/23 06:31:45.108 EDT #Locator Name# <UDP ucast receiver> tid=0x1f] Membership: received request to remove #Node1# from #Node4# Reason=this member is no longer in the view but is initiating connections.

问题分析

开始我们一直觉得这是网络的问题,因为N1不可能在3分钟内没有给N2响应,并且当Locator向它询问are-you-dead的时候它还是没有相应,而在当前这个case下,它竟然有6分钟没有相应,那么长的时间里这个节点会处理什么事情呢?因而我们用了各种工具查网络在出问题的那个点上的情况,有没有中断、包丢失之类的,然而一无所获,直到我们从GC的日志中找到了这句话:
2015-07-23T06:25:43.548-0400: [GC [ParNew (promotion failed): 943744K->943744K(943744K), 3.9544520 secs][CMS2015-07-23T06:31:11.405-0400: [CMS-concurrent-sweep: 327.407/334.829 secs] [Times: user=8.42 sys=1.77, real=334.78 secs]
(concurrent mode failure): 8881917K->1234174K(9437184K), 357.1201510 secs] 9645662K->1234174K(10380928K), [CMS Perm : 67582K->63968K(111848K)], 361.0747320 secs] [Times: user=10.25 sys=1.59, real=361.02 secs]

要不是亲眼所见,我真不敢相信GC会用掉6分多钟的时间!!自己之前也有看过GC相关的书籍,但是一直觉得GC很快(估计是看的不够多),因而并没有引起很大的重视,然后我去翻了一下以前GC的日志,发现我们它不是一个可以随便忽略的操作,即使是ParNew GC都有可能花费7s的时间!!而且平时也一般都在二三十毫秒的数量级(这是我们的测试环境,生产环境的性能要好很多,基本在几个毫秒的级别)。
2015-07-23T05:47:05.774-0400: [GC [ParNew: 943744K->75951K(943744K), 7.4119250 secs] 8202594K->7383241K(10380928K), 7.4120460 secs] [Times: user=0.31 sys=0.06, real=7.41 secs
2015-07-23T05:51:54.529-0400: [GC [ParNew: 914863K->80478K(943744K), 0.0272180 secs] 8222153K->7387768K(10380928K), 0.0273280 secs] [Times: user=0.13 sys=0.00, real=0.02 secs] 
2015-07-23T05:59:54.278-0400: [GC [ParNew: 919390K->53806K(943744K), 0.0572200 secs] 8226680K->7361097K(10380928K), 0.0573110 secs] [Times: user=0.19 sys=0.00, real=0.06 secs] 
2015-07-23T06:07:41.663-0400: [GC [ParNew: 892718K->42574K(943744K), 1.8347990 secs] 8200009K->7387109K(10380928K), 1.8348970 secs] [Times: user=0.30 sys=0.06, real=1.84 secs
而CMS的CMS-concurrent-sweep GC经常要花费10s+的时间,虽然这不是一个STW(Stop The World)操作,但是这个时间也是已经很长了,会影响整体性能(它需要耗费CPU,我们当前设置4个CPU做GC)。

问题解决

要减少GC的停顿时间,我觉得可以从三个方向入手:

  1. 最直观的当然是减少一个进程的总内存大小。
  2. 调节JVM的参数,减少GC的停顿时间,避免Full GC。
  3. 减少类的创建,进而减少GC次数,避免Full GC。

然而在我们的系统中GC花费那么长的时间,当然是和我们的内存大小设置有关系,因为我们的数据节点每个内存大小10G,其中Young Gen:1G,Perm Gen:200M,Old Gen:~9G,因而做一次Full GC当然是比较费时间的。所以一种最简单的做法当然是减少内存,然而减少一个数据节点的内存意味着我们需要增加节点的个数,不然无法保证GemFire集群能存下所有的数据,而增加节点个数又会带来新的问题,如增加运帷难度,节点出错的概率提高,提高集群的通信成本,增加MetaData的存储空间等,因而这个目前不是好的方向。所以我们只能寻求2和3的方案。

调节JVM的参数

当前GemFire节点退出集群问题的直接原因是因为ParNew GC promotion失败,从而引起CMS GC,然而CMS GC又产生concurrent mode failure,进而引起STW(Stop The World)的Full GC引起的,因而比较直接的方案就是调节JVM的参数,以减少GC停顿时间,并且尽量避免Full GC,即方案2。对JVM参数调节首先可以从选择不同的GC收集器开始,如对Young Gen的Serial、ParNew、Parallel Scavenge,对Old Gen的CMS、Serial Old(MSC)、Parallel Old,或者是直接用G1,我们目前使用ParNew+CMS,已经使用多年,而且老板属于保守型,这条路也基本走不通,因而这里只介绍ParNew+CMS的GC。

ParNew收集器调节

对ParNew收集器,它是Serial收集器的多线程版本,使用复制算法,由于每次GC的存活对象很少,因而它使用两个Survivor和一个Eden实现,默认情况下Survivor和Eden的比例是1:8,因而这里可以调节的参数有Young Gen的总大小(-XX:NewSize=1024M -XX:MaxNewSize=1024M),Survivor和Eden的比例(-XX:SurvivorRatio=8),收集线程数(-XX:ParallelGCThreads,默认与CPU数量相同),对对象大小超过一定数值的直接晋升到老年代(-XX:PretenureSizeThreshold,无默认值),设置晋升到老年代的年龄(-XX:MaxTenuringThreshold,默认15),开启Promotion失败的担保(-XX:+HandlePromotionFailure,1.6默认开启)。在我们的设置中,Young Gen的总大小和最大大小设置为一样(1G)以减少动态分配的开销,然而在观察中发现102.4M的Survivor大小有些时候并不足以存放所有的存活对象,因而可以适当增加Young Gen的大小:
2015-07-23T05:25:57.260-0400: [GC [ParNew: 932867K->104832K(943744K), 0.3366410 secs] 7881112K->7169555K(10380928K), 0.3367350 secs] [Times: user=0.59 sys=0.01, real=0.34 secs] 
如该GC日志显示有Young Gen内存从932867K降到104832K(102.375M),减少828035K,然而实际内存从7881112K下降到7169555K,只减少了711557K,即有116478K的对象直接晋升到了Old Gen(这些对象有部分可能是已经到了晋升的年龄,然而由于Minor GC后Survivor几乎满了,因而基本可以确定有部分对象并没有到达晋升年龄而直接晋升了)。
在观察ParNew GC的日志后,我发现大部分情况user和real的时间保持在1:1到5:1之间,然而其实我们有8个CPU,即8个CPU并没有很好的发生作用,反而因为线程交互开销而影响了它的性能,因而可以设置4个线程来回收;另外,通过日志我还发现有些时候real的时间要远远超过user的时间:
2015-07-23T05:47:05.774-0400: [GC [ParNew: 943744K->75951K(943744K), 7.4119250 secs] 8202594K->7383241K(10380928K), 7.4120460 secs] [Times: user=0.31 sys=0.06, real=7.41 secs
2015-07-23T06:21:44.474-0400: [GC [ParNew: 897098K->87972K(943744K), 0.0572610 secs] 8806476K->7997350K(10380928K), 0.0573410 secs] [Times: user=0.33 sys=0.00, real=0.05 secs] 
2015-07-23T06:21:45.974-0400: [GC [ParNew: 926884K->104832K(943744K), 2.4767030 secs] 8836262K->8033953K(10380928K), 2.4767970 secs] [Times: user=0.66 sys=0.06, real=2.47 secs] 
2015-07-23T06:21:49.870-0400: [GC [ParNew: 943744K->104832K(943744K), 4.4340200 secs] 8872865K->8058383K(10380928K), 4.4341130 secs] [Times: user=0.52 sys=0.06, real=4.44 secs
2015-07-23T06:21:55.408-0400: [GC [ParNew: 943744K->104832K(943744K), 3.3951690 secs] 8897295K->8084732K(10380928K), 3.3952610 secs] [Times: user=0.78 sys=0.09, real=3.39 secs] 
2015-07-23T06:21:59.836-0400: [GC [ParNew: 943744K->104832K(943744K), 8.0761790 secs] 8923644K->8137862K(10380928K), 8.0762750 secs] [Times: user=0.73 sys=0.10, real=8.07 secs] 
2015-07-23T06:22:09.037-0400: [GC [ParNew: 943744K->104832K(943744K), 14.2921950 secs] 8976774K->8205723K(10380928K), 14.2923060 secs] [Times: user=1.54 sys=0.12, real=14.29 secs
2015-07-23T06:22:24.289-0400: [GC [ParNew: 943744K->104832K(943744K), 3.4770350 secs] 9044635K->8223741K(10380928K), 3.4771560 secs] [Times: user=0.26 sys=0.05, real=3.47 secs] 
2015-07-23T06:22:38.464-0400: [GC [ParNew: 943744K->104832K(943744K), 0.8620630 secs] 9062653K->8225897K(10380928K), 0.8621870 secs] [Times: user=0.21 sys=0.01, real=0.86 secs] 
2015-07-23T06:22:40.993-0400: [GC [ParNew: 943744K->60810K(943744K), 0.0665070 secs] 9064809K->8181875K(10380928K), 0.0665910 secs] [Times: user=0.25 sys=0.00, real=0.06 secs] 
这里大部分Survivor不足以存放所有的存活对象,然而并不是所有的,如第一条就不是,对这个我一直很纳闷,在网上也没有找到非常可能的答案,但是大概这个答案看起来比较靠谱,简单来说,就是当时有很多page faults,这个也符合我们当时的情况,因为这台机器原本内存不是那么足,因而偶尔会出现内存swap,而且在这种情况下,所有的sys时间相对都比较长,也是一个佐证;另外也有人解释说ParNew在Stop-The-World之前要确保所有JNI线程都暂停下来,因而需要等待到达safepoint,这个貌似不太像我们遇到的情况,因为我们没有使用外部的JNI,如果内部自己的JNI应该不至于有那么大的影响(但是这个点正好说明我们使用JNI的时候要非常小心,如果有函数运行时间太长会影响JVM的稳定性,甚至让JVM没有响应,因为它在GC的时候要等这个长时间的JNI方法结束,或到达safepoint。更正:这里对safepoint有这样的解释:A point during program execution at which all GC roots are known and all heap object contents are consistent. From a global point of view, all threads must block at a safepoint before the GC can run. (As a special case, threads running JNI code can continue to run, because they use only handles. During a safepoint they must block instead of loading the contents of the handle.) From a local point of view, a safepoint is a distinguished point in a block of code where the executing thread may block for the GC. Most call sites qualify as safepoints. There are strong invariants which hold true at every safepoint, which may be disregarded at non-safepoints. Both compiled Java code and C/C++ code be optimized between safepoints, but less so across safepoints. The JIT compiler emits a GC map at each safepoint. C/C++ code in the VM uses stylized macro-based conventions (e.g., TRAPS) to mark potential safepoints.,所以看起来这个论断是有问题的)。ParNew暂停的时间都比较短,而且在大部分情况下,或者在其他内存够用的集群中我们没有遇到那么久的GC时间,因而基本不需要过多调节,所以其他都保持了它的默认值。
更正:前几天我们再次发现ParNew GC用去186.63s:
2015-08-07T14:57:22.317+0100: [GC[ParNew: 845794K->88289K(943744K), 186.6537260 secs] 6808480K->6087745K(10380928K), 186.6540490 secs][Times: user=1703.17 sys=194.13, real=186.63 secs]
通过一些系统工具,我们发现在问题发生的时候,当时那台机器有26%左右的Swap内存,并且有很高的page fault,因而我们基本能肯定这是内存数据被换出到Swap然后在GC的时候产生page fault引起的。并且在这里还提及到了swap中每4KB数据会增加10ms的GC时间:
A very high sys time suggests the OS is struggling with the application. I would make sure there is no chance the application has been partially swapped to disk as it must be completely in main memory for the GC to run is a reasonable time. Every 4 KB swapped to disk and add 10 ms to the GC time.
因而我们基本能肯定发生那么长的时间就是因为内存swap引起的,据说在Cassandra调优时有些直接把虚拟内存禁掉,以防出现类似的问题。

CMS收集器调节

重点当然是要调节CMS收集器,即要避免它在收集时停顿过长,更要避免产生promotion failed和concurrent mode failure的情况,因为这两种情况发生后都会引起CMS做Stop-The-World GC,其中第二中情况在做GC时还会做整理(Compact),因而会有更久的停顿,而我们这次是两种情况同时遇到了。要避免这两种情况的发生需要先理解为什么会发生这两种情况。

首先,我们来看看promotion failed发生的情况:
我们知道当对象到一定的年龄,或者在某次回收过程中一个Survivor无法装下所有存活的对象,或者一个对象的大小超过-XX:PretenureSizeThreshold设置的值,就会被promote到Old Gen中,而在promote过程中如果Old Gen无法装下所有的内存时就会产生promotion failed(这里说CMS是根据预估的值:Modern CMS collector estimates size of objects to be promoted using statistics from previous collections. If old space does not have enough free bytes to hold estimated promotion amount, concurrent mode failure will be raise.但是我的理解是这是ParNew做的GC,为什么由CMS来预估?所以应该是ParNew把需要promote的对象传递给CMS,然后CMS做预估决定是否有足够多的内存存放这些新promote的对象),此时就会先做一遍CMS GC,然后将新promote的对象存放到Old Gen中,由于这属于ParNew GC的范围,因而这次的CMS GC依然处于STW状态,因而这会花比较久的时间。如这次的ParNew GC,花费5.75s:
2015-07-20T08:23:00.028-0400: [GC [ParNew (promotion failed): 844305K->841244K(943744K), 0.2358120 secs][CMS: 6282619K->1891959K(9437184K), 5.5098940 secs] 7126660K->1891959K(10380928K), [CMS Perm : 67716K->66078K(112860K)], 5.7458460 secs] [Times: user=4.77 sys=0.02, real=5.75 secs]

2015-07-20T08:23:06.532-0400: [GC [ParNew: 838912K->7606K(943744K), 0.0063650 secs] 2730871K->1899566K(10380928K), 0.0065380 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]

我们当前的设置:-XX:CMSInitiatingOccupancyFraction=79 -XX:+UseCMSInitiatingOccupancyOnly,也就是只有到Old Gen占用79%后才会触发CMS GC,这里只占66.57%,因而还没能触发CMS GC,然而此时ParNew GC只回收了3061K的对象,还有841244K的对象存活,而一个Survivor只有104857.6K大小,此时需要promote大概736386.4K大小的数据到Old Gen中,此时Old Gen还有(9437184K-6282619K=3154565K)大小的内存,虽然远远大于被promote的对象,但是我们知道CMS采用标记-清除(Mark-Sweep)算法,而不主动整理(Compact),但是它在每次回收时会合并相邻的内存空间,然而跑久了难免会产生内存碎片,也就是说此时内存碎片已经很多了,无法容纳新promote的对象,要不就是新promote的对象大小太大,或者碎片太小,因而需要出发一次CMS GC来释放一些空间(此时发生的CMS是不是已经退化成Serial Old收集器算法了?即在收集的过程还是整理?),以保证能存放下所有新promote出的对象。这里GC日志中并没有显示出什么这次ParNew GC后,Young Gen还剩下多少内存,但是根据下一次ParNew GC的初始大小是838912K,小于之前存活下来的对象(841244K),因而我们可以确定这次GC的结果是把多余的对象promtoe到Old Gen中了。
所以根据分析,我们可以从两个方向调节参数:
1. 降低CMS GC的阈值。
2. 提前减少Old Gen中的碎片,即让CMS GC做整理。
对降低CMS GC阈值,我们可以调节参数:-XX:CMSInitiatingOccupancyFraction,默认大小68,我们可以将它设置成60。对提前减少Old Gen的碎片,这个比较麻烦,我们不想每次CMS GC都做整理(Compact),因而这会比较浪费,会增加GC总体的时间以及停顿的时间,而且也比较危险,因为万一某次整理时间太长会引起集群的不稳定(可以设置-XX:UseCMSCompactAtFullCollection来实现这个功能)。还有一种办法是设置每经历N次CMS后做一次整理,通过-XX:CMSFullGCsBeforeCompaction=<N>来设置,这个相对可以接受一些。当然如果能找到一个相对空闲的时间手动触发一次Full GC,并且确保让它能触发整理(这个目前还没有找到合适的方法,JConsole提供的GC按钮是一个可选项,但是不确定。我做了一下尝试:

2015-07-31T16:04:49.183+0800: [Full GC (System) [CMS: 3861443K->1072505K(9437184K), 2.9535440 secs] 4458634K->1072505K(10380928K), [CMS Perm : 68183K->67112K(112880K)], 2.9537000 secs] [Times: user=2.94 sys=0.00, real=2.95 secs]
看起来是减少了不少内存,按日志的格式,看起来像是Serial Old的算法?另外,使用这个功能要确保-XX:-DisableExplicitGC是关闭的,虽然这就是默认值)。

值得注意的是,promotion failed的情况也可以产生很长的停顿,这里我们看到总的时间是378.38s,user的时间只有5.56s,而sys的时间高达1.80s,看起来和ParNew长时间停顿的情况类似,即产生了对象换出到虚拟内存了?
2015-07-22T08:20:04.712-0400: [GC [ParNew (promotion failed): 842147K->839927K(943744K), 0.2343990 secs][CMS: 7382737K->1921345K(9437184K), 378.2061130 secs] 8224802K->1921345K(10380928K), [CMS Perm : 67406K->66061K(112260K)], 378.4406520 secs] [Times: user=5.56 sys=1.80, real=378.38 secs]


关于产生promotion failed,这里还有更详细的解释,如涉及到PLAB(Promotion Local Allocation Buffer)的介绍等,以及这里是对它的更正。值得注意的是,CMS在管理内存中使用空闲列表的方式,然而这种方式可能会存在某些问题,如这句话所说(具体就不展开了):
CMS memory manager is using separate free lists for different size of chunks. Using these free lists, it can effectively fill small holes in fragmented memory space with objects of exact size. This technique is known to be fairly effective (and widely used in C/C++ memory managers). But, surprisingly, it doesn't seems to work well for JVM in many real live situations.


然后,再来看看concurrent mode failure的情况:
依然是这篇文章,作者说concurrent mode failure是在Young GC发生前,它会预估Old Gen是否有足够的空间存放从Young Gen中promote上来的对象,CMS收集器根据之前统计来预估这些对象的大小,如果Old Gen没有足够的空间存放这个预估的值,就会发生concurrent mode failure。此时不一定会产生Full GC,有些时候JVM只是等待当前并行收集完成,但是用户程序此时还是会STW直到这次收集技术。
At beginning  of each young GC, collector should ensure that there is enough free memory in old space to promote aged objects from young space. Modern CMS collector estimates size of objects to be promoted using statistics from previous collections. If old space does not have enough free bytes to hold estimated promotion amount, concurrent mode failure will be raise. Concurrent mode failure doesn't necessary lead to Full GC, in certain cases JVM will just wait for concurrent collection cycle to finish, but application will remain in STW pause until young collection will be finished.

然而根据我的观察,concurrent mode failure都是发生在CMS已经开始,但是在中间阶段,出现ParNew的promotion failed。
如这是发生在CMS-concurrent-abortable-preclean阶段

2015-07-19T06:17:04.919-0400: [GC [1 CMS-initial-mark: 7612366K(9437184K)] 7726317K(10380928K), 0.0208180 secs] [Times: user=0.02 sys=0.01, real=0.02 secs] 
2015-07-19T06:17:05.275-0400: [CMS-concurrent-mark: 0.334/0.334 secs] [Times: user=1.62 sys=0.02, real=0.33 secs] 
2015-07-19T06:17:05.294-0400: [CMS-concurrent-preclean: 0.019/0.019 secs] [Times: user=0.04 sys=0.00, real=0.02 secs] 
2015-07-19T06:17:05.936-0400: [GC [ParNew (promotion failed): 943744K->943744K(943744K), 0.2429280 secs][CMS2015-07-19T06:17:06.239-0400: [CMS-concurrent-abortable-preclean: 0.493/0.945 secs] [Times: user=1.54 sys=0.06, real=0.95 secs] 
 (concurrent mode failure): 7747387K->1603792K(9437184K), 5.4145810 secs] 8556110K->1603792K(10380928K), [CMS Perm : 65203K->63169K(108704K)], 5.6576200 secs] [Times: user=4.66 sys=0.01, real=5.66 secs] 
这是ParNew发生时,CMS-concurrent-preclean结束不久,此时ParNew花费0.2429280s完成,想premote一些对象而失败,因而CMS在06:17:06.239完成步骤:CMS-concurrent-abortable-preclean,然而这个步骤结束后,依然无法容纳promote上来的对象,所以需要做一个Full GC,完成以后Old Gen内存从7747387K下降到1603792K,总内存从8556110K下降到1603792K,即将所有Young Gen中存活的对象放到了Old Gen中了。

这是发生在CMS-concurrent-sweep阶段

2015-07-23T06:25:36.290-0400: [CMS-concurrent-preclean: 19.091/174.559 secs] [Times: user=53.37 sys=3.66, real=174.53 secs] 
2015-07-23T06:25:36.525-0400: [CMS-concurrent-abortable-preclean: 0.133/0.235 secs] [Times: user=0.37 sys=0.00, real=0.24 secs] 
2015-07-23T06:25:36.526-0400: [GC[YG occupancy: 719822 K (943744 K)][Rescan (parallel) , 0.0487460 secs][weak refs processing, 0.0002160 secs] [1 CMS-remark: 8636790K(9437184K)] 9356613K(10380928K), 0.0490460 secs] [Times: user=0.32 sys=0.00, real=0.05 secs] 
2015-07-23T06:25:38.022-0400: [GC [ParNew: 942035K->104832K(943744K), 3.4626740 secs] 9571668K->8831757K(10380928K), 3.4627820 secs] [Times: user=0.35 sys=0.07, real=3.47 secs] 
2015-07-23T06:25:43.548-0400: [GC [ParNew (promotion failed): 943744K->943744K(943744K), 3.9544520 secs][CMS2015-07-23T06:31:11.405-0400: [CMS-concurrent-sweep: 327.407/334.829 secs] [Times: user=8.42 sys=1.77, real=334.78 secs] 
 (concurrent mode failure): 8881917K->1234174K(9437184K), 357.1201510 secs] 9645662K->1234174K(10380928K), [CMS Perm : 67582K->63968K(111848K)], 361.0747320 secs] [Times: user=10.25 sys=1.59, real=361.02 secs] 

这里基本和上面类似,ParNew在06:25:43.548结束,花费3.9544520s发现promotion failed,启动CMS GC,但在327.407s(从ParNew开始算起)完成CMS-concurrent-sweep后还是无法存放promote上来的对象,而发生concurrent mode failure,然后开始整理以容纳promote的对象,花费20s左右时间,最后做Perm GC,花费4s左右。这里CMS-concurrent-sweep之所以要花费327.407s的时间,应该还是和page faults相关吧?

这是发生在CMS-concurrent-mark阶段:

2015-07-17T03:21:28.701-0400: [GC [1 CMS-initial-mark: 7598316K(9437184K)] 7703150K(10380928K), 1.5896460 secs] [Times: user=0.02 sys=0.00, real=1.59 secs] 
2015-07-17T03:22:16.910-0400: [GC [ParNew (promotion failed): 943744K->943744K(943744K), 7.5542170 secs][CMS2015-07-17T03:22:26.210-0400: [CMS-concurrent-mark: 32.098/55.919 secs] [Times: user=32.19 sys=1.54, real=55.91 secs] 
 (concurrent mode failure): 8270889K->1474450K(9437184K), 27.2265650 secs] 9074498K->1474450K(10380928K), [CMS Perm : 64992K->63114K(108020K)], 34.7809080 secs] [Times: user=6.10 sys=0.21, real=34.78 secs] 

这里的问题类似,不赘述。

这是另一种情况下发生在CMS-concurrent-abortable-preclean阶段:
2015-07-23T06:24:47.450-0400: [GC [1 CMS-initial-mark: 3938781K(5973632K)] 3998846K(6126976K), 0.0030340 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2015-07-23T06:24:47.546-0400: [CMS-concurrent-mark: 0.093/0.093 secs] [Times: user=0.27 sys=0.01, real=0.09 secs] 
2015-07-23T06:24:47.559-0400: [CMS-concurrent-preclean: 0.013/0.013 secs] [Times: user=0.03 sys=0.00, real=0.02 secs] 
2015-07-23T06:24:47.665-0400: [GC [ParNew2015-07-23T06:24:47.675-0400: [CMS-concurrent-abortable-preclean: 0.012/0.116 secs] [Times: user=0.16 sys=0.02, real=0.11 secs] 
 (promotion failed): 133502K->140562K(153344K), 0.0393600 secs][CMS (concurrent mode failure): 3948765K->479672K(5973632K), 1.9491860 secs] 4072283K->479672K(6126976K), [CMS Perm : 62974K->62509K(108776K)], 1.9886830 secs] [Times: user=0.62 sys=0.00, real=1.99 secs] 

这里ParNew发生时正在执行CMS-concurrent-abortable-preclean,而在结束时发生promotion failed,同时因为碎片问题发生concurrent mode failure,因而出现Full GC。


concurrent mode failure除了和promotion failed同时发生,我在想会不会出现这样的场景:CMS整个生命周期分成多个步骤,在这个过程中由于有其他新增的内存需要分配,但是没有足够多的空间分配,因而产生concurrent mode failure的情况呢?这个在之前出现OOM的时候找到过一个类似的,虽然它之前是因为ParNew promotion failed,产生Full GC,然后在Full GC过程中发生的。即如果是这种情况,一般代表内存不够用,需要增加内存空间。
2015-07-30T11:12:38.469+0900: [GC [ParNew (promotion failed): 941415K->941415K(943744K), 0.0385590 secs] 9771224K->9867504K(10380928K), 0.0387350 secs] [Times: user=0.38 sys=0.00, real=0.04 secs]
GC locker: Trying a full collection because scavenge failed
2015-07-30T11:12:38.508+0900: [Full GC [CMS2015-07-30T11:12:38.685+0900: [CMS-concurrent-sweep: 0.863/0.911 secs] [Times: user=5.14 sys=0.32, real=0.91 secs]
 (concurrent mode failure): 8926088K->8485034K(9437184K), 5.7188070 secs] 9867504K->8485034K(10380928K), [CMS Perm : 65574K->65559K(110780K)], 5.7189380 secs] [Times: user=5.70 sys=0.00, real=5.71 secs]


虽然分析了那么多,还有一个疑问没能解决,对这个问题的调节方法还是一样的:1. 降低CMS GC的阈值;2. 提前减少Old Gen中的碎片,即让CMS GC做整理。这里不再赘述。

最后,我们可以看看其他的调节方式:
1. 我们知道CMS收集器很多过程是并发进行的,因而我们可以控制并发线程的个数:-XX:ParallelCMSThreads=4,我们采用的值是4,和ParNew相同。CMS默认的回收线程数是(CPU个数+3)/4。
2. 在历史上还出现过增量式并发收集器(Incremental Concurrent Mark Sweep,i-CMS)。因为对少于4个CPU的时候,如果GC占用一般左右的CPU资源,会影响用户线程的吞吐量,因而增量式并发收集器的思想是在并发标记和并发清理时让用户线程和GC线程交替运行以减少GC占用太多的资源,特别是在只有一个CPU的情况下,即使在CMS并发阶段,还是会产生STW的现象,因而可以使用i-CMS来避免这种情况。然而i-CMS已经不再推荐使用,具体可以参考这里。大概的原因是现在已经很少只有一个CPU的硬件了,而且i-CMS在线程切换时会花费更多的资源和时间,它更加复杂,有更多的参数,难以调节,会产生更多的碎片。

3. 可以简单介绍一下CMS的整个过程(还可以参考这里,或者这里,虽然这里用的例子是1.4.2的版本,我用的是1.6.30,会有一些区别)。以一个正常的CMS为例:

2015-07-21T22:17:20.667-0400: [GC [1 CMS-initial-mark: 7462216K(9437184K)] 7583692K(10380928K), 0.0223830 secs] [Times: user=0.02 sys=0.00, real=0.03 secs] 
2015-07-21T22:17:21.055-0400: [CMS-concurrent-mark: 0.365/0.365 secs] [Times: user=1.75 sys=0.03, real=0.36 secs] 
2015-07-21T22:17:21.075-0400: [CMS-concurrent-preclean: 0.020/0.020 secs] [Times: user=0.04 sys=0.00, real=0.02 secs] 
2015-07-21T22:17:23.851-0400: [CMS-concurrent-abortable-preclean: 1.586/2.776 secs] [Times: user=5.60 sys=0.10, real=2.78 secs] 
2015-07-21T22:17:23.852-0400: [GC[YG occupancy: 679011 K (943744 K)][Rescan (parallel) , 0.1319540 secs][weak refs processing, 0.0001560 secs] [1 CMS-remark: 7511697K(9437184K)] 8190709K(10380928K), 0.1321850 secs] [Times: user=0.46 sys=0.01, real=0.13 secs] 
2015-07-21T22:17:30.242-0400: [CMS-concurrent-sweep: 6.004/6.258 secs] [Times: user=11.89 sys=0.17, real=6.26 secs] 
2015-07-21T22:17:30.261-0400: [CMS-concurrent-reset: 0.018/0.018 secs] [Times: user=0.04 sys=0.00, real=0.02 secs] 

1 CMS-initial-mark:初始标记标记阶段,STW,CMS起始点,标记所有Root对象直接可达的对象,7462216K是CMS触发时Old Gen的内存大小,7583692K是Old Gen+Young Gen的内存大小。
CMS-concurrent-mark:重新标记阶段,和用户线程同时处理,遍历初始标记出来的对象的所有直接或间接可达对象。CPU时间0.365s,总共0.365s(wall time)。这里times时间不是那么准确,因为起于该阶段的开始,但是中间可能包含其他的事情,如用户线程的执行影响等

CMS-concurrent-preclean:preclean阶段,这个阶段依然和用户线程同时处理,它会继续查看在重新标记阶段新产生的对象:从Young Gen promote上来的对象,新分配的对象,或被修改的对象。这个阶段主要用于减少下一次重新标记(remark)的时间,因为重新标记会STW。CPU时间0.020s,总共0.020s(wall time)。
CMS-concurrent-abortable-preclean:可中断的preclean阶段,和用户线程同时处理,当preclean已经结束的时候就可以开始remark了,然而如果这样设计,由于CMS-concurrent-preclean和用户线程一起运行,当它结束的时候,Young Gen已经使用了很多了,但是这里面有很多是可以回收的,为了提升效率就可以先ParNew GC回收掉多余的对象,然后就会接着执行remark,就可以减少remark的时间;而如果Young Gen使用的很少,就可以立即启动remark过程;而如果介于之间,就可以先等待一会让eden占用一些空间后再启动remark,从而将ParNew GC的STW和remark的STW错分开。因而CMS的设计者就想出remark的执行时机还依赖于eden的使用情况(因为新对象总是先分配到eden空间),即通过两个变量来控制:CMSScheduleRemarkEdenSize和CMSScheduleRemarkEdenPenetration,它们的默认值分别是2M和50%,表示在CMS-concurrent-preclean结束后,如果eden只使用了少于2M,则直接启动remark;如果超过2M,但没有超过50%,则先启动CMS-concurrent-abortable-preclean,直到eden的使用率超过了50%,然后启动remark过程,这样就保证了remark和ParNew GC中间会有一定的时间间隔;如果已经超过了50%,就等待下次ParNew GC完成,然后再做remark?貌似只有这样才能解释的通这些日志,当remark阶段准备好后它可以随时被中断,它的中断不是错。如这种日志:

2015-06-16T03:15:21.471-0400: [CMS-concurrent-preclean: 0.030/0.031 secs] [Times: user=0.05 sys=0.00, real=0.03 secs] 
 CMS: abort preclean due to time 2015-06-16T03:15:26.659-0400: [CMS-concurrent-abortable-preclean: 3.351/5.187 secs] [Times: user=3.50 sys=0.04, real=5.19 secs] 
2015-06-16T03:15:26.659-0400: [GC[YG occupancy: 561249 K (943744 K)][Rescan (parallel) , 0.1650010 secs][weak refs processing, 0.0000680 secs] [1 CMS-remark: 7465008K(9437184K)] 8026257K(10380928K), 0.1651410 secs] [Times: user=0.52 sys=0.00, real=0.16 secs] 

这个日志表示preclean结束后,eden的空间在2M和50%之间,因而启动abortable-preclean阶段,直到4.84s后才因为eden超过50%后中断CMS-concurrent-abortable-preclean,并开始remark,实际使用0.16s。

2015-07-03T08:15:21.840-0400: [CMS-concurrent-preclean: 0.019/0.019 secs] [Times: user=0.04 sys=0.00, real=0.02 secs] 
2015-07-03T08:15:22.605-0400: [GC [ParNew2015-07-03T08:15:22.636-0400: [CMS-concurrent-abortable-preclean: 0.693/0.795 secs] [Times: user=1.30 sys=0.06, real=0.79 secs] 
: 943744K->104832K(943744K), 0.2089320 secs] 8446030K->7838840K(10380928K), 0.2090220 secs] [Times: user=0.60 sys=0.01, real=0.21 secs] 
2015-07-03T08:15:22.815-0400: [GC[YG occupancy: 120239 K (943744 K)][Rescan (parallel) , 0.0289020 secs][weak refs processing, 0.0001000 secs] [1 CMS-remark: 7734008K(9437184K)] 7854247K(10380928K), 0.0290690 secs] [Times: user=0.13 sys=0.00, real=0.03 secs] 

这个日志表示在CMS-concurrent-preclean结束后,eden使用空间已经超过50%,所以启动abortable-preclean,并在155ms后启动ParNew GC,在ParNew停止31ms后停止CMS-concurrent-abortable-preclean,而remark随后开始,经历30ms结束。

2015-07-30T12:06:22.199+0900: [CMS-concurrent-preclean: 0.007/0.007 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
2015-07-30T12:06:22.199+0900: [GC[YG occupancy: 2534 K (19136 K)][Rescan (parallel) , 0.0016670 secs][weak refs processing, 0.0000110 secs] [1 CMS-remark: 1984060K(3050752K)] 1986594K(3069888K), 0.0017300 secs] [Times: user=0.03 sys=0.00, real=0.00 secs]

这个日志表示preclean结束后eden使用少于2M,因而跳过abortable-preclean,直接开始remark阶段。

1 CMS-remark:重新标记阶段,STW,这里YG occupancy表示该阶段开始时Young Gen的大小,因为这个阶段的时间长短部分依赖于Young Gen的大小;Rescan用于多线程扫描程序停止时存活的对象,花费0.1319540s;weak refs processing用于处理weak reference的情况,花费0.0001s,如果这个阶段花费太长时间,可以打开开关:-XX:+ParallelRefProcEnabled来调节;然后开始重新标记,即重新从Root对象遍历标记存活对象。
CMS-concurrent-sweep:并发清理,和其他线程同时执行,做真正的清理工作,如把可以回收的内存放回空闲列表,合并相邻内存空间等。

CMS-concurrent-reset:重置CMS的状态用于下一次执行。

减少类的创建

减少类的创建就需要改代码,还要分析项目的特点,但是总体上可以有三个方向:

  1. 实实在在的减少不必要的类创建,如是否可以字段来缓存一个对象而不是每次在调用时都新建一个类,设置可以考虑用一些静态方法而不是实例类等。
  2. 将某些常用的对象缓存起来,每次都从缓存中拿对象而不是新建一个对象,甚至有些时候我们已经新创建了一个对象也要替换成缓存中的对象,这样新创建的对象就可以直接被回收,而在缓存中的对象很多时候会留在Old Gen中而不需要被回收。很多开源的项目中就有使用这个技术,如String的intern方式就是类似的设计,记得有些面试提会问new String("abc")创建了几个String对象,以及"abc"==String.valueOf("abc")的问题等,但是有多少人直到这种现象的设计意图和内部原理呢?
  3. 自己管理对象的创建,即自己维护一个或多个Buffer,然后自己管理和使用这些Buffer,如Jetty中的BufferCache的实现。

后记

这篇博客写了一个多星期了,终于快收尾了。对于GC,所实话自己以前关注的并不多,一直觉得自己了解到的东西已经够用了,直到这次一个同事把我们项目中GemFire节点调出和GC的停顿时间联系起来,然后我突然感觉很多问题豁然开朗了。因而这一周潜心读了很多相关文章来完成这篇博客。其实还有很多可以说的,或者自己不了解的,这些只能留待以后慢慢补充,但是经历这个事件后,发现自己对GC的了解和一些设计思想提升了一个档次,记之。

参考:

《深入理解Java虚拟机-JVM高级特性与最佳实践》
promotion failed/concurrent mode failure explain:
 http://blog.ragozin.info/2011/10/java-cg-hotspots-cms-and-heap.html
promotion buffers explain: http://blog.ragozin.info/2011/11/java-gc-hotspots-cms-promotion-buffers.html
i-CMS not recommended: https://blogs.oracle.com/jonthecollector/entry/really_icms_really
JVM Options: http://stas-blogspot.blogspot.hk/2011/07/most-complete-list-of-xx-options-for.html
JVM Options: http://www.oracle.com/technetwork/articles/java/vmoptions-jsp-140102.html
CMS GC Log(JDK 1.8.0-ea): https://blogs.oracle.com/jonthecollector/entry/the_unspoken_cms_and_printgcdetails
CMS GC Log(JDK 1.4.2): https://blogs.oracle.com/poonam/entry/understanding_cms_gc_logs
GC Log Parser Code:https://java.net/projects/gchisto
CMS介绍:https://docs.oracle.com/javase/8/docs/technotes/guides/vm/gctuning/cms.html
JVM调优的“标准参数”的各种陷阱:http://hllvm.group.iteye.com/group/topic/27945
HotSpot Glossary: http://openjdk.java.net/groups/hotspot/docs/HotSpotGlossary.html

其他相关或不相关的:
https://blogs.oracle.com/jonthecollector/entry/when_the_sum_of_the
https://plumbr.eu/blog/garbage-collection/minor-gc-vs-major-gc-vs-full-gc
https://blogs.oracle.com/poonam/entry/troubleshooting_long_gc_pauses
http://blog.sokolenko.me/2014/11/javavm-options-production.html
http://hllvm.group.iteye.com/group/topic/42365
http://www.blogjava.net/chhbjh/archive/2012/01/28/368936.html
http://wenku.baidu.com/view/c8eb5f67caaedd3383c4d376.html
http://wenku.baidu.com/view/02b2c71255270722192ef7b8.html
http://wenku.baidu.com/view/cda7b606bed5b9f3f90f1cc6.html

网友评论

登录后评论
0/500
评论
雪地脚印
+ 关注