乐趣区

关于android:钉钉-ANR-治理最佳实践-定位-ANR-不再雾里看花

作者：

jiezi

在

作者：姜凡(步定)

本文为《钉钉 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 给出的排查方向，开发同学定位到阻塞的起因是因为测试机系统硬件渲染底层有一个锁期待导致的问题。

后续

本篇文章介绍了钉钉自研的 ANRCanary 通过监控主线程的执行状况，为定位 ANR 问题提供更加丰盛的信息。不过 ANRCanary 日志信息比拟多，心愿每个研发人员都能从中剖析出导致 ANR 的起因是比拟艰难的。

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

评论

发表回复

您的邮箱地址不会被公开。 必填项已用 * 标注

这个站点使用 Akismet 来减少垃圾评论。了解你的评论数据如何被处理。

更多文章