背景
公司的主打产品是一款跨平台的 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 进程没有启动,导致连接端一直在进行重连。在连接后期都发现了这样的日志:
代码语言:javascript复制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
查了下系统错误码:
代码语言:javascript复制#define EMFILE 24 /* Too many open files */
这种错误一般是打开的句柄超过 linux 进程的最大打开文件句柄数 (一般是 1024),这个值对于服务器程序来说一般是不够用的,需要通过系统设置来拉高上限。但对于 App 进程是足够了,怎么会超限呢?难道是出现了句柄泄漏。于是马上去走查了连接关闭的代码:
代码语言:javascript复制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?