MyBatis批量插入导致内存溢出问题分析

type

status

date

slug

summary

背景

上午突然收到大量告警：开始是服务调用超时，然后是OOM，最后在排查过程中自行恢复了。虽然恢复了，但是还是必须要定位一下原因，不然下次可能就没这么“幸运”了。

现象

当时的调用超时异常如下：

OOM异常如下：

分析

我们发现，这个notify-service的两台实例里，只有一台实例有服务调用超时以及OOM的现象，而另外一台并没有，从cpu使用率监控也能看出来：

另外，我们还观察了调用超时的相关提供者服务，它们在对应时间点并没有波动。

基于以上两点，基本可以断定是由于调用端GC，产生了STW，导致了调用超时。我们来看看notify-service 出问题那台实例的gc日志：

可以看到，11:19:05~11:25:41 有大量超过0.5秒的gc，gc导致了长时间的STW。

那是什么导致了内存占用突然升高并且GC不掉呢？接下来我们就来分析hprof文件

如上图所示，内存占用高的几乎都是notifyTaskThreadPool这个自定义的线程池里的线程，单个线程占用的内存最高的竟然有60M+。我们来看看都是什么对象：

这里的4个字符数组就是内存占用的“罪魁祸首”，并且可以看到里面存储的都是具体待执行的SQL（有微小的区别，可以忽略）。我们再结合线程的堆栈信息一起分析：

可以看到这几个“大对象”都是MyBatis内部使用的。这里我们先不去进一步分析这些大对象具体都是干嘛的，先来看看具体的业务场景：

notifyTaskThreadPool这个线程池是用来做消息拆分的，所谓消息拆分就是把一条消息发送任务拆分到每个发送对象维度。比如我创建了一个给杭州所有的用户发一条“恭喜发财”通知的任务，这个时候，notifyTaskThreadPool就会去拆分这个任务，给每个杭州的用户都创建一条notify_record记录，显然这里的拆分数量可能会很大，所以我们采用了每500条记录分批插入的方式，而500条记录的插入SQL拼接起来竟然达到了10M+的大小，主要是MyBatis拼的SQL里包含了大量的空格和换行符，如下所示：

大量的空格和换行极大地增加了字符串的体积。并且，出问题的时候，这样的大型任务同一时间创建了50个，而我们的线程池的最大线程数量是64。

下面我们再看看MyBatis内部为什么会基于SQL字符串衍生出那么多“大对象”。除了DynamicContext，其他的变量都可以在下面这个类里找到线索：

总结

至此，这个问题已经非常清晰了，并且，其实batchInsert场景下的OOM我们也不是第一次碰到了，只是之前没有深入的去分析问题，基本上把每批次的数量降下来就可以了，甚至有一些在写的时候并没有考虑批次，一次性查出来一次性插入。

针对于这个特定的业务场景，我们做了以下优化：

减少每批次插入的数量（500->100），因为每一次循环处理完之后内存就可以回收了

减少notifyTaskThreadPool线程池的线程数量（64->10），因为减少了并发的同时占用，并且发送大批量消息的实时性要求也不高

可以适当增加JVM堆内存

优化MyBatis拼SQL的逻辑，减少不必要的空格和换行，这块看了一下可能相对麻烦一下，以后再说了