今日头条 ANR 优化实践系列分享 - 实例剖析集锦

简述：

在前文，我们用了较多的篇幅介绍了ANR 设计原理及影响因素，并根据不同场景进行了分类，如：当前消息严重耗时，历史消息耗时严重，业务异常密集执行，进程内资源抢占，进程间资源抢占等场景。为了应对系统监控能力不足以及应用侧获取信息受限的情况，我们在应用侧实现了一套消息调度监控工具，重点监控主线程的“过去，现在和将来”，同时结合相关日志对 ANR 问题的分析思路进行了总结。

为了便于大家更好的理解上述知识，接下来我们将结合工作中遇到的一些比较有代表性的问题，并按照前文归因分类，由浅入深进行实例解剖，下面就来看看这几类问题，我们是如何借助系统日志和监控工具进行分析及定位的。

案例一：当前业务耗时严重

主线程 Trace 堆栈：

分析过程：

分析堆栈：

根据前文讲到的问题分析思路，首先观察 Trace 主线程堆栈，从上面堆栈，可以看到正在业务逻辑，但是当前这个业务逻辑是否耗时呢？如果耗时较长，是不是受到系统调度影响呢？带着这些疑问，我们来看一下系统侧的表现。

分析系统&进程负载：

观察不同时段系统负载： 在 ANR Info 中我们搜索 Load 关键字，发现 ANR 前 1，前 5，前 15 分钟(Load:7.45 / 6.92 / 6.84)，系统 CPU 整体负载并不高。

观察进程 CPU 使用率： 进一步观察 CPU usage from 0 ms to 8745ms later，看到 ANR 之后 (later：表示发生 ANR 后一段时间各进程 CPU 占比，ago 表示：ANR 之后一段时间，各进程 CPU 占比)的这段时间，应用主进程 CPU 占比达到 161%，而且在 user，kernel 占比分布上，kernel 比例高达 103%！ 通过前文的介绍，我们知道对应用来说 kernel 空间 CPU 占比较高，说明应用侧应该发生了大量的系统调用，对普通应用来说，发生系统调用的多数场景都是文件 IO 操作。

观察线程： 继续观察上图，可以看到应用进程内部的线程 CPU 占用，可以看到主线程的 CPU 占比 93%，其中 kernel 占用 69%，明显高于用户空间 23%，说明 ANR 之后的这 8S 多，主线程依然在进行大量系统调用。

系统侧结论： 通过观察系统负载和各个进程的 CPU 使用情况，我们发现系统整体负载比较正常，但是我们的主进程 CPU 占比明显偏高，并且集中在主线程。

业务耗时：

根据上面的分析，我们将思路再次回到主线程，进一步观察 Trace 堆栈，发现上面有一个明显的系统调用(read)，难道是本次系统调用导致的 kernel 占比较高吗？那么当前逻辑在 ANR 发生前已经持续了多久呢？分析到这里，如果没有进一步的监控，或者业务不认可当前业务逻辑耗时，那么事情到这里可能就要告一段落，或者需要在业务层添加监控埋点进行复现了，但是如果每次遇到这类问题都要添加埋点，那么将是一个非常糟糕的事情。

别忘了，在前面介绍 ANR 问题分析思路时，我们还有一个杀手锏(参见：监控工具 Raster)，通过这个监控工具可以看到很清晰的看到：历史消息耗时，当前消息持续时间以及消息队列未调度消息 Block 耗时。结合上面这个问题，我们看到了本次主线程消息调度情况，参见下图：

通过还原的时序图，可以清晰看到 ANR 之前，主线程消息调度及耗时基本正常，没有发现明显耗时严重的消息，但是观察正在调度的消息，其 Wall duration 超过 9000ms，并且 Cpu duration 长达 4800ms+，说明该消息耗时非常严重。而且上图灰色部分显示第一个消息，被 Block 了 9S 以上，因此可以进一步的说明该消息被 Block 的时长，基本都是当前正在执行的消息导致。

问题结论：

通过上面这些分析信息和实际数据，我们可以得出如下结论：发生 ANR 问题时，系统负载良好。发生问题前，应用主线程消息调度状态良好，但是当前正在调度的消息耗时严重，导致了后续消息未能及时响应，引起了 ANR。

带着这些结论，在和业务对接时便会清晰高效很多。这种场景，属于比较常规和常见的问题，也是大部分同学排查问题的分析思路，过程相对轻松。接下来，我们再看另一种场景的 ANR 问题。

案例二：历史消息耗时严重

下面分析的这个案例，是大家经常遇到的，也是引起很多人困惑的一种场景：发生 ANR 时，Trace 堆栈落在了 NativePollOnce。根据我们的理解，这个场景一般表示当前线程处于空闲或 JNI 执行完之后，进行上下文切换的过程，相关逻辑比较清晰。

可是日常遇到的问题，有很多 Case 都属于这类场景，如果仅仅依靠系统日志让我们很难进一步分析。下面就看看我们是如何应对这类问题的：

主线程 Trace