记一次 android 线上 oom 问题

Posted 2021-12-03 goodcitizen

oom (out of memory) 问题非常不好排查，特别是线上代码出问题的时候，真是一个头两个大，然而楼主就遇到了这样的倒霉事，看看楼主是怎么硬着头皮解决的吧，顺便搭一波联合征文的东风…

背景

公司的主打产品是一款跨平台的 App，我的部门负责为它提供底层的 sdk 用于数据传输，我负责的是 Adnroid 端的 sdk 开发。

sdk 并不直接加载在 App 主进程，而是隔离在一个单独进程中，然后两个进程通过 tcp 连接进行通信的，这样做的目的是减少因 sdk 的崩溃带来的主进程 crash，为用户带来更好的体验。

如上图所示，sdk 主要实现于 service.so 中被 Work 进程加载，kernel.so 通过 jni 嵌入在 App 主进程，前者作为侦听端，后者是连接端。

不过这样做有一个问题，当侦听端口被占用时，两个进程就无法建立通信了，导致数据无法传输。为了解决这个问题，打算用本地 socket (unix domain socket) 代替 tcp socket，因为前者不依赖端口号，只依赖文件路径，而 Android 中的私有存储可以有效的防止文件冲突。

这个替换过程也不能一蹴而就，因为 App 进程加载的 so 与 Work 进程加载的可能并不是一个版本，考虑到向后兼容，新的 service 版本需要同时侦听 tcp 与 local 两个通道，新的 kernel 版本也需要同时连接两个通道，哪个先连接上就用哪个。

开发完成的自测阶段一切正常，验证了以下组合：

连接端	侦听端	结果
tcp	local, tcp	tcp 成功
local	local, tcp	local 成功
local, tcp	tcp	tcp 成功
local, tcp	local, tcp	local, tcp 均成功，一般 local 抢先

结果符合预期，提测阶段也顺利通过，于是通过版本灰度，逐渐替换线上的旧版本，各个灰度阶段观察正常，最后正式全量发布。

问题发生

全量两天后，正式将特性分支合入 master，结果合入没 30 分钟，QA 反馈主端 oom (out of memory) 崩溃异常升高，需要回滚版本验证。

了解了一下情况，发现主端的全部版本崩溃率确实从 0.01％ 升高到了 0.05％~0.07% 的水平，且大量新增的崩溃类型堆栈显示 oom 信息，最关键的是崩溃升高的趋势和 sdk 灰度的节奏完全吻合，而这期间主端也没有发布新的版本，于是只能回滚 sdk 版本尝试。

糟糕的是刚刚合入代码，使用 revert 回滚提交的几个 commit，又出现了一大堆冲突提示。正在解决冲突的过程中，QA 等不急了，建议从之前合入的位置直接拉分支打版本，一顿操作猛于虎，很快就打好了回滚版本，当天就通过测试小流量了。

第二天来了一看，崩溃率果然应声下降，于是 QA 开启全量修复。同时研究了一个短平快的 master 回滚方案：新建一个目录，clone 并 checkout 到合入前的代码，将 .git 目录删除后用这个目录覆盖旧的工作目录，最后将所有 modified 的文件作为新版本直接提交。这样做的好处是可以得到与合入前完全一样的代码，防止手工处理冲突引入新的变更。

问题分析

随着回滚版本的放量，主端 oom 崩溃逐渐回归正常，进一步坐实了新版本存在问题。oom 问题非常不好排查，原因是崩溃时的堆栈与引入 bug 的地方已经相差了十万八千里，不能直接定位问题点。

好在这个版本之前做过一次小流量，看当时的崩溃率没有明显升高，在准备全量前，合入了 master 上的最新修改、ios 平台的一些代码等，因此重点排查两个版本的差异部分，应该就可以定位引入问题的点了。

走查了一遍，没有发现明显的内存泄漏代码：

• master 是稳定版本，不存在内存泄漏；
• ios 平台代码通过宏定义作了隔离，对 android 没有影响；

只有一个地方非常可疑——这是一个日志上报操作，只在特定场景下发生，日志上报时并不是直接上报到服务器，而是放入一个队列，再由专门的线程负责上传。一次上报并不会占用太多内存，但关键是一旦进入这个特定场景，日志就会一直产生，而主端会在传输数据的过程中频繁调用这个接口，导致大量的日志进入队列，特别是当用户处于非 WIFI 环境下，日志上报会被关闭来节省流量，进一步加剧了队列积压，最终导致队列疯狂增长耗尽内存……

知道了原因，改起来就简单了，加一个 bool 标记，上报过后设置这个标记下次就不再上报了，因为这类日志有一条用来排查问题就足够了。

问题定位

修复版都打好准备送测了，老大的一句话提醒了我——最好能在本地复现一下。于是基于有问题的版本，稍加修改让它一启动就不停上报日志，关闭 WIFI 打开 4G，用这个版本在测试机上跑了一整天，进程居然没崩溃！

于是不得不评估一下日志上报的泄漏规模，按一条日志最大 300 字节、主端 2 次/秒的调用频率计算，一天占用内存为 300 * 2 * 3600 * 24 = 51840000 B < 50 MB，虽然也不小了，但是对于动辙 4~8 GB 的智能手机而言，实在不算什么，要想泄漏 4 GB 得不关机运行将近 82 天，不要说现在没有这样一直不关机的用户，即使有，Android 的后台进程优化功能也早就将 App 杀了上万遍了，哪容你泄漏这么久～ 别说你不是微信，就是微信系统该杀也就杀了~

与同事一起研究这个问题后，自己又提出来一个疑点：假如是因为日志泄漏导致的 oom，那应该是 Work 进程崩溃，而不是出现大量的 App 进程崩溃。如果是因为内存耗尽导致系统上所有进程崩溃，那也至少是崩溃率一起升高，而不像现在只有 App 进程崩溃率升高，所以越看越不像是这个原因导致的。

问题根因

正当排查方向一片迷茫的时候，同事的一句话提醒了我——如果能抓到崩溃现场的日志就好办了。可是怎么抓呢？崩溃平台记录的是崩溃时间和 CUID，后者用于标识一次唯一的崩溃事件；日志抓取需要时间范围和用户 UID，而崩溃平台并不提供 UID。

这时同事神秘兮兮的祭出了一条链接，点开一看：ID-Mapping，可以将各种系统的 ID 进行批量转换，其中就包括 CUID 向 UID 的转换，好家伙，这不就是我想要的？老同事真的浑身都是宝，摸着他们过河错不了~

大部分 UID 没有捞取到日志，只有两个用户有日志。内容非常多但都是重复的，看起来 Work 进程没有启动，导致连接端一直在进行重连。在连接后期都发现了这样的日志：

2021-10-30T20:55:19.84255454 [b61e7920] {netio} LocalHandler::post_connect: local endpoint failed with system:24, fatal error
2021-10-30T20:55:19.84408116 [b61e7920] {netio} kernel_message_transmit:handle_io: pipeerror|system:24 type=1|channel=1
2021-10-30T20:55:19.84480116 [b61e7920] {netio} kernel_message_transmit:handle_io: pipeerror|system:24 type=1|channel=2
2021-10-30T20:55:31.05991064 [b61e7920] {netio} kernel_service_interface:on_ready_timeout: restart! running=1, channel=0

查了下系统错误码：

#define EMFILE      24  /* Too many open files */

这种错误一般是打开的句柄超过 linux 进程的最大打开文件句柄数 (一般是 1024)，这个值对于服务器程序来说一般是不够用的，需要通过系统设置来拉高上限。但对于 App 进程是足够了，怎么会超限呢？难道是出现了句柄泄漏。于是马上去走查了连接关闭的代码：

if channel=\'local\' then 
  close local_channel 
else if channel=\'tcp\' then 
  close tcp_channel
else
  nothing
        
channel = \'none\'

这里使用了伪代码来说明大意，其中 channel 标记当前使用的连接方式，初始时设置为 none，连接时两种方式同时发送异步连接请求，先收到应答的连接将设置对应的 channel 值并关闭另一种连接通道，连接建立成功后 channel 必为两种方式之一 (local | tcp)。

上面推演的是正常的场景，当 Work 进程没有启动而导致两个通道都无法完成连接时，channel 将一直保持 none 值直到超时，再连接重启前，会尝试使用上面这段代码清理资源，此时就会命中最后的 else 逻辑——什么也不做——从而导致连接句柄被泄漏。以 10 秒重连、6 秒超时一次计算，每 16 秒就泄漏 2 个句柄，1024 个句柄泄漏光只需要不到 2 小时！

为了验证，专门修改了一版代码，人为制造 Work 进程不启动的场景，果然跑了没多久 App 进程就崩溃重启了。确定了问题根因，再回顾一下现象，之前那几个疑问就能得到解释了：

• 问题表现为打开文件、创建线程均失败的 oom 问题，实际是 oof (out of fd)，句柄泄漏的表现和内存泄漏有相似的地方
• 问题存在于 kernel，当 kernel 耗光句柄后对应的 App 进程会因 EMFILE 错误崩溃，Work 进程反而是没什么事，所以表现为 App 进程崩溃率单独升高
• 只影响一部分 Work 进程长时间不启动的用户，这部分用户占比较少，所以崩溃率升高有限
• 之前小流量的那版也有问题，只是放量较少所以崩溃率升高不明显而已

问题的修复非常简单，就是在关闭清理资源时，不再根据 channel 判断，直接 close 所有句柄。打好的修复版本在 Work 进程不启动的场景下运行了一天也没有出现崩溃，对外灰度后，观察 App 崩溃率正常，逐步全量覆盖线上版本，最后合入 master。

结语

复盘整个 oom 问题产生的过程，为何在灰度阶段没有发现 App 进程崩溃率异常升高呢？原来在看崩溃数据时是过滤了 sdk 版本号的，而实际发生异常升高的版本号却是奇特的 0.0.0.1 版本，因而没有观察到。

为何 oom 问题会集中在 0.0.0.1 版本中？进一步排查发现并非只有 oom 崩溃是这样，90% 的崩溃都归类在了这个版本下面，原因竟然是 App 在初始化时没有处理好先后关系，从 sdk 拿版本号时 sdk 还未初始化，所以得到了一个无效的版本值。更严重的是，该问题几乎一直存在，而我们之前过滤版本号的做法几乎可以肯定是不正确的，想到这里不由得背上直冒冷汗！幸好有这次问题的复盘，不然这个问题要继续存在多久还是个未知数~

最后总结一下 oom 问题的处理方法，首先不要心慌，特别是在不经求证的情况下靠猜测来定位问题、靠不断发小版本在线上验证问题，这样做一来不严谨，二来效率比较低，最终很可能还会定位不到问题。最好的办法是通过现场日志来定位出错的场景，可以极大的缩小排查范围；另外 oom 与 oof 在 Java 崩溃堆栈中有相似的表现，因此遇到这类问题可以多考虑下句柄泄漏的可能性，而不是一味观察内存的分配与释放。

另外可能还有人对 Work 进程为何没有启动感兴趣，但这就属于另外一个问题了，可以单独写篇文章了。目前仍在排查中，真的是应了那句：生命不息，debug 不止~~

参考

[1]. Git 如何优雅地回退代码，用 reset 还是 revert？