今日头条 ANR 优化实践系列 - 监控工具与分析思路

前言：

在前文，咱们对ANR 设计原理及影响因素进行了介绍，并对影响 ANR 的不一样场景进行归类。可是依靠现有的系统日志，不足以完成复杂场景的问题归因，并且有些信息从应用侧没法获取，这就致使不少线上问题更加棘手。所以咱们在应用侧探索了新的监控能力，以弥补信息获取不足的短板。同时对平常分析过程当中用到日志信息和分析思路进行总结，以帮忙你们更好的掌握分析技巧，下面咱们就来看看相关实现。

Raster 监控工具

俗话说：“工欲善其事，必先利其器”，平常分析 ANR 问题也是如此，一个好的监控工具不只能够帮助咱们在解决常规问题时达到锦上添花的效果，在面对线上复杂隐蔽的问题时，也能为咱们打开视野，提供更多线索和思路。

工具介绍：

该工具主要是在主线程消息调度过程进行监控，并按照必定策略聚合，以保证监控工具自己对应用性能和内存抖动影响降至最低。同时对应用四大组件消息执行过程进行监控，便于对这类消息的调度及耗时状况进行跟踪和记录。另外对当前正在调度的消息及消息队列中待调度消息进行统计，从而在发生问题时，能够回放主线程的总体调度状况。此外，咱们将系统服务的 CheckTime 机制迁移到应用侧，应用为线程 CheckTime 机制，以便于系统信息不足时，从线程调度及时性推测过去一段时间系统负载和调度状况。

所以该工具用一句话来归纳就是：由点到面，回放过去，如今和未来。

因其实现原理和消息聚合后的效果，直观展现主线程调度过程长短不一的耗时片断，犹如一道道光栅，故将该工具命名为 Raster[ˈræstər]。

监控工具由来

举个例子：

例以下图，是线下遇到的 ANR 问题，从手机端获取的 Trace 日志，能够看到从主线程堆栈上基本得不到太多有效信息。 继续从 Trace 中分析其它信息，包含了各个进程的虚拟机和线程状态信息，以及 ANR 以前或以后一段时间，CPU 使用率比较高的进程乃至系统负载(CPU，IO)的相关信息等等，以下图： 可是从这些信息中，相信不少同窗都很难再进一步分析，由于这些信息只是列举了当前各个进程或线程的状态，并无很好的监控和记录影响这些指标的过程。而现实中这类场景的问题，天天都在线上大量发生。那么针对这种状况该如何更好的解决呢？下面就来介绍一下咱们是如何应对的。

消息调度监控

在Android 系统的 ANR 设计原理及影响因素一文中，咱们讲到，ANR 问题不少场景都是历史消息耗时较长并不断累加后致使的，可是在 ANR 发生时咱们并不知道以前都调度了哪些消息，若是能够监控每次消息调度的耗时并记录，当发生 ANR 时，获取这些记录信息，并能计算出当前正在执行消息的耗时，是否是就能够清晰的知道 ANR 发生前主线程都发生了什么？按照这个思路，整理出以下示意图： 可是经过上面示意图并结合实际业务场景，咱们发现，对于大多数业务消息，单次耗时都不多，若是每一个消息都单独记录，要想跟踪记录 ANR 前 10S 甚至更长时间范围内的全部消息，可能须要成千上万条记录，这个显然是不合理的，并且这么多的消息也不方便咱们后续查看。

消息聚合分类

联想到实际业务场景不少状况都是耗时较少的消息，而在排查这类问题过程耗时较少的消息基本是能够直接忽略的，所以咱们是否是能够对这类消息按照必定条件进行聚合，将一段时间之内的消息进行累加计算，若是累计耗时超过咱们规定的阈值，那么就将这些消息的数量和累计耗时合并成一条记录，如 16 个消息累计耗时恰好超过 300ms，则生成一条记录。以此类推存储 100 条的话，就能监控到 ANR 发生前 30S 主线程的调度历史了(实际多是大于 15S，至于为什么是这个范围，咱们会在后面说明)，如此一来就能够较好的解决大量记录和频繁更新带来的内存抖动问题。

根据上面的思路，咱们对消息监控及记录又进一步的进行聚合优化和关键消息过滤。总结来看，分为如下几种类型：

多消息聚合：

该场景主要用于主线程连续调度多个消息，而且每一个消息耗时都不多的状况下，将这些消息耗时累加，直到这些消息累计耗时超过设置的阈值，则汇总并生成一条记录，并在这条记录中标明本次聚合总共调度了多少个消息。按照消息聚合的思路，发生问题时主线程消息调度示意图以下： Count 表示本条记录包含了多少个消息；Wall 表示本轮消息执行的累计耗时

消息聚合拆分：

针对上面多消息聚合策略，会存在一些特殊状况，例如在将多个消息进行累计统计过程当中，若是前 N 次消息调度结束后，累计耗时都没有超过阈值，可是调度完下一个消息以后，发现累计耗时超过阈值，而且还明显超出，如设置阈值是 300ms，可是前 N 个消息累计 200ms，加上本次消息累计耗时达到了 900ms，那么这种状况，咱们明显知道是最后一次消息耗时严重，所以须要将本次消息单独记录，并标记其耗时和相关信息，同时将以前 N 次消息调度耗时和消息数聚合在一块儿并单独记录，这种场景至关于一次生成 2 条记录。

为了考虑监控工具对性能的影响，咱们只在每轮统计须要保存时，更新线程 cpu 执行时间，若是发生消息聚合拆分的场景，会默认前一条记录的 cpu 时间为-1，由于本条记录并非咱们重点关注的，因此会把本轮统计的 cpu 时间所有归到后一条消息。

在一些极端场景下，如本轮监控第一个消息执行耗时为 1ms，可是加上本次消息耗时，累计超过 600ms，所以两次消息累计耗时远大于设定的阈值 300ms，那么就须要对本次耗时严重的消息单独记录，而前面那个 1ms 的消息也须要被单独进行记录。相似情形如此反复，就会出现上面说的保存 100 条记录，总体监控可回溯的时长区间存在波动的状况。该场景的示意图以下： Count 表示本条记录包含了多少个消息；Wall 表示本轮消息执行的累计耗时

关键消息聚合：

除了上面单次耗时严重的消息须要拆分并单独记录以外，还有一类消息也须要咱们单独标记，以达到更好的识别，那就是可能会引发 ANR 的应用组件，如 Activity，Service，Receiver，Provider 等等，为了监控这几种组件的执行过程，咱们须要对 ActivityThread.H 的消息调度进行监控，当发现上面这些组件有关的消息在执行时，无论其耗时多少，都对其进行单独记录，并将以前监控的一个或多个消息也保存为一条记录。该场景的示意图以下： Count 表示本条记录包含了多少个消息；Wall 表示本轮消息执行的累计耗时

IDLE 场景聚合：

熟悉消息队列的同窗都知道，主线程是基于消息队列的方式进行调度，在每次消息调度完成以后都会从消息队列读取下一个待调度的消息，若是消息队列没有消息，或者下一个消息没有到设定的调度时间，而且也没有 IDLE 消息等待调度，那么主线程将会进入 IDLE 状态，以下示意图： 正是由于上面的调度逻辑，使得主线程在消息调度过程当中会屡次进入 IDLE 状态，而这个过程也涉及到线程上下文切换(如：Java 环境切换到 Native 环境)，会去检测是否有挂起请求，因此对调用频繁的接口来讲，会在 ANR 发生时被命中，理论上调用越频繁的接口被命中的几率越大，以下图堆栈： 可是上面这种场景的 IDLE 停留时长可长可短，若是按照彻底上面那几类消息聚合策略，多个消息连续聚合的话，可能会把这类场景也给聚合进来，必定程度形成干扰，这显然不是咱们想要的，为此须要进一步优化，在每次消息调度结束后，获取当前时间，在下次消息调度开始前，再次获取当前时间，并统计距离上次消息调度结束的间隔时长，若是间隔较长，那么也须要单独记录，若是间隔时间较短，咱们认为能够忽略，并将其合并到以前统计的消息一块儿跟踪，到这里就完成了各种场景的监控和归类。该场景的示意图以下： Count 表示本条记录包含了多少个消息；Wall 表示本轮消息执行的累计耗时

耗时消息堆栈采样：

在上面重点讲述了主线程消息调度过程的监控和聚合策略，便于发生 ANR，在线下进行回放。可是那些耗时较长的消息，仅仅知道其耗时和消息 tag 是远远不够的，由于每一个消息内部的业务逻辑对于咱们来讲都是黑盒，各个接口耗时也存在不少不肯定性，如锁等待、Binder 通讯、IO 等系统调用。

所以须要知道这些耗时消息内部接口的耗时状况，咱们选取了 2 种方案进行对比：

第一种方案：是对每一个函数进行插桩，在进入和退出过程统计其耗时，并进行聚合和汇总。该方案的优势是能够精确的知道每一个函数的真实耗时，缺点是很影响包体积和性能，并且不利于其余产品高效复用。

第二种方案，在每一个消息开始执行时，触发子线程的超时监控，若是在超时以后本次消息还没执行结束，则抓取主线程堆栈，并继续对该消息设置下一次超时监控，直到该消息执行结束并取消本轮监控。若是在触发超时以前已经执行完毕，则取消本次监控并在下次消息开始执行时，再次设置超时监控，可是由于大部分消息耗时都不多，若是每次都频繁设置和取消，将会带来性能影响，所以咱们对此进行优化，采用系统 ANR 超时监控相同的时间对齐方案，具体来讲就是：

以消息开始时间加上超时时长为目标超时时间，每次超时时间到了以后，检查当前时间是否大于或等于目标时间，若是知足，则说明目标时间没有更新，也就是说本次消息没结束，则抓取堆栈。若是每次超时以后，检查当前时间小于目标时间，则说明上次消息执行结束，新的消息开始执行并更新了目标超时时间，这时异步监控需对齐目标超时，再次设置超时监控，如此往复。

根据上面的思路，整理流程图以下： 须要注意的是，消息采样堆栈的超时时长不可设置过短，不然频繁抓取堆栈对主线程性能影响较大，同时也不能设置太长，不然会由于采样太低致使数据置信度下降。具体时长根据每一个产品复杂度灵活调整便可。

监控正在调度消息及耗时：

除了监控 ANR 发生以前主线程历史消息调度及耗时以外，也须要知道 ANR 发生时正在调度的消息及其耗时，以便于在看到 ANR 的 Trace 堆栈时，能够清晰的知道当前 Trace 逻辑到底执行了多长时间，帮忙咱们排除干扰，快速定位。借助这个监控能够很好的回答你们，ANR 发生时当前 Trace 堆栈是否耗时以及耗时多久的问题，避免陷入“Trace 堆栈”误区。

获取 Pending 消息：

同时除了监控主线程历史消息调度及耗时以外，也须要在 ANR 发生时，获取消息队列中待调度的消息，为咱们分析问题时提供更多线索，如：

• 消息队列中待调度消息是否被 Block 以及被 Block 时长，根据 Block 时长能够推测主线程的繁忙程度；
• 能够观察消息队列中是否存在发生 ANR 的应用组件消息，如 Service 消息，以及其在待调度消息队列中的位置和 Block 时长；
• 能够观察消息队列中都有哪些消息，这些消息是否有必定规律，如大量重复消息，若是有大量重复消息，则说明颇有可能与该消息相关的业务逻辑发生异常，频繁和主线程交互(后面的案例分析中咱们也会有介绍)。

以前咱们讲到，对于一次消息调度，它的耗时能够从两个维度进行统计，即 Wall Duration 和 Cpu Duration，经过这两个维度的统计，能够帮助咱们更好的推测一次严重耗时，是执行大量业务逻辑仍是处于等待或被抢占的状况，若是是后者，那么能够看到这类消息的 Wall Duration 和 Cpu Duration 比例会比较大，固然如何更好更全面的区分一次消息耗时是等待较多仍是线程调度被抢占，咱们将会在后面结合其余参考信息进行介绍。

完整示意图

在这里咱们再把 Cpu Duration 耗时也给统计以后，那么整个有关主线程完整的消息调度监控功能就基本完成了。示意图以下： 经过这个消息调度监控工具，咱们就能够很清晰的看到发生 ANR 时，主线程历史消息调度状况。当前正在调度消息耗时，以及消息队列待调度消息及相关信息。并且利用这个监控工具，一眼便知 ANR 发生时主线程 Trace 实际耗时状况，所以很好解决了部分同窗对当前堆栈是否耗时以及耗时多久的疑问。

从上面介绍能够看出，为了重点标记单次耗时消息和关键消息，咱们使用了多种聚合策略，所以监控过程记录的信息可能会表明不一样类型的消息，为了便于区分，咱们在可视化展现时加上 Type 标识，便于区别。

应用示例：

例以下图，从 Trace 日志能够看到，ANR 发生时主线程被 Block 在 Binder 通讯过程，可能不少同窗第一反应是 WMS 服务没有及时响应 Binder 请求致使的问题 可是再结合下面的消息调度监控来核实一下，咱们发现当前调度的消息 Wall duration 只有 44ms，而在该消息以前有两次历史消息耗时比较严重，分别为 2166ms，3277ms，也就是说本次 Binder 调用耗时并不严重，真正的问题是前面 2 次消息耗时较长，影响了后续消息调度，只有同时解决这 2 个消息耗时严重问题，该 ANR 问题才可能解决。 若是没有消息调度监控工具，上去就盲目的分析当前逻辑调用的 IPC 问题，可能就犯了方向性的错误，掉入“Trace 堆栈”陷阱中。

接下来再来看一个发生在线上的另一个实例，从下图能够看到主线程正在调度的消息耗时超过 1S，可是在此以前的另外一个历史消息耗时长达 9828ms。继续观察下图消息队列待调度的消息状态(灰色示意)，能够看到第一个待调度的消息被 Block 了 14S 之久。由此咱们能够知道 ANR 消息以前的这个历史消息，才是致使 ANR 的罪魁祸首，固然这个正在执行的消息也须要优化一下性能，由于咱们在前面说过：“发生 ANR 时，没有一个消息是无辜的”。 正是由于有了上面这些监控能力，让咱们在平常面对 Trace 日志中的业务逻辑是否耗时以及耗时多久的困惑，瞬间就会变得清晰起来。

Checktime

Checktime 背景介绍：

Checktime 是 Android 系统针对一些系统服务(AMS，InputService 等)中高频访问的接口，执行时间的监控，当这类接口真实耗时超过预期值将会给出提示信息，此类设计为了在真实环境监测进程被调度和响应能力的一种结果反馈。

具体实现是，在每一个函数执行前和执行后分析获取当前系统时间，并计算差值，若是该接口耗时超过其设定的阈值，则会触发"slow operation"的信息提醒，部分代码实现以下： Checktime 逻辑很简单，用当前系统时间减去对比时间，若是超过 50ms，则给出 Waring 日志提示。 咱们在分析线下问题，或者在系统层面分析这类问题时，常常会在 logcat 中看到这类消息，可是对于线上的三方应用来讲，由于权限问题没法获取系统日志，只能本身实现了。

线程 Checktime：

了解完系统 Checktime 设计思路及实现以后，咱们就能够在应用层实现相似的功能了，经过借助其它子线程的周期检测机制，在每次调度前获取当前系统时间，而后减去咱们设置延迟的时间，便可获得本次线程调度前的真实间隔时间，如设置线程每隔 300ms 调度一次，结果发现实际响应时间间隔有时会超过 300ms，若是误差越大，则说明线程没有被及时调度，进一步反映系统响应能力变差。

经过这样的方式，即便在线上环境获取不到系统日志，也能够从侧面反映不一样时段系统负载对线程调度影响，以下图示意，当连续发生屡次严重 Delay 时，说明线程调度受到了影响。

小结：

经过上述监控能力，咱们能够清晰的知道 ANR 发生时主线程历史消息调度以及耗时严重消息的采样堆栈，同时能够知道正在执行消息的耗时，以及消息队列待中调度消息的状态。同时经过线程 CheckTime 机制从侧面反映线程调度响应能力，由此完成了应用侧监控信息从点到面的覆盖。可是在面对 ANR 问题时，只有这个监控，是远远不够的，须要结合其余信息总体分析，以应对更为复杂的系统环境。下面就结合监控工具来介绍一下 ANR 问题的分析思路。

ANR 分析思路：

在介绍分析思路以前，咱们先来讲一下分析这类问题须要用到哪些日志，固然在不一样的环境下，获取信息能力会有很大差异，如线下环境和线上环境，应用侧和系统角度都有差别。这里咱们会将咱们平常排查问题经常使用的信息都介绍一下，便于你们更好的理解，主要包括如下几种：

• Trace 日志
• AnrInfo
• Kernel 日志
• Logcat 日志
• Meminfo 日志
• Raster 监控工具

对于应用侧来讲，在线上环境可能只能拿到当前进程内部的线程堆栈(取决于实现原理，参见：Android 系统的 ANR 设计原理及影响因素)以及 ANR Info 信息。

在系统侧，几乎能获取到上面的全部信息，对于这类问题获取的信息越多，分析定位成功率就越大，例如能够利用完整的 Trace 日志，分析跨进程 Block 或死锁问题，系统内存或 IO 紧张程度等等，甚至能够知道硬件状态，如低电状态，硬件频率(CPU，IO，GPU)等等。

关键信息解读：

在这里咱们把上面列举的日志进行提取并解读，以便于你们在平常开发和面对线上问题，根据当前获取的信息进行参考。

Trace 信息

在前文Android 系统的 ANR 设计原理及影响因素中，咱们讲到了在发生 ANR 以后，系统会 Dump 当前进程以及关键进程的线程堆栈，状态(红框所示关键信息，稍后详细说明)，示例以下： 上面的日志包含不少信息，这里将经常使用的关键信息进行说明，以下：

• 线程堆栈：

  • 这个比较好理解，也就是发生 ANR 时，线程正在执行的逻辑，可是不少场景下，获取的堆栈耗时并不长，缘由详见Android 系统的 ANR 设计原理及影响因素。

• 线程状态：

  • 见上图“state=xxx”，表示当前线程工做状态，Running 表示当前线程正在被 CPU 调度，Runnable 表示线程已经 Ready 等待 CPU 调度，如上图 SignalCatcher 线程状态。Native 态则表示线程由 Java 环境进入到 Native 环境，可能在执行 Native 逻辑，也多是进入等待状态。Waiting 表示处于空闲等待状态。除此以外还有 Sleep，Blocked 状态等等。

• 线程耗时：

见上图“utmXXX，stmXXX”，表示该线程从建立到如今，被 CPU 调度的真实运行时长，不包括线程等待或者 Sleep 耗时，其中线程 CPU 耗时又能够进一步分为用户空间耗时(utm)和系统空间耗时(stm)，这里的单位是 jiffies，当 HZ=100 时，1utm 等于 10ms。

• utm： Java 层和 Native 层非 Kernel 层系统调用的逻辑，执行时间都会被统计为用户空间耗时。

• stm： 即系统空间耗时，通常调用 Kernel 层 API 过程当中会进行空间切换，由用户空间切换到 Kernel 空间，在 Kernel 层执行的逻辑耗时会被统计为 stm，如文件操做，open,write,read 等等。

• core：最后执行这个线程的 cpu 核的序号。

• 线程优先级：

  • nice： 该值越低，表明当前线程优先级越高，理论上享受的 CPU 调度能力也越强。对于应用进程(线程)来讲，nice 范围基本在 100~139。随着应用所在先后台不一样场景，系统会对进程优先级进行调整，厂商可能也会开启 cpu quota 等功能去限制调度能力。

• 调度态：

  • schedstat： 参见“schedstat=( 1813617862 14167238 546 )”，分别表示线程 CPU 执行时长(单位 ns)，等待时长，Switch 次数。

AnrInfo 信息

除了 Trace 以外，系统会在发生 ANR 时获取一些系统状态，如 ANR 问题发生以前和以后的系统负载以及 Top 进程和关键进程 CPU 使用率。这些信息若是在本地环境能够从 Logcat 日志中拿到，也能够在应用侧经过系统提供的 API 获取(参见：Android 系统的 ANR 设计原理及影响因素)，Anr Info 节选部分信息以下： 对于上图信息，主要对如下几部分关键信息进行介绍：

• ANR 类型(longMsg)：

  • 表示当前是哪一种类型的消息或应用组件致使的 ANR，如 Input，Receiver，Service 等等。

• 系统负载(Load)：

表示不一样时间段的系统总体负载，如："Load：45.53 / 27.94 / 19.57"，分布表明 ANR 发生前 1 分钟，前 5 分钟，前 15 分钟各个时间段系统 CPU 负载，具体数值表明单位时间等待系统调度的任务数(能够理解为线程)。若是这个数值太高，则表示当前系统中面临 CPU 或 IO 竞争，此时，普通进程或线程调度将会受到影响。若是手机处于温度太高或低电等场景，系统会进行限频，甚至限核，此时系统调度能力也会受到影响。

此外，能够将这些时间段的负载和应用进程启动时长进行关联。若是进程刚启动 1 分钟，可是从 Load 数据看到前 5 分钟，甚至前 15 分钟系统负载已经很高，那很大程度说明本次 ANR 在很大程度会受到系统环境影响。

• 进程 CPU 使用率：

如上图，表示当前 ANR 问题发生以前(CPU usage from XXX to XXX ago)或发生以后(CPU usage from XXX to XXX later)一段时间内，都有哪些进程占用 CPU 较高，并列出这些进程的 user，kernel 的 CPU 占比。固然不少场景会出现 system_server 进程 CPU 占比较高的现象，针对这个进程须要视状况而定，至于 system_server 进程 CPU 占比为什么广泛较高，参见：Android 系统的 ANR 设计原理及影响因素。 minor 表示次要页错误，文件或其它内存被加载到内存后，可是没有被映射到当前进程，经过内核访问时，会触发一次 Page Fault。若是访问的内容尚未加载到内存，那么会触发 major，因此对比能够看到，major 的系统开销会比 minor 大不少。

• 关键进程：

  • kswapd： 是 linux 中用于页面回收的内核线程，主要用来维护可用内存与文件缓存的平衡，以追求性能最大化，当该线程 CPU 占用太高，说明系统可用内存紧张，或者内存碎片化严重，须要进行 file cache 回写或者内存交换(交换到磁盘)，线程 CPU 太高则系统总体性能将会明显降低，进而影响全部应用调度。

  • mmcqd： 内核线程，主要做用是把上层的 IO 请求进行统一管理和转发到 Driver 层，当该线程 CPU 占用太高，说明系统存在大量文件读写，固然若是内存紧张也会触发文件回写和内存交换到磁盘，因此 kswapd 和 mmcqd 常常是同步出现的。

• 系统 CPU 分布：

以下图，反映一段时间内，系统总体 CPU 使用率，以及 user，kernel，iowait 方向的 CPU 占比，若是发生大量文件读写或内存紧张的场景，则 iowait 占比较高，这个时候则要进一步观察上述进程的 kernel 空间 CPU 使用状况，并经过进程 CPU 使用，再进一步对比各个线程的 CPU 使用，找出占比最大的一个或一类线程。

Logcat 日志：

在 log 日志中，咱们除了能够观察业务信息以外，还有一些关键字也能够帮咱们去推测当前系统性能是否遇到问题，以下图， “Slow operation”，“Slow delivery” 等等。

Slow operation

Android 系统在一些频繁调用的接口中，分别在方法先后利用 checktime 检测，以判断本次函数执行耗时是否超过设定阈值，一般这些值都会设置的较为宽松，若是实际耗时超过设置阈值，则会给出“Slow XXX”提示，表示系统进程调度受到了影响，通常来讲系统进程优先级比较高，若是系统进程调度都受到了影响，那么则反映了这段时间内系统性能颇有可能发生了问题。

Kernel 日志：

对于应用侧来讲，这类日志基本是拿不到的，可是以下是在线下测试或者从事系统开发的同窗，能够经过 dmesg 命令进行查看。对于 kernel 日志，咱们主要分析的是 lowmemkiller 相关信息，以下图：

Lowmemkiller：

从事性能(内存)优化的同窗对该模块都比较熟悉，主要是用来监控和管理系统可用内存，当可用内存紧张时，从 kernel 层强制 Kill 一些低优先级的应用，以达到调节系统内存的目的。而选择哪些应用，则主要参考进程优先级(oom_score_adj)，这个优先级是 AMS 服务根据应用当前的状态，如前台仍是后台，以及进程存活的应用组件类型而计算出来的，例如：对于用户感知比较明显的前台应用，优先级确定是最高的，此外还有一些系统服务，和后台服务(播放器场景)优先级也会比较高。固然厂商也对此进行了大量的定制(优化)，以防止三方应用利用系统设计漏洞，将自身进程设置过高优先级进而达到保活目的。

消息调度时序图：

如上图，在咱们分析完系统日志以后，会进一步的锁定或缩小范围，可是最终咱们仍是要回归到主线程进一步的分析 Trace 堆栈的业务逻辑以及耗时状况，以便于咱们更加清晰的知道正在调度的消息持续了多长时间，可是不少状况当前 Trace 堆栈并非咱们期待的答案，所以须要进一步的确认 ANR 以前主线程的调度信息，评估历史消息对后续消息调度的影响，便于咱们寻找“真凶”。

固然，有时也须要进一步的参考消息队列中待调度消息，在这些消息里面，除了能够看到 ANR 时对应的应用组件被 Block 的时长以外，还能够了解一下都有哪些消息，这些消息的特征有时对于咱们分析问题也会提供有力的证据和方向。

分析思路

在上面咱们对各种日志的关键信息进行了基本释义，下面就来介绍一下，当咱们平常遇到 ANR 问题时，是如何分析的，总结思路以下：

• 分析堆栈，看看是否存在明显业务问题(如死锁，业务严重耗时等等)，若是无上述明显问题，则进一步经过 ANR Info 观察系统负载是否太高，进而致使总体性能较差，如 CPU，Mem，IO。而后再进一步分析是本进程仍是其它进程致使，最后再分析进程内部分析对比各个线程 CPU 占比，找出可疑线程。

• 综合上述信息，利用监控工具收集的信息，观察和找出 ANR 发生前一段时间内，主线程耗时较长的消息都有哪些，并查看这些耗时较长的消息执行过程当中采样堆栈，根据堆栈聚合展现，进一步的对比当前耗时严重的接口或业务逻辑。

以上分析思路，进一步细分的话，能够分为如下几个步骤：

• 一看 Trace：

  • 死锁堆栈： 观察 Trace 堆栈，确认是否有明显问题，如主线程是否与其余线程发生死锁，若是是进程内部发生了死锁，那么恭喜，这类问题就清晰多了，只需找到与当前线程死锁的线程，问题便可解决。

  • 业务堆栈： 观察经过 Trace 堆栈，发现当前主线程堆栈正在执行业务逻辑，你找到对应的业务同窗，他认可该业务逻辑确实存在性能问题，那么恭喜，你颇有可能解决了该问题，为何只是有可能解决该问题呢？由于有些问题取决于技术栈或框架设计，没法在短期内解决。若是业务同窗反馈当前业务很简单，基本不怎么耗时，而这种场景也是平常常常遇到的一类问题，那么就可能须要借助咱们的监控工具，追溯历史消息耗时状况了。

  • IPC Block 堆栈： 观察经过 Trace 堆栈，发现主线程堆栈是在跨进程(Binder)通讯，那么这个状况并不能立即下定论就是 IPC block 致使，实际状况也有多是刚发送 Binder 请求不久，以及想要进一步的分析定位，这时也须要借助咱们的自研监控工具了。

  • 系统堆栈： 经过观察 Trace，发现当前堆栈只是简单的系统堆栈，想要搞清楚是否发生严重耗时，以及进一步的分析定位，如咱们常见的 NativePollOnce 场景，那么也须要借助咱们的自研监控工具进一步确认了。

• 二看关键字：Load，CPU，Slow Operation，Kswapd，Mmcqd，Kwork，Lowmemkiller 等等

刚才咱们介绍到，上面这些关键字是反应系统 CPU，Mem，IO 负载的关键信息，在分析完主线程堆栈信息以后，还须要进一步在 ANRInfo，logcat 或 Kernel 日志中搜索这些关键字，并根据这些关键字当前数值，判断当前系统是否存在资源(CPU，Mem，IO)紧张的状况。

• 三看系统负载分布：观察系统总体负载：User,Sys,IOWait

经过观察系统负载，则能够进一步明确是 CPU 资源紧张，仍是 IO 资源紧张。若是系统负载太高，必定是有某个进程或多个进程引发的反之。系统负载太高又会影响到全部进程调度性能。经过观察 User，Sys 的 CPU 占比，能够进一步发分析当前负载太高是发生在应用空间，仍是系统空间，如大量调用逻辑(如文件读写，内存紧张致使系统不断回收内存等等)，知道这些以后，排查方向又会进一步缩小范围。

• 四看进程 CPU：观察 Top 进程的 CPU 占比

从上面分析，在咱们知道当前系统负载太高，是发生在用户空间仍是内核空间以后，那么咱们就要经过 Anrinfo 的提供的进程 CPU 列表，进一步锁定是哪一个(些)进程致使的，这时则要进一步的观察每一个进程的 CPU 占比，以及进程内部 user，sys 占比。

• 在分析进程 CPU 占比过程，有一个关键的信息，要看统计这些进程 CPU 太高的场景是发生在 ANR 以前的一段时间仍是以后一段时间，以下图表示 ANR 以前 4339ms 到 22895ms 时间内进程的 CPU 使用率。

• 五看 CPU 占比定线程 ：对比各线程 CPU 占比，以及线程内部 user 和 kernel 占比

在经过系统负载(user,sys,iowait)锁定方向以后，又经过进程列表锁定目标进程，那么接下来咱们就能够从目标进程内部分析各个线程的(utm,stm)，进一步分析是哪一个线程有问题了。

在 Trace 日志的线程信息里能够清晰的看到每一个线程的 utm，stm 耗时。至此咱们就完成了从系统到进程，再到进程内部线程方向的负载分析和排查。固然，有时候可能致使系统高负载的不是当前进程，而是其余进程致使，这时一样会影响其余进程，进而致使 ANR。

• 六看消息调度锁定细节 ：

  • 在分析和明确系统负载是否正常，以及负载太高是哪一个进程引发的结论以后，接下来便要经过咱们的监控工具，进一步排查是当前消息调度耗时致使，历史消息调度耗时致使，仍是消息过于频繁致使，同时经过咱们的线程 CheckTime 调度状况分析当前进程的 CPU 调度是否及时以及影响程度，在锁定上述场景以后，再进一步分析耗时消息的采样堆栈，才算找到解决问题的终极之钥，固然耗时消息内部可能存在一个或多个耗时较长的函数接口，或者会有多个消息存在耗时较长的函数接口，这就是咱们前文中提到：“发生 ANR 时，没有一个消息是无辜的。”

更多信息：

除了上面的一些信息，咱们还能够结合 logcat 日志分析 ANR 以前的一些信息，查看是否存在业务侧或系统侧的异常输出，如搜索“Slow operation”，"Slow delivery"等关键字。也能够观察当前进程和系统进程是否存在频繁 GC 等等，以帮忙咱们更全面的分析系统状态。

总结：

上面咱们重点介绍了基于主线程消息调度的监控工具，实现了"由点到面"的监控能力，以便于发生 ANR 问题时，能够更加清晰直观的总体评估主线程的“过去，如今和未来”。同时结合平常实践，介绍了在应用侧分析 ANR 问题常常用到的日志信息和分析思路。

目前，Raster 监控工具由于其很好的提高了问题定位效率和成功率，成为 ANR 问题分析利器，并融合到公司性能稳定性监控平台，为公司众多产品普遍使用。接下来咱们将利用该工具并结合上面的分析思路，讲一讲实际工做中遇到不一样类型的 ANR 问题时，是如何快速分析和定位问题的。

Android 平台架构团队

咱们是字节跳动 Android 平台架构团队，以服务今日头条为主，面向 GIP，同时服务公司其余产品，在产品性能稳定性等用户体验，研发流程，架构方向上持续优化和探索，知足产品快速迭代的同时，保持较高的用户体验。 若是你对技术充满热情，想要迎接更大的挑战和舞台，欢迎加入咱们，北京，深圳均有岗位，感兴趣发送邮箱：tech@bytedance.com ，邮件标题：姓名 - GIP - Android 平台架构。