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

简述：前文，我们通过线上案例对影响 ANR 问题的六大场景进行剖析，这几类场景基本覆盖了线上大部分问题，详见今日头条 ANR 优化实践系列分享 - 实例剖析集锦。同时我们选取了较多 NativePollOnce 场景的案例，便于大家更好理解，ANR 时看到的 NativePollOnce 场景的问题，并不是导致 ANR 的根本问题。
下面要介绍的这类问题，Trace 现场依然是 NativePollOnce 信息，但与前几类问题不同的是，这类问题真的发生在 NativePollOnce 场景，接下来就看看到底是什么原因导致的。
主线程 Trace 堆栈：

文章插图

分析思路：针对该类问题，当看到这个信息时，第一判断依然是主线程历史消息耗时严重，或者系统负载过重导致的问题，因为工作日常分析了太多这类场景的 ANR 问题，而且最后的结论也证明都与此场景无关。但分析这个问题时，进一步拆解大盘指标发现一段时间内 ANR 增加的量级，基本全部落在这个场景，这不太符合我们的预期。但是鉴于 Trace 信息有限，只好把目光转移到系统侧，看看是否有线索。
分析系统&进程负载：

文章插图

观察系统负载：在 ANR Info 中查看 Load 关键字，发现系统在前 1 分钟，前 5 分钟，前 15 分钟各个时段负载并不高。
观察进程 CPU 分布：进一步观察"CPU usage from 0 ms to 24301 later"，看到 ANR 之后这 24S 多的时间，应用主进程 CPU 占使用率只有 15%，但是 com.meizu.mstore 应用 CPU 使用率达到 92%，user 与 kenel 比例分别为 71%，20% 。与此同时 kswapd,mmc-cmdqd 等内核线程 CPU 使用率并不高，说明系统负载总体正常。如果根据我们前面案例分析得出的结论来看，这种场景难道是 com.meizu.mstore 进程严重抢占 CPU 导致的？带着这个疑惑，继续观察系统 CPU 分布。
观察系统 CPU 分布：

文章插图

进一步分析系统负载，发现整体 CPU 使用率稍微有些高。user 占比 37%，kernel 占比 24%，iowait 占比 6.9%，说明这段时间系统 IO 确实有些繁忙。
系统侧结论：通过观察系统负载和各个进程的 CPU 使用情况，发现系统环境比较正常，但是 com.meizu.mstore 进程 CPU 占比偏高，而且 kernel 层 cpu 使用率(20%)较高，与系统 iowait (6.9%)占用较高可能存在一定关联，那么 IO 负载较高对当前应用有多大影响呢？我们回到应用侧进一步分析。
应用侧分析：根据上面的分析，我们将方向再回到当前进程，通过对比各线程 cpu 耗时(utm+stm)，并没有看到某个线程存在明显异常。主线程 CPU 执行时长 utm:187，stm:57，基本正常。
在分析对比完线程 CPU 耗时之后，将目光再次聚焦到Raster 监控工具的调度时序图上面。

文章插图

通过该时序图，观察以下三类信息特征：ANR 前的历史消息，正在执行的消息，被 Block 的消息：
历史消息：主线程并不存在单次历史消息耗时严重的现象。
当正在执行的消息：正在执行的消息 Wall Duration 为 21744ms，CPU Duration 为 100ms 。也就是说大量的时间发生在等待的场景，结合该场景，如果期间是因为执行 Idle Task 导致的耗时严重或长时间 Wait，那么 ANR 抓取的堆栈应该有 IdleTask 相关信息才对，因此首先排除了是 Idle Task 耗时严重导致的问题。
被 Block 消息：从上图可以看到，第一个待调度的消息被 block 时长为 22343ms，其 block 时长基本等于当前正在执行消息的 Wall Duration 时长。也就说明了本场景大量消息 blcok 是受到了当前正在执行的消息影响。
分析到这里我们就有些困惑了，ANR 发生时当前正处于 NativePollOnce 场景，但是前面我们多次在案例分析中提到，进入 NativePollOnce 场景的条件是：消息队列没有立刻调度的消息时，会有条件的进入 wait 状态，等到超时或者新消息加入时会唤醒该线程并执行，但是从上图可以看到消息队列中存在大量待调度消息，而且很多消息都被 block 了 20 多 S，既然这么多消息可以被调度，那么系统为何还是一直在 NativePollOnce 环境中呢？难道真的是底层发生了问题，导致无法唤醒当前线程？
带着这个疑惑，我们陆续分析了同段时间内其他用户上报的问题，发现存在同样的现象：NativePollOnce 场景的 WallDuration 普遍较长，有的甚至超过了 100S，但是 Cpu 时长很短。如下图：