barrier repair barrier

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

barrier repair barrier

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

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

文章插图
进一步分析系统负载,发现整体 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 监控工具的调度时序图上面 。
barrier repair barrier

文章插图
通过该时序图,观察以下三类信息特征: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 时长很短 。如下图:
barrier repair barrier