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

2023-01-13  本文已影响0人  代码我写的怎么

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

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

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

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

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

术语表

系统 ANR 完整流程

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

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

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

刻舟求剑的 ANR Trace

ANR 误报过滤

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

钉钉采用的方案是：

详细流程图如下：

ANR 监控工具

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

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

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

历史任务监控

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

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

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

历史任务聚合

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

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

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

当前 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 消息列表，可以感知以下几点：

总的来说，如上图所示，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 给出的排查方向，开发同学定位到阻塞的原因是因为测试机系统硬件渲染底层有一个锁等待导致的问题。

后续

本篇文章介绍了钉钉自研的 ANRCanary 通过监控主线程的执行情况，为定位 ANR 问题提供更加丰富的信息。不过 ANRCanary 日志信息比较多，希望每个研发人员都能从中分析出导致 ANR 的原因是比较困难的。

接下来将在下篇文章中讲述钉钉基于分析算法得出 ANR 归因，并上报到 ANR 归因监控平台，帮助研发人员更快更准确的解决 ANR 问题。

作者：阿里巴巴终端技术
链接：https://juejin.cn/post/7181731795439157306

上一篇 下一篇

猜你喜欢

热点阅读