您的位置: 首页 > 技术杂谈 > 正文

钉钉 ANR 治理最佳实践 | 定位 ANR 不再雾里看花

2022-12-27 16:00 https://my.oschina.net/alimobile/blog/5696198 阿里巴巴终端技术次阅读条评论

作者：姜凡(步定)

本文为《钉钉 ANR 治理最佳实践》系列文章首篇《定位 ANR 不再雾里看花》，主要介绍了钉钉自研的 ANRCanary 通过监控主线程的执行情况，为定位 ANR 问题提供更加丰富的信息。

后续将在第二篇文章中讲述钉钉基于分析算法得出 ANR 归因，上报到 ANR 归因监控平台，帮助研发人员更快更准确的解决 ANR 问题，并总结钉钉 ANR 实战踩坑与经验总结

相信大家对 Android 的 ANR 问题并不陌生。钉钉作为一个用户数超 5 亿，服务着 2100 万家组织的产品，基本上其他 App 遇到的 ANR 问题，我们都会遇到。

和大家一样，我们最初在分析 ANR Trace 日志的时候，都会不禁怀疑上报的堆栈是否真的有问题，总有一种雾里看花的感觉。

本系列文章主要介绍钉钉在 ANR 治理过程中的思考方向，工具建设，典型问题等，希望能够通过本次分享，为有 ANR 治理诉求的团队提供一定的参考。

术语表

系统 ANR 完整流程

系统 ANR 完整流程可以分为如下三个部分：

超时检测
ANR 信息收集
ANR 信息输出

对于超时检测的逻辑，业界已经有比较详细的阐述，此处不再赘述。重点聊聊检测到超时之后的处理逻辑。详细源码可以参见：ProcessRecord.java，ANR 信息收集和 ANR 信息输出两个流程图如下：

如上图所示，从系统源码中，得到的启示有：

ANR Trace 的堆栈抓取时机是滞后的，其堆栈不一定是 ANR 根因。
System Server 会对多个进程发送 SIGQUIT 信号，请求堆栈抓取的操作。
- 收到 SIGQUIT 不代表当前进程发生了 ANR ，可能是手机里有一个其他的 App 发生了 ANR，如果不进行 ANR 的二次确认，就会导致 ANR 误报。
App 可以通过进程 ANR 错误状态感知发生了前台 ANR 。

刻舟求剑的 ANR Trace

以广播发送导致 ANR 的过程为例，当 System Server 进程检测到广播处理超时时，会发送SIGQUIT 信号到 App 进程， App 进程收到信号之后，会将当前所有线程的执行堆栈 Dump 下来为 ANR Trace，并最终输出。
然而如图所示，这个 Dump 时机是有一定的滞后性的，真正导致 ANR 的 长耗时消息3 已经执行完了。当前执行消息5 是作为替罪羊被抓到的，甚至 当前执行消息5 到底消耗了多长时间也不确定。因此 Android 系统设计提供的用来分析 ANR 问题的 ANR Trace ，其实只是刻舟求剑，并不一定能定位到 ANR 的根因。

ANR 误报过滤

鉴于前面提到的收到 SIGQUIT 信号，并不代表当前进程发生了 ANR，需要一个二次确认逻辑，进行误报过滤。

钉钉采用的方案是：

在收到 SIGQUIT 信号之后，在 20 秒内轮询进程错误状态的确认是否为前台 ANR。
与此同时，因为发生后台 ANR 之后，系统会直接杀进程，而其他进程 ANR 并不会导致进程被杀，因此可以通过持久化的方案来区分。

详细流程图如下：

ANR 监控工具

工欲善其事，必先利其器。钉钉自研的 ANRCanary 监控工具，通过轮询的方式持续记录主线程最新任务的执行耗时，到发生 ANR 时，基于耗时最长的消息定位 ANR 的根因。

ANRCanary 相对于 ANR Trace，从点扩展到面，提供了主线程历史任务耗时维度的信息，解决了 ANR Trace 刻舟求剑的问题。

接下来将对上图中的关键技术方案依次进行详细说明。

历史任务监控

Android 主线程任务，可以大概划分为如下几个分类：

Handler 消息：最常见的基于 Handler 的主线程任务。
IdleHandler：消息队列进入空闲状态时执行。
nativePollOnce：从 Native 层触发，具体可能包括：
- 触摸事件处理
- 传感器事件处理
- ...

历史任务监控的目标是感知每个主线程任务的开始时间和结束时间，针对不同的主线程任务，需要采用不同的 Hook 方式。大部分的 Hook 方案，业界均有比较详细的描述，不再说明。

简单介绍一下 FakeIdle 排除法方案：

基于定时的堆栈抓取能力，将堆栈始终处于 nativePollOnce 的任务，判断为 Idle 任务。
那么既不是 Message 任务，也不是 IdleHandler 任务，还不是 Idle 时间段其余任务，单独识别为 FakeIdle 任务。

历史任务聚合

对于 ANR 来说，需要重点关注的是长耗时的任务，大部分的短耗时任务是可以忽略的。因此任务调度是可以按照一定条件进行聚合。

任务聚合的好处具体包括：

减少内存操作次数：避免内存抖动和对应用性能产生影响
压缩冗余数据：方便观察和分析

基于上述思路，将聚合以后的主线程历史任务记录分成如下几个类型：

聚合类型：主线程连续调度多个任务，并且每一个任务耗时都很少的情况下，将这些任务耗时累加。直至这些任务累计耗时超过阈值，则汇总并记录一条聚合类型的任务记录。该类型任务通常不需要关注。
Huge 类型：单个任务耗时超过设定的阈值，则单独记录一条 Huge类型的任务。同时将 Huge 任务前面尚未聚合的 N 次短时间耗时任务生成一条聚合类型的任务。该类型任务需要重点关注。
Idle 类型：主线程进入空闲状态的时间段，自然也应该生成一条记录。该类型任务通常不需要关注。
Key 类型：可能会引起 ANR 的Android 四大组件的消息，需要单独记录。称之为 Key 类型的记录。
Freeze 类型：部分厂商手机独有的 App 退后台，进程运行被冻结，直到 App 回到前台才会继续运行，被冻结的任务时间间隔可能会很长，却不能当做 Huge 类型，需要单独记录为 Freeze 类型。

当前 Running 任务

通过 ANRCanary 的当前 Running 任务信息，可以清晰的知道当前任务到底执行了多长时间，帮忙研发人员排除干扰，快速定位。借助这项监控，可以非常直观的看到 ANR 的 Trace 堆栈刻舟求剑的问题。

"runningTaskInfo":{
    "stackTrace":[
        "android.os.MessageQueue.nativePollOnce(Native Method)",
        "android.os.MessageQueue.next(MessageQueue.java:363)",
        "android.os.Looper.loop(Looper.java:176)",
        "android.app.ActivityThread.main(ActivityThread.java:8668)",
        "java.lang.reflect.Method.invoke(Native Method)",
        "com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:513)",
        "com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1109)"
    ],
    "type":"IDLE",
    "wallDuration":519
}

如上所示，基于 ANRCanary 抓取到信息，可以看到发生 ANR 时主线程当前处于 IDLE 状态，持续时间为 519 毫秒。

Pending消息列表

主线程的消息列表也是 ANRCanary 需要 Dump 的，基于 Pending 消息列表，可以感知以下几点：

消息队列中的消息是否被 Block 以及被 Block 了多久：基于 Block 时长可以判断主线程的繁忙程度。
判断是否存在 Barrier 消息泄露。一旦发生 Barrier 消息泄露，主线程会永久阻塞，导致永远处于 ANR 状态。
- 关于 Barrier 消息泄露的问题，将在后续章节进行详细探讨。
判断消息列表里是否存在重复消息：据此推断是否有业务逻辑异常导致重复任务，从而填满了主线程导致 ANR。

总的来说，如上图所示，ANRCanary 收集的主线程信息包括过去，现在，未来三个阶段。

主线程堆栈采样

每个主线程任务内部的业务逻辑对于研发人员来说都是黑盒。函数执行的耗时存在很多的不确定性。有可能是锁等待，跨进程通信，IO操作等各种情况都会导致任务执行耗时，因此需要堆栈信息帮忙定位到具体代码。

ANRCanary 实现的时间对齐的堆栈采样方案，主要目的包括：

避免频繁添加、取消超时任务
只有长耗时执行任务才会触发堆栈抓取
尽可能减少堆栈抓取的次数

如上图所示，堆栈采样的时间对齐方案具体实现如下：

由单独的堆栈采样线程负责堆栈抓取。
基于主线程的任务监听机制，每个任务的开始和结束都会告知到堆栈采样线程。
超时任务触发堆栈抓取的前提条件是：当前最新的主线程任务执行超过最低超时时间。
执行完堆栈抓取后，会对超时时长进行渐进，再丢一个超时任务，直到当前任务执行完成
长耗时后面的任务发现超时时长发生过渐进，就会执行一次堆栈采样线程消息队列的清理，重置超时任务。

案例分享

我们收到一例测试同学的反馈，说钉钉在长时间压测过程中，总是遇到 ANR 问题，阻塞了测试流程。

基于 BugReport 里的 ANR Trace 信息显示，是传感器事件处理耗时的问题。

"main" prio=5 tid=1 Runnable
  | group="main" sCount=0 dsCount=0 flags=0 obj=0x749019e8 self=0x743c014c00
  | sysTid=26378 nice=-10 cgrp=default sched=0/0 handle=0x74c1b47548
  | state=R schedstat=( 12722053200 4296751760 139559 ) utm=949 stm=323 core=2 HZ=100
  | stack=0x7febba5000-0x7febba7000 stackSize=8MB
  | held mutexes= "mutator lock"(shared held)
  at java.io.CharArrayWriter.<init>(CharArrayWriter.java:67)
  at java.io.CharArrayWriter.<init>(CharArrayWriter.java:58)
  at java.net.URLEncoder.encode(URLEncoder.java:206)
  at xxx.b(SourceFile:???)
  at xxx.build(SourceFile:???)
  at xxx.onEvent(SourceFile:???)
  at xxx.onEvent(SourceFile:???)
  at xxx.handleSensorEvent(SourceFile:???)
  - locked <0x00052b82> (a sco)
  at android.hardware.SystemSensorManager$SensorEventQueue.dispatchSensorEvent(SystemSensorManager.java:833)
  at android.os.MessageQueue.nativePollOnce(Native method)
  at android.os.MessageQueue.next(MessageQueue.java:326)
  at android.os.Looper.loop(Looper.java:160)
  at android.app.ActivityThread.main(ActivityThread.java:6718)
  at java.lang.reflect.Method.invoke(Native method)
  at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:492)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:858)

可是基于钉钉接入的 CrashSDK 里的 ANR Trace 信息显示，是硬件渲染的问题。

"main" prio=10 tid=1 Native
  | group="" sCount=0 dsCount=0 flags=0 obj=0x749019e8 self=0x7602814c00
  | sysTid=25052 nice=-10 cgrp=default sched=0/0 handle=0x7688258548
  | state=? schedstat=( 0 0 0 ) utm=0 stm=0 core=0 HZ=100
  | stack=0x7fe795e000-0x7fe7960000 stackSize=8MB
  | held mutexes=
  at android.view.ThreadedRenderer.nSyncAndDrawFrame(Native method)
  at android.view.ThreadedRenderer.draw(ThreadedRenderer.java:823)
  at android.view.ViewRootImpl.draw(ViewRootImpl.java:3321)
  at android.view.ViewRootImpl.performDraw(ViewRootImpl.java:3125)
  at android.view.ViewRootImpl.performTraversals(ViewRootImpl.java:2484)
  at android.view.ViewRootImpl.doTraversal(ViewRootImpl.java:1466)
  at android.view.ViewRootImpl$TraversalRunnable.run(ViewRootImpl.java:7196)
  at android.view.Choreographer$CallbackRecord.run(Choreographer.java:949)
  at android.view.Choreographer.doCallbacks(Choreographer.java:761)
  at android.view.Choreographer.doFrame(Choreographer.java:696)
  at android.view.Choreographer$FrameDisplayEventReceiver.run(Choreographer.java:935)
  at android.os.Handler.handleCallback(Handler.java:873)
  at android.os.Handler.dispatchMessage(Handler.java:99)
  at android.os.Looper.loop(Looper.java:193)
  at android.app.ActivityThread.main(ActivityThread.java:6718)
  at java.lang.reflect.Method.invoke(Native method)
  at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:492)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:858)

两个结论僵持不下，最后再来看看 ANRCanary 提供的信息

  "cpuDuration": 9,
    "messageStr": ">>>>> Dispatching to Handler (android.view.Choreographer$FrameHandler) {3b01fdc} android.view.Choreographer$FrameDisplayEventReceiver@bdac8e5: 0",
    "threadStackList": [
        ...
        {
            "stackTrace":[
                "android.view.ThreadedRenderer.nSyncAndDrawFrame(Native Method)",
                "android.view.ThreadedRenderer.draw(ThreadedRenderer.java:823)",
                "android.view.ViewRootImpl.draw(ViewRootImpl.java:3321)",
                "android.view.ViewRootImpl.performDraw(ViewRootImpl.java:3125)",
                "android.view.ViewRootImpl.performTraversals(ViewRootImpl.java:2484)",
                "android.view.ViewRootImpl.doTraversal(ViewRootImpl.java:1466)",
                "android.view.ViewRootImpl$TraversalRunnable.run(ViewRootImpl.java:7196)",
                "android.view.Choreographer$CallbackRecord.run(Choreographer.java:949)",
                "android.view.Choreographer.doCallbacks(Choreographer.java:761)",
                "android.view.Choreographer.doFrame(Choreographer.java:696)",
                "android.view.Choreographer$FrameDisplayEventReceiver.run(Choreographer.java:935)",
                "android.os.Handler.handleCallback(Handler.java:873)",
                "android.os.Handler.dispatchMessage(Handler.java:99)",
                "android.os.Looper.loop(Looper.java:193)",
                "android.app.ActivityThread.main(ActivityThread.java:6718)",
                "java.lang.reflect.Method.invoke(Native Method)",
                "com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:492)",
                "com.android.internal.os.ZygoteInit.main(ZygoteInit.java:858)"
            ],
            "state":"RUNNABLE",
            "wallTime":65347
        }
    ],
    "type": "HUGE",
    "wallDuration": 68497
}

ANRCanary的信息显示钉钉在硬件渲染阶段耗费了 68 秒的时间。

{
    "curThreadStack":{
        "stackTrace":[
            "android.os.MessageQueue.enqueueMessage(MessageQueue.java:569)",
            "- locked <192655128> (a android.os.MessageQueue)",
            "android.os.Handler.enqueueMessage(Handler.java:745)",
            "android.os.Handler.sendMessageAtTime(Handler.java:697)",
            "android.os.Handler.postAtTime(Handler.java:445)",
            "xxx.send(SourceFile:???)",
            "xxx.handleSensorEvent(SourceFile:???)",
            "- locked <189021104> (a xxx)",
            "android.hardware.SystemSensorManager$SensorEventQueue.dispatchSensorEvent(SystemSensorManager.java:833)",
            "android.os.MessageQueue.nativePollOnce(Native Method)",
            "android.os.MessageQueue.next(MessageQueue.java:326)",
            "android.os.Looper.loop(Looper.java:160)",
            "android.app.ActivityThread.main(ActivityThread.java:6718)",
            "java.lang.reflect.Method.invoke(Native Method)",
            "com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:492)",
            "com.android.internal.os.ZygoteInit.main(ZygoteInit.java:858)"
        ],
        "state":"RUNNABLE",
        "wallTime":12
    },
    "messageStr": "",
    "type": "LOOPER",
    "wallDuration": 12
}

而一开始 BugReport 指出的传感器事件处理，作为当前 Running 任务，只耗费了 12 毫秒。

最终基于 ANRCanary 给出的排查方向，开发同学定位到阻塞的原因是因为测试机系统硬件渲染底层有一个锁等待导致的问题。