线上OOM分析 2/119

发表于 2021-11-19

记一次mybatis引起的线上OOM

最近在忙着加班+找房换租的窝，所有很久没写博客，社畜的艰苦生活，哈哈

言归正传，最近线上一个小项目，出现了特殊的OOM情况，很有意思，所以跟大家分享一下

奇特的内存溢出现象

项目背景：

公司有某个线下零售业务部门，有POS一千台左右，业务和门店还在持续扩张中。业务现有的CRM和POS修改起来较为困难(全为供应商标准系统)。
业务有个中间件，用于接受POS的一个结账前的会员信息请求，转发到SRM系统获取基础信息后，然后查数据库表做数据加工后再返回POS，以此来做双方系统的自定义配置。(个人不认可这种方案)
这个小项目是由我们组的一个小伙伴完成开发，压测完成后部署在阿里云上，2台ECS做了负载均衡。

溢出现场:

项目上线后，间隔一段时间后，用户反馈POS有些门店请求报错。上服务器查询日志发现报了内存溢出，项目已经被守护进程自动重启，无法查看溢出时内存具体成分。查看代码报错，是请求导致的OOM报错。结合之前的日志分析发现，崩溃前已经发生多次内存无法回收的异常。查看ECS的监控，发现内存是缓慢上升的。断定发生了内存泄漏。
监控了一段时间后，发现被重启后应用，内存依旧在缓慢上升。并发高发时间段是在晚上7-8点，而内存溢出发生在晚上9点多。所以也并不是并发引起的。思考这种内存无法释放的缓慢OOM，单靠增加内存或者JVM调优是很难解决的，应该是小伙伴的代码中有对象没有及时释放导致的，此时已经晚上十点多，门店已经关店，无法观察内存变化，而且之前压测也没有出现OOM。考虑有可能需要长压测来让内存缓慢累计，所有起了压测程序，参数并发调低，压测时间改为连续3小时。等待明早观察成果。

问题定位

早上发现内存回收正常，尝试分析内存内容。无法复现的异常，很难解决，尝试观察内存状况。
先用 jmap -histo 在服务器上查看哪些对象内存占用异常。
结果发现都是 char 并无异常。于是打开窗口连接2台服务器，持续监控2台机器的内存状况。同时打开代码，找寻可能异常点。
（最小化接着做其他的事情）
中午左右，观察到其中一台服务器内存持续上升。立刻将负载均衡全部切换到另一台上，保护现场防止再崩溃。
开始处理分析内存内容：
1，使用 jmap -histo 在服务器上查看内存中哪些对象异常。
发现除了 char map 这些基础类，还有 CurrentHashMap 占用很多。
CurrentHashMap ？采用了数组+链表+红黑树的实现方式来设计，内部大量采用CAS操作，是线程安全性的map，锁的颗粒度是到数组。因为该项目并不涉及到多线程，找寻项目代码果然没有这方面的引用。
2, 发现不能迅速定位，先保存下内存状态。使用 jmap -dump:format=b,file=文件名 [pid] 将内存数据导出成二进制文件。
下载下来后，重启服务，调回负载均衡。
3，使用 java 自带 VisualVM 来分析内存中的类及其引用。
发现大量的char和原始值引用指向CurrentHashMap，同时存在某个 entity 占用也过多。
这时想到 mybatis 源码是将数据映射成map，处理并发时应该会有CurrentHashMap。正好也和某个实例占用过多吻合。
打开 mybatis 源码发现在一级缓存和二级缓存，果然是使用 CurrentHashMap 来接收缓存的。
难道缓存没释放？
mybatis 一级缓存是SqlSession内的，二级缓存是基于namespace。如果是缓存没释放那我将二级缓存关闭试试。于是将二级缓存配置关闭。配置数据库请求超时时间后。
本地压测通过（之前压测就无法复现），打包发布至其中一台服务器，做个对比验证。

问题解决

以为问题已经解决，安心下班，晚上收到运维小伙伴反馈，服务器内存报警了。
–”，还是我新发布的那台。立刻上线查看，还是内存缓慢溢出。缓存已经关闭了，还是大量的引用指向CurrentHashMap？
这难道不是缓存引起的？那还有什么能够让CurrentHashMap撑爆内存？
没关系，已经定位到是mybatis的问题了，下面应该从SQL入手去看看，有没有什么SQL的异常。
看了对应namespace的sql，咦？这个sql写的有点怪，把id包在if判断里也正常，难道id也有可能不存在，如果id不存在，那这个sql就会变成全部查询？
那也会超时被断开呀？没怎么用过oracle，难道真的是这里？
戴着疑问，我让DBA把表发给我，oracle的自增id是DBA自己用触发器生成，但是真的会有业务数据没有id嘛？我跑了sql查了一下，真的！！！有极个别几个用户的在业务表id居然是null。
突然间豁然开朗，一切问题都能解释通了。
小伙伴代码有个基于id的查询，没有判断id是否为空（id还有为空的？算了不想吐槽了）。id传到mapper时，查询条件被过滤掉，形成了一个全表查询。
oracle的查询是流式缓慢吐出数据，所以照成内存缓慢增加，因为id为空是极个别现象所以照成了内存溢出是随机的现象。
mybatis 查询sql会先把值存在缓存里，所以分析内存时，发现缓存中的CurrentHashMap引用大量entity，占据内存不释放。

到此问题原因已经找到，于是在查询前，增加了一个id为空的判断，发布后监控内存状况。

第二天，果然没有再出现内存泄漏问题，于是问题解决（小伙伴和DBA关于id为空撕逼中）。

过程中忘了截图，没有图大家将就着看吧，过程中主要用到了jmap的相关命令、VisualVM内存分析、mybatis源码和自己敏锐的问题觉察能力