Android 卡顿与 ANR 的分析实践

本文首发于微信公众号“Shopee技术团队”

摘要

针对客户端开发的“终生之敌”——卡顿和 ANR 问题，本文将深入剖析系统消息队列机制和常见的卡顿与 ANR 成因，并介绍监控工具 LooperMonitor 如何借助多维分析平台 MDAP 的智能聚合和可视化看板，为业务方提供更精准、易用的分析能力。

这是 MDAP 系列的第三篇文章，前文回顾：

• 《MDAP：可观测性数据分析平台设计与实践》
• 《机器学习在基于 URL 的客户端监控分析中的优化和实践》

前言

卡顿和 ANR，这是一个所有客户端开发同学都十分关注的话题，也是一个无法绕过的话题。

卡顿的表现是 App 出现丢帧、滑动不流畅、用户的触摸事件响应慢；当发生非常严重的卡顿时，App 甚至可能会弹出 Application not responding 的弹窗，提示用户当前 App 无响应。

卡顿和 ANR 除了会影响用户的使用体验外，对于电商平台来说，在订单高峰期更是会直接影响成交量，导致实际的收入损失。可以说卡顿与 ANR 是客户端开发同学的终生之敌。

但是卡顿和 ANR 问题的分析与解决又具有一定的难度，尤其是 ANR。主要原因是 ANR 是主线程繁忙导致关键的系统消息不能及时执行而触发的，导致主线程繁忙的原因很多，同时系统对 ANR 的认定阈值又比较久，最低也是 5s 起步，在这段时间内，有可能出现了设备 CPU 资源紧张或主线程执行了一些耗时消息的场景，这些场景都有可能是“导致雪崩发生的那几片雪花”。

目前业内主流的监控 SDK，其基本思路都是监听 ANR 信号，并在 ANR 发生现场抓取线程堆栈和系统 ANR 日志，此时的堆栈抓取是一种事后策略，除了一些非常明显的比如线程死锁或者当前正好存在异常耗时的业务逻辑外，对更隐晦和复杂的原因就无能为力了，这种“事后策略”往往导致上报的 ANR 数据里充斥着大量的“无效堆栈”。比如经典的 MessageQueue.nativePollOnce：

大量堆栈都聚合到 MessageQueue.nativePollOnce 这里了，难道是因为主线程调用 nativePollOnce 在 jni 层一直阻塞没有被唤醒吗？如果只借助这么一份堆栈数据的话，我们无法找到分析思路，这些 ANR 问题是很难被解决的。

为了解决这些痛点，ShopeeFood 团队和 Shopee Engineering Infrastructure 团队通过深入研究系统消息队列机制和常见的卡顿与 ANR 成因，实现了一套新的监控工具 LooperMonitor，作为 APM-SDK 基础能力的一部分，与卡顿和 ANR 上报结合，借助多维分析平台 MDAP（Multi-dimension-analysis-platform）的智能聚合和可视化看板，旨在为业务方提供更精准和易用的分析能力。

1. 卡顿与 ANR 的产生原理

在正式介绍 LooperMonitor 方案之前，我们有必要搞清楚为什么传统方案抓取的 ANR 现场堆栈会不准？要解答这个问题，需要先弄清楚卡顿和 ANR 是如何产生的。

我们知道，Android 的应用层是基于 Looper+MessageQueue 的事件循环模型运作起来的。

Looper 是一个消息轮询器，它不停地在 MessageQueue 中取出消息并执行。

这里的消息，包括 UI 绘制消息、系统四大组件的调度消息、业务自己通过 Handler 构建的消息等。

里面负责 UI 绘制的是 doFrame 的消息。它是由 Choreographer 通过申请和监听硬件层的 vsync 垂直同步信号后，将 UI 绘制任务包装成一个 doFrame 的消息，在合适的帧绘制时间点将消息抛到主线程消息队列去执行的。

一个 doFrame 消息内部有五个 callback 队列，比较重要的是 input_queue、animation_queue 和 traversal_queue。它们分别处理触摸事件、动画事件、UI 绘制事件。

当一个 doFrame 消息被执行时，上述三个队列的事件会被执行，我们认为 App 响应了一次用户的触摸，同时 UI 更新了一帧，完成了一次交互。

当一个 doFrame 消息执行完成后，会通知 Choreographer 申请下一次的 vsync 信号。此时 UI 绘制任务便被串起来了，如下图：

如果在每一个 vsync 间隔都能执行完一个新的 doFrame 消息的话，此时设备是满帧运行的。

但是有种情况会导致下一个 doFrame 消息不能在一个 vsync 间隔内被执行，比如当前的 doFrame 消息正好超出了 vsync 间隔，导致下一个 vsync 不能及时申请；或者 doFrame 消息前，主线程 Looper 被其他耗时任务占据了。

一旦 doFrame 不能及时被执行，表现在体验上，就是设备绘制丢了一帧。当这个间隔越大，丢帧表现就越明显，App 就越卡顿。

对于 ANR 来说，其原理是类似的。我们拿系统创建 Service 举例，在目标 Service 创建过程中会调用到 realStartServiceLocked()，在 realStartServiceLocked() 内部最终会调用到 ActiveServices 的 scheduleServiceTimeoutLocked 方法，系统会在此时埋下“炸弹”，同时依据服务是前台还是后台的不同，炸弹会按照不同的时间引爆，这里前台服务是 20s。

ActiveServices.java

void scheduleServiceTimeoutLocked(ProcessRecord proc) {
    ……
    Message msg = mAm.mHandler.obtainMessage(
            ActivityManagerService.SERVICE_TIMEOUT_MSG);
    msg.obj = proc;
    mAm.mHandler.sendMessageDelayed(msg,
            proc.execServicesFg ? SERVICE_TIMEOUT : SERVICE_BACKGROUND_TIMEOUT);
}

用图表示如下：

通过一系列的系统调用，最终 ActivityThread 的内部类 ActivityThread$H 中会接收到一条 CREATE_SERVICE 消息。当 CREATE_SERVICE 被执行时，service 实例会被创建，并且会回调其 onCreate() 方法，在 onCreate() 被调用前，会通知 ActiveServices 取消掉这条超时引爆的信息。

ActiveServices.java

private void serviceDoneExecutingLocked(ServiceRecord r, boolean inDestroying,
        boolean finishing) {
        ……
        mAm.mHandler.removeMessages(ActivityManagerService.SERVICE_TIMEOUT_MSG, r.app);

如果因为种种原因导致本次 CREATE_SERVICE 不能在 20s 内得到执行，SERVICE_TIMEOUT_MSG 消息便会被执行，此时便会产生 ANR。

系统对不同的事件，其“容忍度” 和 ANR 信息引爆后的表现也有所不同，具体定义见表：

总结一下：

卡顿产生的原因是 doFrame 的消息无法在 vsync 的时间间隔内完成执行，而 ANR 是因为关键的系统消息，或者 Input 事件无法在系统定义的超时阈值内完成执行。

从本质上来说，它们是同一个问题的两种表现，只是严重程度不同而已。当设备发生了 ANR 时，往往也发生了非常严重的卡顿。

2. 为什么堆栈不准？

从前文分析可知，卡顿和 ANR 的产生原因都是特定类型消息在指定阈值内没有得到及时执行。这个阈值的时间有长有短。

对于卡顿监控，我们的阈值间隔不会很长，按业务场景和产品复杂度可能会有所不同，但一般可能在几百毫秒左右。ANR 的监控阈值更长，发生用户可感知的 ANR， 最短也有 5s，最长 10s。

当监控到卡顿和 ANR 时，其实意味着过去的几百毫秒，5s，10s 的主线程消息队列有异常的耗时任务出现，如果此时抓取堆栈，只意味着我们抓取到了卡顿和 ANR 现场的堆栈数据。

对于卡顿来说，几百毫秒的间隔不算很长，本次抓取的堆栈有较高概率可能可以命中异常耗时任务的堆栈，但也只是 “可能”。

对于 ANR 就没有那么容易命中了，毕竟过去了 5s，10s，主线程执行过的任务太多了，在这 5s 和 10s 内，每一个耗时任务，都有可能导致关键性系统消息无法及时被执行。如果在 ANR 信号发生时去抓取堆栈，大概率会将这些场景 miss 掉。

ANR 的信号是异步产生的，在接收到 ANR 信号时采集堆栈，除了有可能采集到当前消息内执行的业务堆栈外，也有可能采集到主线程 MesageQueue 正在取消息的“过程”，这个取下一条消息的方法 MessageQueue.next() 调用得非常频繁，所以命中概率很高，这也是为什么很多 ANR 上报里最终都命中了这个堆栈。

知道了堆栈不准的原因后，解决它也便有了一个很清晰的思路。

3. MDAP-LooperMonitor

其实通过上述分析可以看到，导致 ANR 和卡顿产生的原因是主线程 Looper 中有异常消息。

同时，有提示的可感知 ANR 最长耗时是 10s，如果可以通过一种机制，记录主线程过去 10s 内所有消息的调度历史，保存业务方需要的关键数据，并处理好性能和内存占用，在问题发生时，上报监控阈值内的调度数据：

• 比如在卡顿时，上报过去 500ms（可在配置平台灵活调整）的调度数据；
• 在 ANR 发生时，上报过去 10s 和尚未调度的 Pending 消息。

这样对于开发者来说，就等同于拥有了“看穿过去和未来”的能力，应该就可以解决大部分卡顿和 ANR 问题了。

MDAP 的 LooperMonitor 便是基于此思路的一种监控方案，我们在内部也做了大量技术优化来确保方案落地，比如寻找性能更优的监控入口，使用对象复用技术减少 GC 压力，使用多实例单线程模型减少同步开销，使用小消息聚合和滚动淘汰策略减少内存占用等，详见下文。

3.1 监控入口

找到主线程 Looper 的调度的入口是本次监控方案的核心，如果可以在调度的起止点插入我们想要的代码，便可以获取到当前 msg 的执行耗时。

Looper 的源码只摘取关键信息如下：

for (;;) {
            Message msg = queue.next(); // might block
            ...
            // This must be in a local variable, in case a UI event sets the logger
            final Printer logging = me.mLogging;
            if (logging != null) {
                logging.println(">>>>> Dispatching to " + msg.target + " " +
                        msg.callback + ": " + msg.what);
            }
            try {
                msg.target.dispatchMessage(msg);
                if (observer != null) {
                    observer.messageDispatched(token, msg);
                }
                dispatchEnd = needEndTime ? SystemClock.uptimeMillis() : 0;
            } catch (Exception exception) {
                throw exception;
            } finally {
            }
            
            if (logging != null) {
                logging.println("<<<<< Finished to " + msg.target + " " + msg.callback);
            } 
            ...
        }

目前绝大部分 APM SDK 都是通过设置一个 Printer 对象，在 println 方法的回调中去判断字符串是否以 >>>>> Dispatching to 和 <<<<< Finished to 来判断消息起止点的，在起止点插入统计代码，即可获得消息执行耗时。

如果有异常耗时的消息，为了定位到异常点，通常还需要获得一些额外数据：

1. 当前消息的 target： 来源自哪个 Handler，如果业务侧是通过继承 Handler 并且在 handleMessage 中处理消息的，我们需要知道这个 Handler 的位置。
2. 当前消息的 callback：如果是直接 post 一个 runnable，此时需要通过 callback 才能定位到业务代码的位置。
3. 系统消息的类型： 如果消息是由 ActivityThread$H 处理的，我们需要知道当前调度的是哪一类系统消息，从而筛选出会导致 ANR 的四大组件调度信息。

设置 Printer 的方案可以满足 1 和 2 的要求 ，但是无法拿到系统消息类型，也就是无法做到 3 的要求。

对于 3，可以再通过 hook 系统的 ActivityThread$H 的 what 字段拿到调度的消息类型。

除了设置 Printer 之外，还有更好的方案吗？

翻看源码时发现，在 Android api ≥ 28 时，Looper 中新增了一个 Observer 的接口，在消息被调度前后会回调其对应方法，并将消息对象作为参数传入了，可以尝试将其替换成我们自己的实现，这看起来是一个更高效的方法，不用产生大量临时 String 对象。

源码见下：

for (;;) {
            Message msg = queue.next(); // might block
            ...
            // Make sure the observer won't change while processing a transaction.
            final Observer observer = sObserver;
            ...
            if (observer != null) {
                token = observer.messageDispatchStarting();
            }
            try {
                msg.target.dispatchMessage(msg);
                if (observer != null) {
                    observer.messageDispatched(token, msg);
                }
            } catch (Exception exception) {
                if (observer != null) {
                    observer.dispatchingThrewException(token, msg, exception);
                }
                throw exception;
            } finally {
               
            }
            ...
        }

但是该类是一个 Hidden 的 API，无法直接拿到其类定义，从而无法在 App 侧实现该接口，同时又在反射黑名单中，无法通过反射将实现设置到 Looper 中。

对于反射限制，可以采取元反射的方法破解掉该限制，概括来说就是使用系统身份去反射，在 Api ≥31 时系统限制了元反射调用，我们对此也做了兼容处理，使得方案在 Api≥31 的设备上仍然可用。

对于无法拿到类定义，可以通过实现一个自己定义的 Stub 接口，并在编译时修改 Stub 接口对应的类型信息，保证可以通过编译的同时，也可以通过运行时类校验。

对比上述两种实现不难发现，对于业内常见的设置 Printer 的方案，随着 Looper 的 for 循环不断执行，会导致字符串频繁拼接，产生大量临时对象，有可能加重 App 的 GC 频率，导致内存抖动。

MDAP 通过绕过高版本反射限制以及编译时插桩，实现了性能更优秀的 LooperObserver 方案，同时为了兼容性和低版本的可用性， 保留了设置 Printer 的能力，在 LooperObserver 方案失败时，会降级到 Printer 方案。

3.2 支持多 Looper

对于 Looper 的监控，我们希望做成通用能力，可以监控任意线程的 Looper。因为 Looper 模型不仅仅在 Android 主线程使用了，在 ReactNative 中也大量使用了，比如 NativeModulesMessageQueueThread 和 JSMessageQueueThread，对于以 RN 为主要技术栈的 App 来说，这两个线程的 Looper 执行异常，同样会导致 App 卡顿。

如果对多 Looper 进行监控，监控模块势必被多个线程调用，为了减少频繁加锁带来的上下文切换开销，我们采用了多实例+单线程的模型。通过为每一个 Looper 创建对应的 LooperRecorder 对象来处理数据采集，每个 LooperRecorder 按照 Looper 的线程 ID 进行映射，以此做到 Recorder 实例的内部无锁。

3.3 信息采集

有了监控入口，如何采集不同消息的对应数据？

3.3.1 消息分类

其实对于不同耗时阈值的消息，业务方的关注重点也是不太一样的。

比如在大部分场景下，消息都是不耗时的小消息，执行耗时在 30ms 以下，这类消息对于 ANR 的产生影响不大，为了节约内存，记录一个总耗时和结束时间戳，以及最后一条消息的相关数据，用来将消息队列串联起来即可。

普通滚动消息，记录其 target、callback、what 字段，基于线上的符号还原，基本也可以定位到业务逻辑在哪。

对于耗时的消息，比如超过 200ms 的，只知道其 target 和 callback，可以定位到 Handler 的具体位置，但其内部的具体执行逻辑仍然是未知的，业务方更希望会有堆栈。

对于系统消息，除了上述基础数据外，还需要知道当前调度的是哪一类系统消息，从而筛选出会导致 ANR 的四大组件调度信息。

此外，当 ANR 发生时，还需要获取尚未调度的 Pending 消息。对于 Pending 消息，除了需要记录 target、what、callback 字段外，还需要记录他们超时了多久，这样当 ANR 发生时，可以检索 Pending 消息队列，找到触发本次 ANR 发生的 “炸弹”。

3.3.2 堆栈采集

对于耗时消息的堆栈采集，常见的主要是两种方案，

方案 1：编译时插桩，在函数的起止位置，插入统计代码。

这种方案的好处是，可以清晰知道方法的具体耗时；此外，如果在编译时为每个函数生成唯一 ID，还可以借助 ID 与函数名映射表，使用非常小的容量保存堆栈数据。

但这种方案对包体积和运行时性能都有一些影响；同时，它依赖接入方接入了插桩插件。

方案 2：使用子线程进行超时检测抓取。

这种方案的优点是实现简单，并且不依赖接入方是否接入插件。

缺点是抓取的堆栈比插桩方案大，并且如果频率控制不好的话，有可能对 App 性能产生较大影响。

对于方案 1， MDAP 已经实现了一套较高性能的线上函数 Tracing 方案。

方案 2 是 LooperMonitor 目前采用的方案。我们通过协程的非阻塞式挂起能力实现了高效的异步检测和采集，同时对 Looper 的 IDLE 状态做了过滤，若当前并无消息执行时，不会采集目标线程堆栈，防止采集到大量的 NativePollOnce 调用。

对耗时消息，检测阈值会线性增加，尽可能控制好采样频率，减少对线上 App 的性能影响。
对采集到的堆栈数据，会延迟到卡顿和 ANR 上报时才序列化。

后续我们会考虑将两个方案结合起来，若接入方接入了插件并且开启了 trace 功能，优先从 trace 组件获取精简的堆栈数据，进一步减少 trace 对 App 的内存和性能占用。

3.4 内存占用

App 内存是非常宝贵的资源，LooperMonitor 必须尽量保证对 App 的内存占用可控，并且尽可能减少占用，才有真正在线上运行的价值。

我们采用了一系列手段来达到这个目的。

3.4.1 对象池复用

对象池技术对于需要频繁创建和销毁的场景非常适用，可以大大减少对象创建带来的内存压力，对于减少内存抖动有非常明显的帮助。在 Android 系统内部有大量使用对象池技术的场景，比如 Message 对象、TouchEvent 对象的创建等。
在 Message 内部有一个 sPool，当使用 Message.obtain() 时，便会尝试从 sPool 中返回一个已有对象。因为整个 Android 上层是基于 Looper 和 Message 的消息循环机制实现的，所以 Message 对象的创建和销毁会非常频繁，非常适合使用对象池技术。

LooperMonitor 的消息执行记录对象 MessageInfo 同样也是适用于该场景的。

通过测试，MessageInfo 队列绝大部分只会用到 100 个左右的记录，通过为 MessageInfo 设置了一个较小的 50 个 size 的 Pool，在大部分场景下，可以减少约 50% 左右的新对象 allocating。

3.4.2 聚合小消息+滚动淘汰旧值

对于不耗时的小消息，其对 ANR 的影响有限，为了不占用宝贵的内存资源，我们会将连续的小消息聚合成一条，记录最后一条小消息的 callback 和 traget，总耗时和消息的 occurTime，用来串起整个消息 Record 队列。

消息 Record 队列的最大值目前设置为 500 条，并通过 Size + occurTime 滚动淘汰旧值。概括来说就是“超出队列上限的”以及“消息发生时间超出设定阈值比如 10s 的旧数据”会被滚动删除。

通过测算，即使在理论上的极限值（每一个消息都没有命中聚合，导致队列被小消息塞满），500 的队列长度仍然可以记录 8s 的数据。

500 个塞满是理论上的极限场景，通过对线上 App 进行实际测算一般都在 100 - 200 个 Records 之间。

不同消息因为记录的数据略有差别，内存占用情况并非完全一致。

整体的内存概览如下：

当后期开启线上 Trace 功能，fat 消息的内存占用会进一步缩小。

对主线程不同繁忙程度，这里也做了一个大概的场景+内存占用统计：

可以看到，方案基本做到了内存占用的可控。

3.5 数据看板

Looper 监控数据会跟随 ANR 和卡顿监控 一起上报到 MDAP 的分析平台去，作为卡顿和 ANR 上报的补充数据。

3.5.1 MDAP Looper 看板

Looper 的 H5 分析看板如下：

顶部色条为历史调度消息时间轴，色块长短依据消息耗时时长不同而不同，从左到右为最旧到最新的消息数据，最右边一条记录代表 JANK 发生时，也即 ANR/卡顿现场的数据，不同类型消息按照不同颜色进行区分，时间轴可横向缩放，点击每条消息均可查看详细数据。

为了方便研发同学线下开发调试，我们也提供了 Debug 的 Looper 监控看板，可以监控实时调度信息，点击可以去到详情页，查看每条调度历史详情。

3.5.2 实时 Looper 监控浮窗

Looper 实时监控浮窗使用不同颜色的柱状图代表每一条消息的耗时状况，浮窗实时更新，不同消息类型，其颜色不同。

• 横坐标代表耗时时间，单位毫秒。
• 纵坐标代表消息索引，从上到下代表最新到最旧的消息。
• 点击右上角箭头，可以采集当前快照后进入详情看板页面查看。

3.5.3 Debug 详情看板

详情看板数据和 MDAP 平台看板数据一致，只是样式有些不同，主要分为两个部分。

1）上半部分为 “Pending 消息数据”

横坐标代表 Pending 消息在 MessageQueue 的索引，从左到右代表从队头到队尾。

纵坐标代表 Pending 消息“目标执行时间点”与“卡顿/ANR 发生时”的时间点差值。

• 如果为正数，其可能是一条通过 sendMessageAtTime() 放入消息队列的消息，还未到目标执行时间点，数值代表与目标执行时间点的差值。
• 如果为负数，表示消息已经超时，其值表示超时时长，比如一个 CREATE_SERVICE 消息超时触发的 ANR，会在 Pending 消息列表中看到一个蓝色的系统消息，其 Pending 时长 <-10000ms。

2）下半部分为“历史调度数据”

• 横坐标代表消息耗时，单位为毫秒。
• 纵坐标代表消息索引，从上到下代表最新到最旧的消息，与 Looper 实时监控浮窗一致。
• 对于不同消息使用不同颜色色条进行区分，点击可以查看详细数据。

到这里，Looper 监控工具的基本介绍就结束了。下面会举一些具体案例与大家分享。

4. 案例分享

案例 1

这是一份线上的 System.log 日志：

2021-11-12 11:26:19.996 1657-11869/? E/ActivityManager: ANR in com.***.***.***
    PID: 11093
    Reason: Input dispatching timed out (*****.**CheckInActivity_ (server) is not responding. Waited 8014ms for MotionEvent(action=DOWN))
    Load: 3.89 / 2.63 / 2.44
    CPU usage from 0ms to 6012ms later (2021-11-12 11:26:13.938 to 2021-11-12 11:26:19.949):
      53% 1657/system_server: 32% user + 21% kernel / faults: 14664 minor 589 major
      52% 11093/com.***.***.***: 37% user + 14% kernel / faults: 17832 minor 34 major
      19% 25179/cnss_diag: 11% user + 7.6% kernel / faults: 7 minor
      12% 853/surfaceflinger: 4.1% user + 8.4% kernel / faults: 503 minor 7 major
      10% 499/logd: 4.3% user + 6.4% kernel / faults: 22 minor
      0% 1227/media.swcodec: 0% user + 0% kernel / faults: 19869 minor 68 major
      10% 10580/com.miui.securitycenter: 5.8% user + 4.4% kernel / faults: 4022 minor 3 major
      9.2% 9835/adbd: 3.4% user + 5.8% kernel / faults: 14 minor
      7.9% 3307/com.android.systemui: 5.4% user + 2.4% kernel / faults: 1546 minor 2 major
      7.6% 23896/com.google.android.gms.persistent: 4.4% user + 3.1% kernel / faults: 3190 minor 29 major
      0% 1135/media.codec: 0% user + 0% kernel / faults: 8815 minor 66 major
      3.6% 27550/com.miui.powerkeeper: 2.4% user + 1.1% kernel / faults: 3265 minor 104 major
      3.1% 149/kswapd0: 0% user + 3.1% kernel
      2.8% 773/android.hardware.wifi@1.0-service: 2.1% user + 0.6% kernel / faults: 262 minor
      2.8% 3685/com.android.phone: 1.4% user + 1.3% kernel / faults: 2965 minor 202 major
      2.6% 10542/kworker/u16:8: 0% user + 2.6% kernel
      ...
      0.4% 90/system: 0% user + 0.4% kernel

这里简单提一下 System.log 日志怎么看：

1）看 ANR 类型，确认分析范围

先找 ANR 原因，主要是看 Reason 这一行，对于不同的 ANR 类型，Reason 的内容会有所区别。比如 Input dispatching timed out 表示 ANR 是 Input 派发超时导致，executing service com.xx.xxx 表示是 Service 创建超时导致，通过 Reason 这一行可以定位到 ANR 类型，进而判定超时阈值是多少，比如本次 ANR 是 Input 导致，Input 超时时间是 5s，这个可以进一步帮我们缩小问题分析的时间范围。

2）看 CPU LOAD Average 数据

Load: 3.89 / 2.63 / 2.44 表示过去 1、5、15 分钟内的，正在使用或者等待使用 CPU（处于 Run queue 或 Ready queue）的进程数的平均值。具体定义可参考维基百科)。

在一般 Linux 标准下，单核 CPU 通常以 70 分位数为分水岭，也即 <0.7 为理想负载，多核 CPU 则需乘以对应核心数，但现代 Android 设备一般对多进程都有智能调度策略，例如自动冻结后台进程，或者对后台进程只定时分配少量 CPU 时间等，此时高 Load 也未必代表设备遇到性能瓶颈，某些设备其 Load average 经常维持在 40+，但依然响应流畅，CPU 使用率也不高，基于此，我们无法单纯为 Load average 定义一个绝对的判断公式。

在分析 ANR 问题时，更多是看该值有无明显劣化的趋势，比如本次 System.log 设备使用的是一颗 8 核心 CPU，4 大核 4 小核，整体看 CPU load 并无明显异常，有轻微加重趋势，但不算严重。

3）看进程 CPU 占用率

CPU usage from 0ms to 6012ms later，这里的 later 表示采集的 CPU 占用率数据为 ANR 发生后的数据，除了 later 还可能有 before 的字样，代表数据在 ANR 发生前采集。

注意：系统并不能保证采集 CPU 使用率的具体时间，我们查看此类日志也要区别来看，比如如果 CPU 数据为 ANR 后采集，那么 system_server 的 CPU 使用率高是正常的，因为 system_server 此时需要做 dump 操作。

日志中会按照 CPU 使用率从高到低将进程信息打印出来，包括 CPU 使用率、进程号、进程名、user 和 kernel CPU 占比、页错误数。

kernel 若 CPU 占比较高，说明应用侧应该发生了大量的系统调用。一般来说，发生系统调用的多数场景都是文件 IO 操作。

从日志看，本次 ANR 发生时，应用进程 CPU 占比 52%，较其他进程高出不少，ANR 发生瓶颈应该与系统其他进程无关，但 user 与 kernal 占比无明显异常，主进程应该没有 IO 异常。

4）看 App 进程页错误数量

进程的 minor 和 major 代表次要页错误和主要页错误，分别表示内存与缓存的命中情况。页错误过高说明内存频繁换页，会导致分配内存与 GC 速度显著变慢。

5）看 kswapd0 进程

kswapd0 是管理虚拟内存的进程。当设备 RAM 空间被耗尽时，kswapd0 会负责将 App 进程的部分虚拟内存写入 swap 交换区，当该进程占用率很高时，往往反映设备处于低内存状态。

整体而言，通过上述 SystemLog，可以大概看出设备 ANR 发生前后的一段时间的基本状况：CPU 负载无加重趋势，kswapd0 进程只有 3.1%，无低内存场景，应用进程 52%，相比设备其他进程而言，CPU 占用率较高，但无明显 IO 异常。

此时，需要进一步借助 Looper 监控看板工具查看本次 ANR 上报的 Looper 数据。

当 ANR 发生时，当前正在调度的消息耗时超过了 8s；继续看其 Wall 和 CPU Duration，可以看到 WallDuration 是 8369ms，但是 CPU 时间是 0，说明主线程在此时没有拿到时间片，可能处于阻塞状态。有可能是主线程 IO 了，或者在等待锁。

进一步通过堆栈定位到对应的业务逻辑，发现确实有死锁产生。

通过 Looper 看板工具，可以发现本次 ANR 的根源消息就是当前正在调度的信息严重耗时，解决掉该 bug 也就解决了这个 ANR。

另外一种场景会更隐秘一些:

案例2

ANR in **.***.*******
    PID: 5111
    Reason: executing service **.***.*******/com.***.*****.******Service
    Load: 32.79 / 32.69 / 33.14
    CPU usage from 0ms to 12126ms later (2021-12-12 20:22:05.251 to 2021-12-12 20:22:17.377):
      67% 5111/**.***.********: 52% user + 14% kernel / faults: 2186 minor 1 major
      55% 1309/system_server: 36% user + 19% kernel / faults: 2084 minor 3 major
      14% 24540/com.google.android.gms.persistent: 12% user + 2.4% kernel / faults: 29 minor 1 major
      13% 706/adbd: 2.5% user + 10% kernel
      12% 634/surfaceflinger: 8.2% user + 4.5% kernel / faults: 93 minor
      7.3% 2433/glgps4774: 4.4% user + 2.8% kernel / faults: 5 minor
      2.2% 636/powerlogd: 1.7% user + 0.4% kernel
      2.2% 1874/com.oppo.launcher: 1.4% user + 0.7% kernel / faults: 7267 minor
      0.3% 150/kswapd0: 0% user + 0.3% kernel
      0% 32322/com.google.android.gms.ui: 0% user + 0% kernel / faults: 1021 minor 22 major

先看 System.log：
executing service **.***.*******/com.***.*****.******Service 说明本次 ANR 是 Service 超时导致。

CPU 负载正常，App 主进程无明显 CPU 使用异常，kswapd0 0.3%，设备无低内存场景，本次 ANR 发生大概率不是因为设备负载和 RAM 不够，我们将分析重点放在 App 进程的 Looper 上报中。

通过 ANR 看板工具可以看到，主线程当前正在调度的消息执行耗时超过了 1767ms，是一个非常严重的耗时消息，抓取的堆栈停留在了 registerSensorManager，这个堆栈也是其他 ANR 监控 SDK 上报时抓取的 ANR 线程堆栈，如果只看到这个数据，业务方可能认为解决了这个耗时场景，就可以解决掉 ANR 问题了，但实际情况是吗？

查看顶部的 Pending 消息看板可以发现，Pending 队列已经被塞满，大量消息没有得到及时执行。

点击左边蓝色的系统消息查看详情：

一个 CREATE_SERVICE 的消息 pending 了 10s 有余，它才是引爆本次 ANR 的“炸弹”。

但当前正在执行的消息只耗费了 1.7s，它肯定不是全部原因。继续查看历史调度数据。

再往前递推 10s，发现历史还有两条严重耗时消息，总执行耗时超过 6s。这两条消息才是本次 ANR 发生的最大原因。业务方只有同时看到并解决了这两个问题，这次的 ANR 问题才可以被彻底解决。

案例 3

本次的数据比较有代表性，可以看到主线程 Looper 调度历史中，有大量飘红的消息。

每个耗时消息的 CPU 与 Wall 差距都很大，有些实际 CPU 时间只有 1ms 的，但是 WallDuration 却有 220ms，说明在此期间主线程几乎很难抢占到 CPU 时间片，大量的时间浪费在 CPU 进行任务切换上，猜测可能是当前设备 CPU 负载过重，或者主线程被其他线程抢占了太多 CPU 资源。

继续分析 system.log 日志：

12-03 19:01:47.821 1309-1328/? E/ActivityManager: ANR in com.***.******
    PID: 5323
    Reason: executing service *******/com.***.*****.service.**AppTrackingService
    Load: 46.81 / 40.09 / 41.53
    CPU usage from 0ms to 12496ms later (2021-12-03 19:01:35.306 to 2021-12-03 19:01:47.801):
      116% 5323/com.***.****** 64% user + 52% kernel / faults: 11566 minor 11 major
      45% 1309/system_server: 26% user + 18% kernel / faults: 1830 minor 4 major
      18% 634/surfaceflinger: 12% user + 5.8% kernel / faults: 49 minor
      10% 590/android.hardware.graphics.composer@2.2-service: 5% user + 5.6% kernel
      6.7% 2433/glgps4774: 4.3% user + 2.4% kernel / faults: 55 minor
      6.4% 630/audioserver: 5.7% user + 0.6% kernel / faults: 54 minor 1 major
      3% 1756/com.huawei.lbs: 2.1% user + 0.8% kernel / faults: 1 minor
      2.7% 4811/kworker/0:0: 0% user + 2.7% kernel
      2.6% 598/vendor.huawei.hardware.audio@4.0-service: 0.7% user + 1.9% kernel / faults: 4 minor
      1.9% 150/kswapd0: 0% user + 1.9% kernel
      1.2% 4542/kworker/u17:0: 0% user + 1.2% kernel
      1.1% 1849/com.android.phone: 0.6% user + 0.4% kernel / faults: 1 minor
      1.1% 30529/kworker/u16:0: 0% user + 1.1% kernel

可以看到设备整体负载有加重趋势，但不算严重（8 核 CPU）。可是，当前线程 CPU 使用率却高达 116%，kernal 占比 52%，基本占据了一半的 CPU 使用率，表示当前主进程有大量 syscall。

进一步查看 log 文件：

       46% 5323/com.***.******: 61% user + 23% kernel / faults: 247 minor
        44% 5698/realm_thread-io-4: 4% user + 40% kernel
        11% 5776/OkHttp TaskRunn: 5.8% user + 5.8% kernel
        8.7% 6055/Thread-764: 5.8% user + 2.9% kernel
        5.8% 5345/Jit thread pool: 0% user + 5.8% kernel
        3.8% 5699/realm_thread-io-5: 5.8% user + 0% kernel
        2.9% 5645/realm_thread-io-1: 2.9% user + 0% kernel
        2.9% 5704/DefaultExecutor: 0% user + 2.9% kernel
        2.9% 5724/pool-35-thread-: 2.9% user + 0% kernel

发现 realm_thread-io-4 线程占用 44% 的 CPU，同时 OkHttp TaskRunn 占用了 11%，这两个子线程加起来占用了 55% 的 CPU 使用率，同时 realm_thread-io-4 的 kernal 占比高达 40%。

这里基本可以破案了，通过进一步分析业务逻辑也印证了这个问题：一个异常的 realm_thread-io-4 在进行大量 IO，同时因为种种原因导致其 nice 值较高，抢占了大量主线程的 CPU 时间，触发了这次的 ANR。

5. 结语

以上几种案例比较典型，相信大家也注意到了这些本应该比较复杂和晦涩的 ANR 问题，借助于 LooperMonitor 强大的数据搜集和可视化能力，竟然都变得非常直观起来，这也是我们希望 LooperMonitor 能给业务侧同学带来的实际价值。

当然，工具只是辅助，最终解决和定位问题的还是要靠人的经验和分析，线上的 ANR 问题千奇百怪，只靠 LooperMonitor 的数据肯定是无法解决所有场景的。MDAP 目前仍在紧锣密鼓地开发更多能力来丰富卡顿 ANR 监控上报，为分析和定位问题提供更为详实和完备的数据，目前已有的包括 Java、Native 侧堆栈 dump、线程死锁监控，后续还即将上线线程监控，在 ANR 发生时提供更为清晰的存活线程数据。

本文作者

Xiaqiu，Android 开发工程师，来自 ShopeeFood 团队。