今日头条ANR优化实践系列 - Barrier导致主线程假死( 三 )


今日头条ANR优化实践系列 - Barrier导致主线程假死

文章插图
 

今日头条ANR优化实践系列 - Barrier导致主线程假死

文章插图
 
上图为异步消息的设置和判断是否是异步消息的接口实现,我们日常创建的 Message 是不会设置该属性的 。只有系统在某些特殊场景,如 UI 刷新,为了保障交互体验,会在请求 vsync 信号前,先发送一个 barrier 消息,然后等到 barrier 消息执行时,遍历 vsync 消息并将其强制调整到头部,以保证该类消息的响应能力:barrier 消息设置和移除,实现逻辑如下:
今日头条ANR优化实践系列 - Barrier导致主线程假死

文章插图
 
通过上面实现可以看到,barrier 消息是不会主动移除的,需要设置 barrier 消息的业务消息得到响应后主动移除该消息,否则 barrier 消息会一直存在!
分析到这里就可以很好的解释为何在 MessageQueue.next()接口内部多次调用 NativePollOnce 了,一定是当前的 mMessage 是个 barrier 消息,但是与其关联的业务消息一直没有出现,或者执行之后没有同步移除该消息,导致该 barrier 消息一直处于消息队列头部,每次获取下一个消息时,都被 barrier 拦截和并遍历异步消息,如果有异步消息则响应,没有异步消息则通过 nativePollOnce 进行等待,从而阻塞了正常消息的调度和响应!
进一步梳理 MessageQueue.next 接口执行逻辑,通过下图就可以清晰的看到我们在 Native 层 Hook 时看到 nextPollTimeMills 传参-1 的场景是怎么设置的 。
今日头条ANR优化实践系列 - Barrier导致主线程假死

文章插图
 
那么结合本类 ANR 问题,消息队列第一个待调度的消息是不是 barrier 消息呢?我们再次找到上面分析的案例,通过监控时序图观察第一个被 block 的消息 。
今日头条ANR优化实践系列 - Barrier导致主线程假死

文章插图
 
通过上图可以清晰的看到,当前消息 target 对象为 null,正是 barrier 消息!破案了!
连锁反应:按照上面的分析,如果 barrier 消息没有及时移除,那么每次通过 MessageQueue.next()查询时,只能过滤并返回带有异步属性的消息,如用户点击消息 input,vsync 消息等等 。 即使用户交互和 UI 刷新消息可以正常执行,但是大量业务消息无法执行,这就导致了 UI 展示可能存在异常或功能异常,并且应用 service,receiver 等消息并没有异步属性,因此也会被 block,最终造成响应超时发生 ANR!
结合当前问题,我们发现该用户在第一次 ANR 不久之后再次发生 ANR,主线程 Trace:
今日头条ANR优化实践系列 - Barrier导致主线程假死

文章插图
 
第二次 ANR 时,对应的调度时序图如下:
今日头条ANR优化实践系列 - Barrier导致主线程假死

文章插图
 
通过当前用户连续 2 次 ANR 的消息调度监控时序图可以看到,本次 ANR 时,之前的历史消息记录没有发生任何变化,也就是说第一个 ANR 发生后确实没有再调度其他消息,但 2 次 ANR 的 WallTime 间隔超过 40S,也就是说这 40S 时间里,主线程确实一直 Block 在当前场景!
在消息调度时序图上进一步对比分析,发现两次 ANRCase,主线程当前正在执行消息的 Cpu Time 时长却发生了变化,即从 100ms 增加 450ms 。那么这个数据是否置信吗?
结合这两次 ANR,分别分析一下 ANR Trace 主线程 utm+stm 的耗时(见上图 2 次 Trace 堆栈):
发生第一次 ANR 时线程状态及 utm,stm 耗时:
 state=S schedstat=( 2442286229 338070603 5221 ) utm=187 stm=57 core=5 HZ=100发生第二次 ANR 时线程状态及 utm,stm 耗时:
| state=S schedstat=( 2796231342 442294098 6270 ) utm=202 stm=77 core=5 HZ=100用第二次发生 ANR 时的 utm+stm 减去第一次 ANR 时的 utm+stm,即 202+77-(187+57)=35ms 。这个值对应的是 cpu 时间片,utm,stm 单位换算成时间单位为 1 比 10ms,即 35*10=350ms 。这个值恰好等于 Raset 监控工具统计到的两次 Cputime 差值:450ms-100ms=350ms 。
说明在此期间消息队列增加了多个消息,因为每次增加一个消息,主线程都会从 epollwait 场景唤醒,然后回到 java 环境对消息队列进行遍历,判断是否有异步消息,如果没有找到,则再次进入 epollwait 状态,如此反复,从而导致了上述现象!
问题初定位:通过上面的层层分析,我们知道了是 barrier 同步机制出现了问题,导致消息调度发生异常,即:在 barrier 消息没有被移除之前,主线程只能处理 asyncronous 属性的消息,这类消息通常是用来刷新的 vsync 消息,以及响应用户交互的 input 消息,但是正常的业务消息及其他系统消息则无法正常调度,如 Serivce,Receiver 具体超时行为的消息,因此导致了 ANR 。


推荐阅读