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

观察进程 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 时长很短。如下图：

为此我们第一反应是系统出问题了？但是进一步对比来看，该类现象只在某个版本之后明显增加，而之前的版本并没有这类现象，如果是厂商更新 rom 导致的问题，应该影响全版本，甚至会影响所有应用，但事实并非