PermGen大了也不行

随便记一下。

今天有个应用说是full GC过于频繁。看了下发现执行的都是CMS GC，并不是真的stop-the-world的full GC。但确实是很频繁，几秒就触发一次。
堆的使用状况，eden/SS0/SS1的使用量都没啥特别的，old gen大概用了10%+，而perm gen用了70%+。光看空间占用量的话，都还达不到CMS的触发条件。.

$ jstat -gcutil `pgrep -u admin java` 1s
  S0     S1     E      O      P     YGC     YGCT    FGC    FGCT     GCT   
 37.21   0.00  99.81  12.87  76.82   1767  196.843  3085 2998.088 3194.931
 37.21   0.00  99.81  12.87  76.82   1767  196.843  3086 2998.088 3194.931
  0.00  47.48   1.06  12.90  76.82   1768  196.959  3086 2999.778 3196.737
  0.00  47.48   1.88  12.90  76.82   1768  196.959  3086 2999.778 3196.737

有几个VM参数会影响GC堆的占用量状况与CMS的触发之间的关系：

product(uintx, MinHeapFreeRatio, 40,
  "Min percentage of heap free after GC to avoid expansion")
product(intx, CMSTriggerRatio, 80,
  "Percentage of MinHeapFreeRatio in CMS generation that is allocated before a CMS collection cycle commences")
product(intx, CMSTriggerPermRatio, 80,
  "Percentage of MinHeapFreeRatio in the CMS perm generation that is allocated before a CMS collection cycle commences, that also collects the perm generation")
product(intx, CMSInitiatingOccupancyFraction, -1,
  "Percentage CMS generation occupancy to start a CMS collection cycle. A negative value means that CMSTriggerRatio is used")
product(intx, CMSInitiatingPermOccupancyFraction, -1,
  "Percentage CMS perm generation occupancy to start a CMScollection cycle. A negative value means that CMSTriggerPermRatio is used")

在HotSpot VM里，上面几个参数是这样用的：

// The field "_initiating_occupancy" represents the occupancy percentage
// at which we trigger a new collection cycle.  Unless explicitly specified
// via CMSInitiating[Perm]OccupancyFraction (argument "io" below), it
// is calculated by:
//
//   Let "f" be MinHeapFreeRatio in
//
//    _intiating_occupancy = 100-f +
//                           f * (CMSTrigger[Perm]Ratio/100)
//   where CMSTrigger[Perm]Ratio is the argument "tr" below.
//
// That is, if we assume the heap is at its desired maximum occupancy at the
// end of a collection, we let CMSTrigger[Perm]Ratio of the (purported) free
// space be allocated before initiating a new collection cycle.
//
void ConcurrentMarkSweepGeneration::init_initiating_occupancy(intx io, intx tr) {
  assert(io <= 100 && tr >= 0 && tr <= 100, "Check the arguments");
  if (io >= 0) {
    _initiating_occupancy = (double)io / 100.0;
  } else {
    _initiating_occupancy = ((100 - MinHeapFreeRatio) +
                             (double)(tr * MinHeapFreeRatio) / 100.0)
                            / 100.0;
  }
}

_cmsGen ->init_initiating_occupancy(CMSInitiatingOccupancyFraction, CMSTriggerRatio);
_permGen->init_initiating_occupancy(CMSInitiatingPermOccupancyFraction, CMSTriggerPermRatio);

在这个应用里，这几个参数都没显式设置，用的就是默认值：

$ jinfo -flag MinHeapFreeRatio `pgrep -u admin java`
-XX:MinHeapFreeRatio=40
$ jinfo -flag CMSTriggerPermRatio `pgrep -u admin java`
-XX:CMSTriggerPermRatio=80
$ jinfo -flag CMSInitiatingPermOccupancyFraction `pgrep -u admin java`
-XX:CMSInitiatingPermOccupancyFraction=-1

所以可以知道，CMS perm gen触发CMS GC的占用量是((100 - 40) + (80 * 40) / 100.0) / 100.0 = 92%

要观察CMS的触发条件的动态调整的话，有-XX:+PrintCMSInitiationStatistics参数可用。这里有该参数对应的日志的例子，https://gist.github.com/1050942，内容是类似这样的：

CMSCollector shouldConcurrentCollect: 42.910
time_until_cms_gen_full 2.0111715
free=32676856
contiguous_available=44957696
promotion_rate=1.00797e+07
cms_allocation_rate=0
occupancy=0.5003915
initiatingOccupancy=0.9200000
initiatingPermOccupancy=0.9200000

CMS GC默认不只通过old gen和perm gen的占用量来触发，还有别的一些条件。

product(bool, UseCMSInitiatingOccupancyOnly, false, "Only use occupancy as a crierion for starting a CMS collection")

如果这个参数是true的话那就只用占用量来触发了。

关于CMS GC的触发条件的一段注释：

// We should be conservative in starting a collection cycle.  To
// start too eagerly runs the risk of collecting too often in the
// extreme.  To collect too rarely falls back on full collections,
// which works, even if not optimum in terms of concurrent work.
// As a work around for too eagerly collecting, use the flag
// UseCMSInitiatingOccupancyOnly.  This also has the advantage of
// giving the user an easily understandable way of controlling the
// collections.
// We want to start a new collection cycle if any of the following
// conditions hold:
// . our current occupancy exceeds the configured initiating occupancy
//   for this generation, or
// . we recently needed to expand this space and have not, since that
//   expansion, done a collection of this generation, or
// . the underlying space believes that it may be a good idea to initiate
//   a concurrent collection (this may be based on criteria such as the
//   following: the space uses linear allocation and linear allocation is
//   going to fail, or there is believed to be excessive fragmentation in
//   the generation, etc... or ...
// [.(currently done by CMSCollector::shouldConcurrentCollect() only for
//   the case of the old generation, not the perm generation; see CR 6543076):
//   we may be approaching a point at which allocation requests may fail because
//   we will be out of sufficient free space given allocation rate estimates.]
bool ConcurrentMarkSweepGeneration::should_concurrent_collect() const {

// Decide if we want to enable class unloading as part of the
// ensuing concurrent GC cycle. We will collect the perm gen and
// unload classes if it's the case that:
// (1) an explicit gc request has been made and the flag
//     ExplicitGCInvokesConcurrentAndUnloadsClasses is set, OR
// (2) (a) class unloading is enabled at the command line, and
//     (b) (i)   perm gen threshold has been crossed, or
//         (ii)  old gen is getting really full, or
//         (iii) the previous N CMS collections did not collect the
//               perm gen
// NOTE: Provided there is no change in the state of the heap between
// calls to this method, it should have idempotent results. Moreover,
// its results should be monotonically increasing (i.e. going from 0 to 1,
// but not 1 to 0) between successive calls between which the heap was
// not collected. For the implementation below, it must thus rely on
// the property that concurrent_cycles_since_last_unload()
// will not decrease unless a collection cycle happened and that
// _permGen->should_concurrent_collect() and _cmsGen->is_too_full() are
// themselves also monotonic in that sense. See check_monotonicity()
// below.
bool CMSCollector::update_should_unload_classes() {

// Support for concurrent collection policy decisions.
bool CompactibleFreeListSpace::should_concurrent_collect() const {
  // In the future we might want to add in frgamentation stats --
  // including erosion of the "mountain" into this decision as well.
  return !adaptive_freelists() && linearAllocationWouldFail();
}

=====================================================================

观察GC日志，发现CMS的initial mark阶段的暂停居然超过1.4s了。而印象中上次看这个应用的initial mark的暂停时间还不到1s，说明情况恶化了。这期间，MaxPermSize从256m调到了512m。感觉暂停时间的提高跟perm gen的增大很有关系。

2011-06-28T11:11:01.417+0800: 432933.547: [GC [1 CMS-initial-mark: 262613K(2097152K)] 2003375K(4019584K), 1.9010460 secs] [Times: user=1.90 sys=0.00, real=1.90 secs] 
2011-06-28T11:11:03.347+0800: 432935.478: [CMS-concurrent-mark-start]
2011-06-28T11:11:04.737+0800: 432936.867: [CMS-concurrent-mark: 1.362/1.390 secs] [Times: user=1.50 sys=0.01, real=1.39 secs] 
2011-06-28T11:11:04.737+0800: 432936.868: [CMS-concurrent-preclean-start]
2011-06-28T11:11:04.752+0800: 432936.883: [CMS-concurrent-preclean: 0.014/0.015 secs] [Times: user=0.00 sys=0.01, real=0.02 secs] 
2011-06-28T11:11:04.752+0800: 432936.883: [CMS-concurrent-abortable-preclean-start]
2011-06-28T11:11:07.783+0800: 432939.913: [GC 432939.913: [ParNew: 1800925K->85199K(1922432K), 0.1672690 secs] 2063538K->348295K(4019584K), 0.1675310 secs] [Times: user=0.40 sys=0.00, real=0.17 secs] 
 CMS: abort preclean due to time 2011-06-28T11:11:09.938+0800: 432942.068: [CMS-concurrent-abortable-preclean: 3.556/5.185 secs] [Times: user=4.15 sys=0.04, real=5.18 secs] 
2011-06-28T11:11:09.944+0800: 432942.074: [GC[YG occupancy: 124255 K (1922432 K)]432942.074: [Rescan (parallel) , 0.1174650 secs]432942.192: [weak refs processing, 0.0000200 secs]432942.192: [class unloading, 0.0868120 secs]432942.279: [scrub symbol & string tables, 0.0169840 secs] [1 CMS-remark: 263096K(2097152K)] 387351K(4019584K), 0.2316920 secs] [Times: user=0.31 sys=0.00, real=0.23 secs] 
2011-06-28T11:11:10.176+0800: 432942.306: [CMS-concurrent-sweep-start]
2011-06-28T11:11:10.688+0800: 432942.818: [CMS-concurrent-sweep: 0.512/0.512 secs] [Times: user=0.54 sys=0.00, real=0.51 secs] 
2011-06-28T11:11:10.688+0800: 432942.818: [CMS-concurrent-reset-start]
2011-06-28T11:11:10.707+0800: 432942.838: [CMS-concurrent-reset: 0.020/0.020 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 

增大perm gen对这应用来说或许反而成毒药了。它大量使用了Groovy脚本，有比较频繁的新的类的生成与加载动作，简单看了段日志大概是每隔几分钟会加载十来个类。类卸载的速度足以维持perm gen不OOM。

嘛，回头再跟进了。

评论

8 楼 bert82503 2016-04-22  

bglmmz 写道

RednaxelaFX 写道

chenchao051 写道

很有启发性，之前也一直没有注意到permSize会影响到initial mark，依照莫枢同学的文章，假如没有大量Groovy的使用，或者说没有动态语言的加入，还会不会出现文中所述情况。
按理来讲，load进去后，反正都是class，应该和语言无关才对。比较关注这点，因为我也在项目中引进了Groovy.

是的，反正都是class，本来是语言无关的。但一般的Java应用很少会大量的、持续的动态加载类，而使用Groovy的话不注意就容易掉进陷阱里：大量动态加载类会极大的增加PermGen的压力（在当前已经跟随JDK6正式发布的HotSpot里）。如果一个不用动态语言的应用也大量动态加载类的话那也会遇到一样的问题。

回到这篇blog，我已经知道实际造成full GC频繁的最具体原因了。在VM里改一行代码就好了，呵呵～

请教楼主，是什么原因引起的呢？要怎么改？

GroovyEngine 在每次编译加载内容时，都会将当前系统时间作为文件名的一部分，所以即使是内容相同的文件，每次加载都是不一样的。

7 楼 serenity 2016-04-20  

博主，请教一下，cms日志如何看出MaxPermSize从256m调到了512m？

6 楼 bglmmz 2012-10-08  

RednaxelaFX 写道

chenchao051 写道

很有启发性，之前也一直没有注意到permSize会影响到initial mark，依照莫枢同学的文章，假如没有大量Groovy的使用，或者说没有动态语言的加入，还会不会出现文中所述情况。
按理来讲，load进去后，反正都是class，应该和语言无关才对。比较关注这点，因为我也在项目中引进了Groovy.

是的，反正都是class，本来是语言无关的。但一般的Java应用很少会大量的、持续的动态加载类，而使用Groovy的话不注意就容易掉进陷阱里：大量动态加载类会极大的增加PermGen的压力（在当前已经跟随JDK6正式发布的HotSpot里）。如果一个不用动态语言的应用也大量动态加载类的话那也会遇到一样的问题。

回到这篇blog，我已经知道实际造成full GC频繁的最具体原因了。在VM里改一行代码就好了，呵呵～

请教楼主，是什么原因引起的呢？要怎么改？

5 楼 richard_2010 2011-08-08  

RednaxelaFX 写道

回到这篇blog，我已经知道实际造成full GC频繁的最具体原因了。在VM里改一行代码就好了，呵呵～

具体神马原因也不说出来。。。。

对了，你提到CMS在initial mark时已经达到1.4s，这也太慢了吧？你的持久代只有512m，如果我的旧生代有几个G的话，那多恐怖？

4 楼 RednaxelaFX 2011-07-21  

chenchao051 写道

很有启发性，之前也一直没有注意到permSize会影响到initial mark，依照莫枢同学的文章，假如没有大量Groovy的使用，或者说没有动态语言的加入，还会不会出现文中所述情况。
按理来讲，load进去后，反正都是class，应该和语言无关才对。比较关注这点，因为我也在项目中引进了Groovy.

是的，反正都是class，本来是语言无关的。但一般的Java应用很少会大量的、持续的动态加载类，而使用Groovy的话不注意就容易掉进陷阱里：大量动态加载类会极大的增加PermGen的压力（在当前已经跟随JDK6正式发布的HotSpot里）。如果一个不用动态语言的应用也大量动态加载类的话那也会遇到一样的问题。

回到这篇blog，我已经知道实际造成full GC频繁的最具体原因了。在VM里改一行代码就好了，呵呵～

3 楼 chenchao051 2011-07-20  

很有启发性，之前也一直没有注意到permSize会影响到initial mark，依照莫枢同学的文章，假如没有大量Groovy的使用，或者说没有动态语言的加入，还会不会出现文中所述情况。
按理来讲，load进去后，反正都是class，应该和语言无关才对。比较关注这点，因为我也在项目中引进了Groovy.

2 楼 RednaxelaFX 2011-07-04  

all_wmh 写道

嘿嘿，现在还看不大懂jvm的代码，所以请教撒迦几个个问题：相对于old gen来讲perm gen上的初始标识阶段采用的算法是不是比较复杂？这个复杂的地方在哪里呢？ 如果真的是perm gen上的初始标识算法比较复杂，那么以后的应用是不是应该注意这个值的设置呢？

算法并没复杂，一样的。关键是扫描的地方的多少。例如说SystemDictionary要不要扫描、是指扫描里面的system classes还是all classes，之类。

1 楼 all_wmh 2011-07-04  

嘿嘿，现在还看不大懂jvm的代码，所以请教撒迦几个个问题：相对于old gen来讲perm gen上的初始标识阶段采用的算法是不是比较复杂？这个复杂的地方在哪里呢？ 如果真的是perm gen上的初始标识算法比较复杂，那么以后的应用是不是应该注意这个值的设置呢？