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

日常问题排查-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运算。

为什么以前没问题上了个版本就出问题了

首先这个肯定和修改的代码没有关系，笔者推测是由于上游流量的变化导致了批次数量的变化。这个也在后续的数据分析中得到了相关的印证。

解决方案

找到根本原因之后，解决这个问题就很简单了，将分批数给设定一个最大值，强制限制分批大小。代码只需寥寥数行，但是要知道怎么改则需要大量的观察和分析。

总结

Younggc时间变长是一个比较棘手的问题，因为它的可观测信息过少，而且往往和代码变更无关，而和请求分布导致的内存生成速率与存活分布有关。这时候只有通过大量的观察来分析各种数据间的相关性然后通过底层原理推断出因果性，最后才能找到根因。