写点什么

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

作者:wgy
  • 2022 年 7 月 04 日
  • 本文字数:6290 字

    阅读完需:约 21 分钟

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 秒)的影响:


在当前的情况下,假定时间周期为 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: [ParNewDesired 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_sizepreferred_max_new_size的值定义在:



preferred_max_new_sizepreferred_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 时间为目标来优化程序,因为最终用户只关心发出请求到响应所话费的时间,也就是响应速度,而不太关心程序到底是用了多少个线程或者处理器来完成任务。

发布于: 刚刚阅读数: 3
用户头像

wgy

关注

还未添加个人签名 2015.07.17 加入

还未添加个人简介

评论

发布
暂无评论
容器环境minor gc异常频繁分析_Java_wgy_InfoQ写作社区