容器环境minor gc异常频繁分析

1. 问题现场

近日，通过IMP监控发现，生产的容器环境gc很频繁-约40s一次，且都是minor gc，具体的gc日志如下:


从上图中我们可以看到，gc发生在ParNew收集器上，触发的原因是Allocation Failure。当前java进程配置的垃圾收集器是CMS，对应新生代的收集器是ParNew，上图充分说明在进行频繁的minor gc，每次minor gc的时间在30~40ms，minor gc也会产生STW(Stop The Word)，因此，如此的频繁的gc势必会对应用产生不良的影响。
那么，如此频繁的minor gc是如何产生的？
​

2. 问题分析

2.1 频繁minor gc带来的影响

从前面我们可以看到，应用在进行频繁的minor gc，且minor gc导致应用暂停（STW），那么，它对应用的影响到底有多少？
​

一个显而易见的点是，由于minor gc会导致STW，那么在minor gc发生时，会使应用的响应时间延长，假如应用正常状态下响应时间在100ms，那么在触发minor gc时，因为STW的影响，响应时间会变为100+40=140ms。
​

另外，从全局看，我们可以套用以下公式分析下minor gc对GC吞吐量（简单点来说，吞吐量是指应用程序线程用时占程序总用时的比例。 例如，吞吐量99/100意味着100秒的程序执行时间应用程序线程运行了99秒， 而在这一时间段内GC线程只运行了1秒）的影响：

$$Throughput=(1-\frac{{\sum }_{k=1}^n{c}_k\overline{t_k}}{T_n})\times 100\%(C_k为一个周期内GC次数，\overline{t_k}为周期内每次GC耗费的平均时间，T_n为总时间)$$

在当前的情况下，假定时间周期为4分钟，那么，以40s触发一次gc计算，gc触发的次数为460/40=6次，每次gc的时间以40ms计算，那么吞吐量在（1-（640）/(4601000)）*100%=99.9%，这意味着在至少0.1%的时间内，应用是不可用的（当然在用户层面是无感知的）。
​

2.2 GC日志分析

摘一段的GC日志的文本如下：

46834.030: [GC (Allocation Failure) 46834.031: [ParNew
Desired survivor size 4358144 bytes, new threshold 6 (max 6)
- age   1:    1200496 bytes,    1200496 total
- age   2:     673016 bytes,    1873512 total
- age   3:     145352 bytes,    2018864 total
- age   4:     180720 bytes,    2199584 total
- age   5:     153152 bytes,    2352736 total
- age   6:     170024 bytes,    2522760 total
: 71467K->4646K(76672K), 0.0318805 secs] 212747K->146025K(2088640K), 0.0320934 secs] [Times: user=0.03 sys=0.00, real=0.04 secs] 

简单说明下以上的GC日志：
第一行GC发生的时间点在应用启动后46834.030秒，触发GC的原因是Allocation Failure，收集器是ParNew。
​

第二行Desired survivor size的值是4358144 bytes=4.156M（这个值是 survivor区容量 * TargetSurvivorRatio/100，TargetSurvivorRatio默认值是50），动态计算的最大年龄new threshold是6。
​

第三行到第八行是各个年龄段的信息，以age 2为例，673016 bytes是新生代中age=2的对象占用的内存大小，1873512 total是新生代所有小于等于2年龄对象占用内存（1200496+673016=1873512）的大小。
​

第九行的信息比较关键，71467K->4646K(76672K)中，71467K是GC前该内存区域(这里是新生代)使用容量，4646K是GC后该内存区域使用容量，76672K是该内存区域总容量。212747K->146025K(2088640K)中，212747K是GC前堆中内存大小，146025K是GC后堆中内存大小，2088640K是堆的总大小。[Times: user=0.03 sys=0.00, real=0.04 secs] 中我们比较关系real=0.04 secs，代表此次GC实际耗费的时间，具体这几个参数的含义可以参考附录4.2章节。
​

这里我们可以看到，GC前的容量71467K=69.79M非常小，而新生代的总大小是76672K=74.875M也异常的小。在当前的案例中，我们是没有设置新生代的大小，可以使用jinfo命令查看当前java进程的情况：

红框中Non-default VM flags是非vm默认参数（被命令行选项覆盖或者被vm优化策略设置），Command line是启动时的命令行参数，从启动命令中看到，我们没有设置Xmn或者NewSize、MaxNewSize参数，没有设置的原因是因为我们认为使用默认参数计算的新生代大小没有问题（这在虚拟机环境下运行良好），默认新生代的大小和NewRatio参数有关，这个参数的含义是老年代和新生代大小的比例，我们也可以看到当前jvm中这个参数的值：

如果用这种方式计算的话，那么新生代的大小应该是2048M*(1/3)=682.7M，这和GC日志中展现的值完全不相符。
具体的计算说明在oracle的官方文档（https://docs.oracle.com/javase/8/docs/technotes/guides/vm/gctuning/sizing.html#heap_parameters）中有所体现：

The Young Generation

After total available memory, the second most influential factor affecting garbage collection performance is the proportion of the heap dedicated to the young generation. The bigger the young generation, the less often minor collections occur. However, for a bounded heap size, a larger young generation implies a smaller tenured generation, which will increase the frequency of major collections. The optimal choice depends on the lifetime distribution of the objects allocated by the application.
By default, the young generation size is controlled by the parameter NewRatio. For example, setting -XX:NewRatio=3 means that the ratio between the young and tenured generation is 1:3. In other words, the combined size of the eden and survivor spaces will be one-fourth of the total heap size.
The parameters NewSize and MaxNewSize bound the young generation size from below and above. Setting these to the same value fixes the young generation, just as setting -Xms and -Xmx to the same value fixes the total heap size. This is useful for tuning the young generation at a finer granularity than the integral multiples allowed by NewRatio.

682.7M对比74.875M相差巨大，说明我们计算新生代的方式是有误的（至少不完全准确）。仔细观察，我们还可以发现jinfo查看的Non-default VM flags中有NewSize和MaxNewSize，这两个的值都是87228416，单位是byte，换算之后是83.1875M，这就和GC日志中的值非常接近了。
​

那堆中各个区域的实际值到底是多少了，我们还有一个工具-jmap，可以用jmap查看堆中的实际情况：

结果很明显，NewSize=83.1875M，这和jinfo查看到的值是一致的，新生代（New Generation）的大小是Eden区和一个Suvivor区的大小，在启动命令行中，我们没有设置SurvivorRatio的值，因此使用默认值8(约等于)，这意味着Eden区和Suvivor区的比例是8:1，那么一个Suvivor区的大小是NewSize的1/10，此处实际值是8.3125，新生的代的大小是66.5625=8.3125=74.875M，这和GC日志中新生代的容量是一致的。
​

至此，我们可以确定的点是，当前java进程堆中各区域的内存大小和GC日志中的值是一致的，但是，并没有解决NewSize=83.1875M的来源问题。
​

目前，问题似乎没什么其他解决方式了，只能从源码入手。从github下载openjdk的源码（https://github.com/openjdk/jdk），切换到版本对应分支jdk8-b07，全局搜索MaxNewSize，从搜索结果我们定位到这个文件/jdk/hotspot/src/share/vm/runtime/arguments.cpp，里面有一个方法void Arguments::set_cms_and_parnew_gc_flags()用于调整CMS收集器和ParNew收集器的GC参数，这和我们当前java进程使用的收集器是一致的。

这里我们直接摘出其中非常关键的一段：

从这里我们可以看到，如果命令行没有显式地设置NewSize，那么MaxNewSize的值是preferred_max_new_size，preferred_max_new_size的值定义在：

preferred_max_new_size是preferred_max_new_size_unaligned进行了字节对齐，而preferred_max_new_size_unaligned由max_heap/(NewRatio+1)和ScaleForWordSize(young_gen_per_worker * parallel_gc_threads)中的小值决定，max_heap/(NewRatio+1)我们之前计算过，值为682.7M。ScaleForWordSize方法的计算结果由young_gen_per_worker和parallel_gc_threads决定，其中parallel_gc_threads由ParallelGCThreads参数决定，ParallelGCThreads可以用jinfo查看一下：

ParallelGCThreads的值是1（这个值未显式设置，为什么是1后文说明），young_gen_per_worker的值等于CMSyoungGenPerWorker，这个值在在x86的机器上为64M：

再来看看ScaleForWordSize方法：

HeapWordSize在64位的机器上为8字节，上面计算之后的结果大约是83.20M，做最后的对齐之后是83.1875M，这就是最终的MaxNewSize的值，当然这个是适用于CMS+ParNew收集器。而NewSize的值也可以通过MaxNewSize的值最终确定：

2.3 ParallelGCThreads分析

在上面我们提到，preferred_max_new_size_unaligned的值是和ParallelGCThreads有关的，那这个值是从哪里得到的呢？它可以通过命令行参数-XX:ParallelGCThreads=value直接指定，在命令行参数没有指定的时候，它会根据CPU的核数进行计算。

​

对于大多数的机器而言，switch_pt的值为8，在注释中我们也可以看出来，当CPU的核数小于等于8时，ParallelGCThreads的值和CPU核数相等，当CPU的核数大于8时，计算方式是(8+(ncpus-8)*5/8)。在oracle的官方文档中也有相应描述：

On a machine with N hardware threads where N is greater than 8, the parallel collector uses a fixed fraction of N as the number of garbage collector threads. The fraction is approximately 5/8 for large values of N. At values of N below 8, the number used is N. On selected platforms, the fraction drops to 5/16. The specific number of garbage collector threads can be adjusted with a command-line option (which is described later). On a host with one processor, the parallel collector will likely not perform as well as the serial collector because of the overhead required for parallel execution (for example, synchronization). However, when running applications with medium-sized to large-sized heaps, it generally outperforms the serial collector by a modest amount on machines with two processors, and usually performs significantly better than the serial collector when more than two processors are available.

官方文档的描述更为直白，当N大于8的大值时，因子接近于5/8。按照这个算法，我们的ParallelGCThreads是不可能等于1的（生产环境硬件的CPU数总不至于是1），那么问题出在哪里呢？
​

当前有一个非常重要的场景，我们处于容器环境。生产上运行的java版本是jdk 8，而jdk 8的第一个正式版本发布是在2014年3月（原定于2013年）。2013年3月Docker创始人 Solomon Hykes 在 PyCon 大会上的演讲中首次公开介绍了 Docker 这一产品，2014年6月的DockerCon大会上Docker正式发布了Docker 1.0 版本，Docker的稳定性和可靠性已经基本满足了生产环境的运行需求。可以看到，在早期的java版本中，docker技术并没有非常流行，这也意味着早期的jvm虚拟机在docker环境中运行是或多或少的存在一些问题的。
​

我们可以先通过cat /proc/cpuinfo看看容器所在宿主机的CPU核数：

processor的值从0开始计算，那么CPU核数是48。按前文的计算方式，如果jvm取的是宿主机的CPU核数，那么ParallelGCThreads的值应该是48*5/8=30左右，这显然和我们的实际情况不符。前面我们提到，因为jdk 8 发布时，docker并没有大规模流行，所以docker环境运行早期的java版本会出现一些问题，实际这就是其中之一。在容器中运行java程序时，应用可能或获取错误的CPU资源，从而导致程序判断出现错误，引发一些不必要的上下文切换。
​

庆幸的是，从 Java SE 8u131 开始以及在 JDK 9 中，JVM 对 Docker CPU 限制透明地感知 Docker。这意味着如果 -XX:ParalllelGCThreads 或 -XX:CICompilerCount未指定为命令行选项，则 JVM 将应用 Docker CPU limit作为 JVM 在系统上看到的 CPU 数量。然后 JVM 将调整 GC 线程和 JIT 编译器线程的数量，就像它在裸机系统上运行一样，CPU 数量设置为 Docker CPU limit。
​

当前我们设置的cpu limit是1000m，在未显式配置ParallelGCThreads的情况下该参数为1，从而通过前文一系列的计算，使得jvm的MaxNewSize和NewSize的值为83.1875M。在获知这些信息之后，我们尝试修改了CPU limit的值，在修改为大于1000m小于2000m时，ParallelGCThreads的值为2，使用jmap查看堆中各个区域的情况也发生了变化：

此时，NewSize和MaxSize的值变成了166.375M， 是原先的两倍。
​

3. 问题解决

在进行了详尽的问题分析之后，我们得到的结论是：minor gc频繁的原因是由于新生代过小，而过小是由于没有显式地配置MaxNewSize和NewSize的值，从而触发了jvm的一系列机制，最终计算出一个值。那要解决minor gc频繁的问题就很简单了，在命令行设置-Xmn512M（相当于同时设置MaxNewSize和NewSize的值，具体应用具体分析）即可，另外，我们的ParallelGCThreads也有问题，在命令行也加上-XX:ParallelGCThreads=8的配置，在配置完之后，我们观察了GC日志，minor gc的时间间隔从原先的40s提升到了7分钟，提取了近13个小时的gc日志分析如下：



​

4. 附录

4.1 动态对象年龄判定

在《深入理解java虚拟机》第三版中有这么一段话：

为了能更好地适应不同程序的内存状况，HotSpot虚拟机并不死永远要求对象的年龄必须达到-XX:MaxTenuringThreshold才能晋升到老年代，如果在Survivor空间中低于或等于某年龄的所有对象大小的总合大于Survivor空间的一半，年龄大于或等于该年龄的对象就可以直接进入老年代，无需等到-XX:MaxTenuringThreshold中要求的年龄。

这一段话该如何理解呢？
​

前文gc日志（这是调整新生代之前的）中，有这么一段：

Desired survivor size 4358144 bytes, new threshold 6 (max 6)
- age   1:    1200496 bytes,    1200496 total
- age   2:     673016 bytes,    1873512 total
- age   3:     145352 bytes,    2018864 total
- age   4:     180720 bytes,    2199584 total
- age   5:     153152 bytes,    2352736 total
- age   6:     170024 bytes,    2522760 total

Desired survivor size的值是4358144 bytes=4.156M（这个值是 survivor区容量*TargetSurvivorRatio/100，TargetSurvivorRatio默认值是50），当时survivor区的容量是8.3125M。max 6代表的是-XX:MaxTenuringThreshold，这个值我们在命令行中没有设置，使用的是默认值6。以age 6为例，当前小于等于年龄6的对象大小是2522760 bytes，小于4358144 bytes，所以计算的动态年龄等于XX:MaxTenuringThreshold的值6。那假如age 5的总大小已经大于4358144 bytes了，则new threshold会是5，大于等于年龄5的对象都会直接进入老年代。
​

假如动态年龄计算出的new threshold过小，导致大量对象过早进入老年代，可以考虑调整SurvivorRatio的值，将Survivor空间放大一些。
​

4.2 usr, sys, real含义

• user是进程执行用户态代码所耗费的处理器时间。
• sys是进程执行内核态代码所耗费的处理器时间。
• real是执行动作从开始到结束耗费的时钟时间。

user和sys是处理器时间，real是时钟时间，他们的区别是处理器时间代表的是线程占用一个核心的耗时计数，而时钟时间是现实世界中的时间的计数。如果是单核单线程的场景，这两者可以认为是等价的，但是在多核场景下，同一个时钟时间内有多少处理器核心正在工作，就会有多少倍的处理器时间被消耗和记录下来。
​

在垃圾收集调优时，我们主要依据real时间为目标来优化程序，因为最终用户只关心发出请求到响应所话费的时间，也就是响应速度，而不太关心程序到底是用了多少个线程或者处理器来完成任务。