如何检测 iOS app 卡顿导致的系统强杀

如何检测 iOS app 卡顿导致的系统强杀

在之前的文章中提到过,现有市面上的 iPhone 老设备(特指 iPhone 6s 之前的设备)占有率高达 40%,iOS app 卡顿的发生率发生概率也很高。卡顿里有一类卡顿又尤其严重:主线程长期不响应而导致的系统 Watchdog 强杀。

现在很多 iOS 线上 App 都集成了卡顿检测工具,原理多是基于 runloop 的各个事件回调,这类工具可以检测主线程是否在某个 threshold(比如 2 秒) 内是否处于可反应状态,比如重复进入某个 runloop 即可认为主线程没有被卡住。我们姑且称这类工具为 AppWatchdog,但对于严重的主线程卡顿,比如超过 10 秒会被系统强杀,我们称这种系统机制为 iOSWatchdog。为了方便表述,我们进一步将 AppWatchdog 侦测到的卡顿我们称为 stall,iOSWatchdog 强杀的卡顿我们称为 hard stall。

AppWatchdog 侦测到的 stall 很好分析,我们只需要在发生 stall 时,在另外一个线程将主线程的 call stack 记录下来上报即可,而后对症下药在下个版本修复。但对于 hard stall,准确检测很难,原因是系统强杀时并没有任何信号提醒,也不会像 crash 一样生成一个 report,现在主流 App 是怎么做的呢?

我们先从 Facebook 曾经公开发布过的一篇相关文章说起:Reducing FOOMs in the Facebook iOS app

这篇文章系统化的提出了 iOS App 冷启动分析方法,比如 App 升级,用户强杀,App crash,系统升级,后台内存不够(BOOM),前台内存不够(FOOM)等,类似一个 pipeline,一个个分析下来,最后剩下的就是 FOOM,即 app 在前台由于消耗过多内存而被系统强杀。

近两年大家开始意识到这个 pipeline 漏分析了一个重要的冷启动原因:hard stall,而且事实证明 hard stall 出现的概率还不低。可能大家也没意识到 hard stall 会这么容易出现在线上 App 中。

在继续分析之前,我们再进一步明确下 hard stall 的定义,一般我们指系统强杀为 hard stall,但一般用户会在 App 卡顿长达 10 秒之久时依旧等待吗?我比较怀疑,我认为相当一部分用户会提前手动杀掉 App,还有一小部分用户会直接放弃当前 App 进入后台。我觉得我们可以将这类导致用户中断当前任务的卡顿都称为 hard stall,虽然不是系统强杀,但在严重性质上相差无几。

微信客户端团队曾经分享过一篇类似主题的文章:iOS微信内存监控 ,其中有一段相关表述:

前台卡死引起系统watchdog强杀
也就是常见的0x8badf00d,通常原因是前台线程过多,死锁,或CPU使用率持续过高等,这类强杀无法被App捕获。为此我们结合了已有卡顿系统,当前台运行最后一刻有捕获到卡顿,我们认为这次启动是被watchdog强杀。同时我们从FOOM划分出新的重启原因叫“APP前台卡死导致重启”,列入重点关注。

所以微信客户端的做法是检查 stall 的时间戳和冷启动的时间戳,如果二者比较接近,则认为是 hard stall。这种做法应该比较简单有效,但无法检测用户放弃当前任务的 hard stall 场景,而”‘相近“的 threshold 取多少秒也难以把握。FB 内部也有一套机制来区分 stall 与 hard stall,但我个人感觉也不是十分准确,最近在思考如何改进这一检测机制,现在大致有个思路和大家分享,等下半年抽空实践下。

如何检测

用一句话来概括这个思路就是:如果 stall 导致 runloop 无法从当前任务中恢复,则认之为 hard stall

我们知道,主线程的 runloop 用来处理各种任务,每一次 loop 会触发几种不同类型的回调:

kCFRunLoopBeforeTimers 
kCFRunLoopBeforeSources 
kCFRunLoopBeforeWaiting 
kCFRunLoopAfterWaiting 

某个回调可能会触发我们客户端里的某个耗时任务,一般一个 loop 里会触发多个任务,比如 job1,job2,job3,执行顺序及耗时如下:

job1(10ms) --> job2(1500ms)-->job3(15000ms) --> 一小时之后冷启动

很明显,job1 是安全的,job2 会触发 stall,并被我们的 AppWatchdog 工具检测上报(假设 threshold 为 2s),job3 会首先被 AppWatchdog 检测,而后由于长期阻塞主线程,被系统 watchdog 强杀,是真正的 hard stall。那么当我们在后台看到 job2 和 job3 的上报日志时,怎么判断那个才是 hard stall 呢?显然我们无法记录每一个任务的执行时间,所以并不知道 job2 和 job3 哪个更严重,或者说 job3 是不是足够严重。

回到上面对于思路的概括,我们就看 runloop 能否从 stall 当中恢复出来,我们可以在 runloop 每次进入不同事件的时候,如果上次发生过 stall,我们就记录一个新的时间戳 activeTs,来表示 runloop 在未来某个时间点从 stall 中恢复了,然后再在下次冷启动的时候做如下判断:

if (report.stallTs < activeTs) {
  report.isHardStall = true;
} else {
  report.isHardStall = false;
}

所以上面的时间序列会变成:

job1(10ms) --> job2(1500ms)-->activeTs-->job3(15000ms) --> 一小时之后冷启动

很显然,job2 执行之后,我们记录一个 runloop 活跃的时间戳,那么表明 job2 是常规 stall,而 job3 由于耗时过长导致系统强杀,runloop 没有机会进入下一次 loop,则没有记录下最新的 activeTs,所以,依据上面的条件判断,可以轻易的检测出 job2 为常规 stall,而 job3 为 hard stall。

这种判断机制更有针对性,所以即使 hard stall 之后用户放弃当前任务,过很长时间之后再次启动 App,我们依然能够判断出哪个 stall(call stack)是真正的 hard stall。

一些细节

说完大致思路,看着好像并不怎么复杂,但魔鬼藏在细节里,有哪些需要注意的细节呢?暂时想到的有:

  • stall 检测工具是为了检测 stall,所以本身应该轻量,尽量避免费时的任务或者是 disk I/O,而记录 activeTs 必然会有一次额外的磁盘写操作,我们应该做到一次 App 启动最多只记录一次 activeTs 到磁盘里,而且只发生在有 stall 的情况下。
  • 为了效率起见,在下次冷启动的时候,我们应该只处理上次启动留下的 stall reports,也能够避免记录过多的 activeTs。为此,我们需要引入一个 Session 的概念,即每一次启动对应一次 Session,每个 Session 只处理上一个 Session 的 stall reports,我们可以将一个连续自增长的 Session ID 写入 stall report 里,这样就知道每一个 stall 对应那一次启动,甚至可以将 Session ID 写入 stall report 的文件名,方便过滤,既高效有简洁。
  • 如果 runloop 在执行完某个任务进入休眠,获得 kCFRunLoopBeforeWaiting 回调,此时我们也需要记录 activeTs,因为能够进入休眠表明非 hard stall。

最后用图再描述下具体思路:

等待真正去实现的时候,估计还有不少细节需要处理,后面做好了再更新一篇文章。

全文完。

发布于 2018-06-04 08:10