记一次 android 线上 oom 问题

• 2021 年 11 月 29 日
• 筆記
• Android, debug, leaks, oof, oom, uds, 线上

背景

公司的主打产品是一款跨平台的 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 版本也需要同时连接两个通道，哪个先连接上就用哪个。

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

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

问题发生

全量两天后，正式将特性分支合入 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？