如何了解CMS的垃圾碎片率

作者: 阿飞的博客 | 来源:发表于2017-09-20 17:34 被阅读672次

如何了解CMS的垃圾碎片率
垃圾回收
jvm
Java-JVM-垃圾回收器
25. java虚拟机总结-垃圾回收器（八）
2.JVM系列-CMS垃圾收集器
CMS的缺点
JVM垃圾回收器之CMS回收过程及优缺点
java CMS垃圾回收日志
一起来学习下，G1垃圾回收算法

PrintFLSStatistics这个参考比较有用，因为CMS GC会有碎片问题，而随着碎片的越来越严重，GC性能会变差直到发生FullGC，而FullGC时STW通过会超过数秒，这对OLTP系统来说是致命的，通过这个参数可以在gc日志中输出free list方式分配内存后内存统计情况和碎片情况；

从CompactibleFreeListSpace的描述可知CMS使用free list分配内存
-- 源码摘自compactibleFreeListSpace.hpp：

// Concrete subclass of CompactibleSpace that implements
// a free list space, such as used in the concurrent mark sweep generation.
class CompactibleFreeListSpace: public CompactibleSpace {
  friend class VMStructs;
  friend class ConcurrentMarkSweepGeneration;
  ... ...
}

PrintFLSStatistics参数

再看compactibleFreeListSpace.cpp中的gc_prologue和gc_epilogue（prologue的中文意思是开场白，epilogue的中文意思是收场白，所以这两个方法可以理解为gc前和gc后），由两个方法的实现可知，如果JVM参数PrintFLSStatistics 不为0（负数也可以），那么每次GC前后都会调用reportFreeListStatistics()方法打印出free list的统计信息：

void
CompactibleFreeListSpace::gc_prologue() {
  if (PrintFLSStatistics != 0) {
    gclog_or_tty->print("Before GC:\n");
    reportFreeListStatistics();
  }
}

void
CompactibleFreeListSpace::gc_epilogue() {
  // Print Space's stats
  if (PrintFLSStatistics != 0) {
    gclog_or_tty->print("After GC:\n");
    reportFreeListStatistics();
  }
}

再看reportFreeListStatistics的具体实现，分为两个部分来看：

第一部分是_dictionary->report_statistics()输出BinaryTreeDictionary统计信息；
第二部分是当PrintFLSStatistics >1时输出的附加log即IndexedFreeLists统计信息；

void CompactibleFreeListSpace::reportFreeListStatistics() const {
  // 输出BinaryTreeDictionary统计信息
  _dictionary->report_statistics();
  if (PrintFLSStatistics > 1) {
    // 如果PrintFLSStatistics >1，输出IndexedFreeLists统计信息
    reportIndexedFreeListStatistics();
    gclog_or_tty->print(" free=" SIZE_FORMAT " frag=%1.4f\n", total_size, flsFrag());
  }
}

第一部分即BinaryTreeDictionary统计信息：

输出free list统计信息，gc日志中输出内容如下：
Total Free Space: 25165824
Max Chunk Size: 25165824
Number of Blocks: 1
Av. Block Size: 25165824
Tree Height: 1

第二部分即IndexedFreeLists统计信息：

如果JVM参数为PrintFLSStatistics 大于1，例如-XX:PrintFLSStatistics=2，那么还会输出IndexedFreeLists的统计信息，以及如下的gc日志，能够直观的看到碎片率，frag的值越大碎片化越严重，JVM的初始化时frag的值为0.0000，即没有任何碎片：

 gclog_or_tty->print(" free=" SIZE_FORMAT " frag=%1.4f\n", total_size, flsFrag());

实际GC日志

为了查询碎片化率越来越严重的GC日志，笔者基于kafka 2.11-1.1.1版本，对其GC参数进行了一些调整，从而引起不断CMS GC：

调整kafka-server-start.sh

if [ "x$KAFKA_HEAP_OPTS" = "x" ]; then
    export KAFKA_HEAP_OPTS="-Xmx256m -Xms256m -Xmn64m 
    -server -XX:+UseConcMarkSweepGC 
    -XX:+UseCMSInitiatingOccupancyOnly 
    -XX:CMSInitiatingOccupancyFraction=50 
    -XX:+PrintGCDetails -XX:PrintFLSStatistics=2"
fi

调整kafka-run-class.sh

# JVM performance options
if [ -z "$KAFKA_JVM_PERFORMANCE_OPTS" ]; then
  #KAFKA_JVM_PERFORMANCE_OPTS="-server -XX:+UseG1GC"
  echo ""
fi

调整kafka-run-class.sh是为了屏蔽默认使用的G1，因为配置的CMS GC不能和G1共存。

接下来只需要启动一个kafka broker，然后利用kafka自带的压测脚本向broker发送1kw条消息（每条消息128个字节）：
bin/kafka-run-class.sh org.apache.kafka.tools.ProducerPerformance --topic topic-afei-test --num-records 10000000 --record-size 128 --throughput -1 --producer-props acks=1 bootstrap.servers=127.0.1.168:9092 buffer.memory=67108864 batch.size=8196

jstat结果

由jstat可知，FGC非常严重，每2s就有好几次的FGC：

[yyapp@redis-01 ~]$ jstat -gcutil 28982 2s
  S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT   
  0.00   3.43  26.39  70.34  98.74  96.89     49    0.468   115    2.208    2.676
  0.00   3.61  80.16  70.32  98.77  96.89     51    0.478   120    2.308    2.786
  0.00   2.88  88.76  70.33  98.77  96.89     53    0.491   122    2.339    2.829
  2.80   0.00  19.37  70.34  98.77  96.89     56    0.509   125    2.377    2.886
  4.05   0.00  40.13  70.34  98.77  96.89     58    0.526   127    2.396    2.923
  3.64   0.00  41.64  70.33  98.77  96.89     60    0.535   131    2.493    3.028
  4.59   0.00  86.03  70.33  98.77  96.89     62    0.548   135    2.577    3.125

gc日志

再看gc日志，kafka默认开启了gc日志（位于：logs/kafkaServer-gc.log.0.current）：

2018-08-20T14:12:14.366+0800: 144.545: [CMS-concurrent-sweep: 0.009/0.009 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
2018-08-20T14:12:14.372+0800: 144.552: [CMS-concurrent-reset-start]
2018-08-20T14:12:14.379+0800: 144.559: [CMS-concurrent-reset: 0.007/0.007 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2018-08-20T14:12:14.683+0800: 144.863: [GC (Allocation Failure) Before GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 7421969
Max   Chunk Size: 7397322
Number of Blocks: 47
Av.  Block  Size: 157914
Tree      Height: 11
Statistics for IndexedFreeLists:
--------------------------------
Total Free Space: 32849
Max   Chunk Size: 254
Number of Blocks: 2065
Av.  Block  Size: 15
 free=7454818 frag=0.0154
2018-08-20T14:12:14.683+0800: 144.863: [ParNew: 52960K->791K(59008K), 0.0287046 secs] 191199K->139086K(255616K)After GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 7421969
Max   Chunk Size: 7397322
Number of Blocks: 47
Av.  Block  Size: 157914
Tree      Height: 11
Statistics for IndexedFreeLists:
--------------------------------
Total Free Space: 25698
Max   Chunk Size: 254
Number of Blocks: 452
Av.  Block  Size: 56
 free=7447667 frag=0.0135
, 0.0289033 secs] [Times: user=0.03 sys=0.00, real=0.03 secs] 
2018-08-20T14:12:14.714+0800: 144.894: [GC (CMS Initial Mark) [1 CMS-initial-mark: 138295K(196608K)] 139776K(255616K), 0.0024734 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
2018-08-20T14:12:14.717+0800: 144.896: [CMS-concurrent-mark-start]
2018-08-20T14:12:14.739+0800: 144.918: [CMS-concurrent-mark: 0.022/0.022 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]