CMS gc调整实践(续)

xiaoxiao2024-04-22 9

在初步确定CMS参数后，系统运行了几天，今天尝试在线上打开了GC日志，按阿宝同学的说法是gc日志的开销比之jstat还小，打开之后发现确实影响很小。打开GC日志之后又发现几个隐藏的问题比较有价值，这里记录下。首先是系统在启动的时候有一次System.gc()调用引起的full gc，日志输出类似这样： 1.201 : [Full GC (System) 1.201 : [CMS: 0K -> 797K(1310720K), 0.1090540 secs] 29499K -> 797K(1546688K), [CMS Perm : 5550K -> 5547K(65536K)], 0.1091860 secs] [Times: user = 0.05 sys = 0.06 , real = 0.11 secs] 可以确认的是我们系统里的代码绝对没有调用System.gc()方法，但是不保证第三方代码有调用，通过搜索代码引用，后来定位到了mina的ByteBuffer创建上面。 Mina 1.1封装的ByteBuffer的allocate()方法默认创建的是Direct ByteBuffer，而DirectByteBuffer的构造函数里调用了 Bits.reserveMemory(cap); 这个方法强制调用了System.gc(): static void reserveMemory( long size) { synchronized (Bits. class ) { if ( ! memoryLimitSet && VM.isBooted()) { maxMemory = VM.maxDirectMemory(); memoryLimitSet = true ; } if (size <= maxMemory - reservedMemory) { reservedMemory += size; return ; } } System.gc(); try { Thread.sleep( 100 ); } catch (InterruptedException x) { // Restore interrupt status Thread.currentThread().interrupt(); } synchronized (Bits. class ) { if (reservedMemory + size > maxMemory) throw new OutOfMemoryError( " Direct buffer memory " ); reservedMemory += size; } } 调用这个方法是为了用户对Direct ByteBuffer的内存可控。而在我们系统中使用的通讯层初始化Decoder的时候通过Mina 1.1创建了一个Direct ByteBuffer，导致了这一次强制的full gc。这个Buffer因为是长期持有的，因此创建Direct类型也还可以接受。但是在这次GC后，又发现每隔一个小时就有一次System.gc()引起的full gc，这就太难以忍受了，日志大概是这样，注意间隔时间都是3600秒左右： 10570.672 : [Full GC (System) 10570.672 : [CMS: 779199K -> 107679K(1310720K), 1.2957430 secs] 872163K -> 107679K(1546688K), [CMS Perm : 23993K -> 15595K(65536K)], 1.2959630 secs] [Times: user = 1.27 sys = 0.02 , real = 1.30 secs] 14171.971 : [Full GC (System) 14171.971 : [CMS: 680799K -> 83681K(1310720K), 1.0171580 secs] 836740K -> 83681K(1546688K), [CMS Perm : 20215K -> 15599K(65536K)], 1.0173850 secs] [Times: user = 0.97 sys = 0.01 , real = 1.02 secs] 17774.020 : [Full GC (System) 17774.020 : [CMS: 676201K -> 79331K(1310720K), 0.9652670 secs] 817596K -> 79331K(1546688K), [CMS Perm : 22808K -> 15619K(65536K)], 0.9655150 secs] [Times: user = 0.93 sys = 0.02 , real = 0.97 secs] 21374.989 : [Full GC (System) 21374.989 : [CMS: 677818K -> 78590K(1310720K), 0.9297080 secs] 822317K -> 78590K(1546688K), [CMS Perm : 16435K -> 15593K(65536K)], 0.9299620 secs] [Times: user = 0.89 sys = 0.01 , real = 0.93 secs] 24976.948 : [Full GC (System) 24976.948 : [CMS: 659511K -> 77608K(1310720K), 0.9255360 secs] 794004K -> 77608K(1546688K), [CMS Perm : 22359K -> 15594K(65536K)], 0.9257760 secs] [Times: user = 0.88 sys = 0.02 , real = 0.93 secs] 28578.892 : [Full GC (System) 28578.892 : [CMS: 562058K -> 77572K(1310720K), 0.8365500 secs] 735072K -> 77572K(1546688K), [CMS Perm : 15840K -> 15610K(65536K)], 0.8367990 secs] [Times: user = 0.82 sys = 0.00 , real = 0.84 secs] 32179.731 : [Full GC (System) 32179.732 : [CMS: 549874K -> 77224K(1310720K), 0.7864400 secs] 561803K -> 77224K(1546688K), [CMS Perm : 16016K -> 15597K(65536K)], 0.7866540 secs] [Times: user = 0.75 sys = 0.01 , real = 0.79 secs] 搜遍了源码和依赖库，没有再发现显式的gc调用，问题只能出在运行时上，突然想起我们的系统使用RMI暴露JMX给监控程序，监控程序通过RMI连接JMX监控系统和告警等，会不会是 RMI的分布式垃圾收集导致的？果然，一查资料，RMI的分布式收集会强制调用System.gc()来进行分布式GC，server端的间隔恰好是一个小时，这个参数可以通过： - Dsun.rmi.dgc.server.gcInterval = 3600000

来调整。调长时间是一个解决办法，但是我们更希望能不出现显式的GC调用，禁止显式GC调用通过-XX:+DisableExplicitGC是一个办法，但是禁止了分布式GC会导致什么问题却是心理没底，毕竟我们的JMX调用还是很频繁的，幸运的是JDK6还提供了另一个选项-XX:+ExplicitGCInvokesConcurrent，允许System.gc()也并发运行，调整DGC时间间隔加上这个选项双管齐下彻底解决了full gc的隐患。打开GC日志后发现的另一个问题是remark的时间过长，已经启用了并行remark，但是时间还是经常超过200毫秒，这个可能的原因有两个：我们的年老代太大或者触发CMS的阀值太高了，CMS进行的时候年老代里的对象已经太多。初步的计划是调小-XX:SurvivorRatio增大救助空间并且降低-XX:CMSInitiatingOccupancyFraction这个阀值。此外，还找到另一个可选参数-XX:+CMSScavengeBeforeRemark，启用这个选项后，强制remark之前开始一次minor gc，减少remark的暂停时间，但是在remark之后也将立即开始又一次相对较长时间minor gc，如果你的minor gc很快的话可以考虑下这个选项，暂未实验.

文章转自庄周梦蝶，原文发布时间2009-09-22