日常问题排查-Younggc突然变长 - 无毁的湖光

news/2025/10/20 9:22:22/文章来源:https://www.cnblogs.com/alchemystar/p/19150110

日常问题排查-Younggc突然变长

前言

研发突然反馈一个版本上线后线上系统younggc时间变长，而这个版本修改的代码就是非常普通的CRUD，但是younggc时间就硬生生暴涨了100%。导致天天告警，虽然问题不大，但非常想知道原因，于是向我求助。

问题现场

如下图所示,younggc一个版本后从60ms涨到了120ms。而告警的阈值在100ms，导致每次younggc都告警。显然，调整告警阈值是最简单的方案，但作为一个有好奇心对技术很执着的同学，他很纠结于这个问题。当然我也是遇到有意思的问题就必须去一探究竟的性格，两者一拍即合。

代码改动

第一反应肯定是去看代码的变化，代码改变如下所示:

改之前:
void functionA(){......a.setBuinsessKey(key1);......
}改之后:
void functionB(){......a.setBusinessKey(Key1);a.setBuinessesKey(Key2);a.setBusinessKey(Key3);......
}

看着这微小的改动引起了这么大的变化，这是不可能的。笔者第一时间便否决了这种可能性。

流量变化

以这么多年我troubleshooting的第一直觉，肯定是负载变化才能引起younggc耗时的变化。询问那位同学，他明显是已经考虑了这样的问题。当即甩给了我相关的监控截图。从分钟级的尺度来讲，没有任何变化。

容器问题

由于younggc耗时高集中在几台机器上，于是笔者登陆上那几台机器，发现在younggc耗时变高的时候都出现了nr_throttled，也就是当前容器的CPU时间片消耗达到了配置的cgroup上限，导致被kernel强制offline了。但到底是younggc导致了throttle还是throttle导致了younggc，这个因果关系以现有的信息来说完全无法判断。

Younggc日志

既然不能一眼看出来原因，那只能上去分析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哪些数据

问了一下gemini，object copy的对象一般有从

1.从Eden Region复制到Survivor Region
2.从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-120ms
case 2: 分了5000批，每批处理2000条数据，Survivor区50M，对应的youggc在50-70ms

发现了这个规律之后，笔者去看了下业务系统的源代码。其伪代码如下所示:

// 这边的batchNo就是
for(long batchNo : batchNoList) { 	// 按照批次从数据库中捞取相关数据List<Task> task = selectFromDBBatchNo(bachNo);// 处理相关数据	handleTask(task);
}

看到这段代码，上面的规律就很好理解了，batchNoList以及其相关数据是一直在for的计数里面，一直到处理完毕整个batchNoList以及其相关数据的引用都不会被回收。所以batchNoList(批次)数量越大，在Survivor区younggc的时候需要copy到old区的数据量就越多。反而在每次循环的循环体中，通过batchNo从数据库中捞取的数据在处理完之后就没用了，younggc的时候自然消亡，完全不参与相关younggc运算。