宋寿袄玖前言研发突然反馈一个版本上线后线上系统younggc时间变长而这个版本修改的代码就是非常普通的CRUD但是younggc时间就硬生生暴涨了100%。导致天天告警虽然问题不大但非常想知道原因于是向我求助。问题现场如下图所示,younggc一个版本后从60ms涨到了120ms。而告警的阈值在100ms导致每次younggc都告警。显然调整告警阈值是最简单的方案但作为一个有好奇心对技术很执着的同学他很纠结于这个问题。当然我也是遇到有意思的问题就必须去一探究竟的性格两者一拍即合。younggc_slower代码改动第一反应肯定是去看代码的变化代码改变如下所示:改之前:void functionA(){......a.setBuinsessKey(key1);......}改之后:void functionB(){......a.setBusinessKey(Key1);a.setBuinessesKey(Key2);a.setBusinessKey(Key3);......}看着这微小的改动引起了这么大的变化这是不可能的。笔者第一时间便否决了这种可能性。流量变化以这么多年我troubleshooting的第一直觉肯定是负载变化才能引起younggc耗时的变化。询问那位同学他明显是已经考虑了这样的问题。当即甩给了我相关的监控截图。从分钟级的尺度来讲没有任何变化。younggc_slower容器问题由于younggc耗时高集中在几台机器上于是笔者登陆上那几台机器发现在younggc耗时变高的时候都出现了nr_throttled也就是当前容器的CPU时间片消耗达到了配置的cgroup上限导致被kernel强制offline了。但到底是younggc导致了throttle还是throttle导致了younggc这个因果关系以现有的信息来说完全无法判断。nr_throttled_deltaYounggc日志既然不能一眼看出来原因那只能上去分析gc日志了比对一下gc。发现差距在Object Copy上。偏长younggc 120ms[Object Copy (ms): Min: 107.5, Avg:108.2,Max:108.9,Diff:0.8,Sum: 869.5]正常younggc 60ms[Object Copy (ms): Min: 55.2, Avg: 56.1, Max:56.3, Diff: 1.1,Sum: 450.0]嗯从这个数据来判断肯定是要Copy的数据变多了。为什么会变多呢看看其younggc后的各年代的变化。偏长younggc 120ms[Eden: 4804.0M(4804.0M)-0.0B(4784.0M) Survivors: 108.0M-128.0M Heap: 6632.7M(8192.0M)-1848.8M(8192.0M)]正常younggc 60ms[Eden: 4848.0M(4848.0M)-0.0B(4832.0M) Survivors: 64.0M-80.0M Heap: 6717.7M(8192.0M)-1888.0M(8192.0M)]笔者敏锐的观察到Survivor区变大了。偏长Younggc Survivor区是108M而正常Younggc Survivor区是64M。Object Copy哪些数据问了一下geminiobject copy的对象一般有从1.从Eden Region复制到Survivor Region2.从Survivor Region复制到老年代Region这两个地方进行Copy。也就是说如果Survivor区变大了之后Object Copy的数据应该是会变多。嗯虽然大模型经常忽悠我但这个回答还是比较符合逻辑的姑且就相信他。观察gc监控鉴于上面的分析笔者突然觉得Younggc的时间很有可能和Survivor区的大小成正比关系。一旦Survivor区大于一个阈值那么Younggc时间就会超过100ms进而导致告警。为了验证这个关系笔者去观察了不同机器正常younggc和偏长younggc的关系。发现完全符合这个规律。为什么Survivor区会变化由于分钟级的请求量没有任何变化。监控当前的精度只能到分钟级于是笔者只能在请求机器上的日志中寻找相关的线索。比较了相关的业务日志笔者敏锐的发现了一个不一样的地方。在相同数据量的情况下分批的次数越多它的Younggc越长。如果一共需要处理100W条数据case 1: 分了10000批每批处理1000条数据Survivor区100M。对应的younggc在100-120mscase 2: 分了5000批每批处理2000条数据Survivor区50M对应的youggc在50-70ms发现了这个规律之后笔者去看了下业务系统的源代码。其伪代码如下所示:// 这边的batchNo就是for(long batchNo : batchNoList) {// 按照批次从数据库中捞取相关数据List task selectFromDBBatchNo(bachNo);// 处理相关数据handleTask(task);}看到这段代码上面的规律就很好理解了batchNoList以及其相关数据是一直在for的计数里面一直到处理完毕整个batchNoList以及其相关数据的引用都不会被回收。所以batchNoList(批次)数量越大在Survivor区younggc的时候需要copy到old区的数据量就越多。反而在每次循环的循环体中通过batchNo从数据库中捞取的数据在处理完之后就没用了younggc的时候自然消亡完全不参与相关younggc运算。long_vs_normal为什么以前没问题上了个版本就出问题了首先这个肯定和修改的代码没有关系笔者推测是由于上游流量的变化导致了批次数量的变化。这个也在后续的数据分析中得到了相关的印证。解决方案找到根本原因之后解决这个问题就很简单了将分批数给设定一个最大值强制限制分批大小。代码只需寥寥数行但是要知道怎么改则需要大量的观察和分析。总结Younggc时间变长是一个比较棘手的问题因为它的可观测信息过少而且往往和代码变更无关而和请求分布导致的内存生成速率与存活分布有关。这时候只有通过大量的观察来分析各种数据间的相关性然后通过底层原理推断出因果性最后才能找到根因。