引言

ANRCanary 在钉钉上线以后，在 ANR 问题的治理中提供了有力的支持。接下来将挑选一些钉钉遇到的典型 ANR 问题，介绍 ANRCanary 在定位 ANR 根因上的效果。同时从工具建设和最佳实践的角度，为大家总结一下钉钉在 ANR 治理方面的一些思考。

往期回顾：

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

《让 nativePollOnce 不再排名第一 | 钉钉 ANR 治理最佳实践》

1.实战案例

1.1 线程类：启动任务在主线程执行

这个案例是大家非常容易遇到的，本来不需要在主线程执行的任务，却放在了主线程执行。

现场信息

ANRCanary 提供的信息如下：

{
    "cpuDuration": 31,
    "messageStr": ">>>>> Dispatching to Handler (elz) {54931ac} itl$3@d29c599: 0",
    "threadStackList": [
        {
            "stackTrace": [
                "java.util.ArrayList.<init>(ArrayList.java:164)",
                "com.alibaba.dingtalk.android.XXXStatistic.i(SourceFile:???)",
                "com.alibaba.dingtalk.android.XXXStatistic.a(SourceFile:???)",
                "odj.execute(SourceFile:???)",
                "itl$3.run(SourceFile:???)",
                "android.os.Handler.handleCallback(Handler.java:900)",
                "android.os.Handler.dispatchMessage(Handler.java:103)",
                "android.os.Looper.loop(Looper.java:219)",
                "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)"
            ],
           "state": "RUNNABLE",
            "wallTime": 411
        }
    ],
    "type": "HUGE",
    "wallDuration": 488
}

信息解读

可以非常直观的看到该任务类型为 Huge，任务耗时为 488 毫秒，ANRCanary 提供的堆栈为该任务执行到第 411 毫秒时。

该任务对应的是一个自定义的 Handler 类：elz，对应的 Runnable 是一个匿名内部类：itl\$3

问题结论

翻阅对应的代码以后，发现这是一个需要在启动过程中执行的统计任务，因为跨进程调用了系统服务的接口，所以比较耗时，但是该任务是 UI 无关的，所以可以在子线程执行。

另外，从该问题对应的当前任务信息来看，大部分都是落在 nativePollOnce 堆栈上，所以可以认为该问题是导致 ANR Trace 中 nativePollOnce 的原因之一。

这类问题的修复比较简单，将该任务切换到子线程执行即可。

1.2 同步类：主线程等待子线程的网络超时

这个案例如果研发同学稍不小心也会遇到，主线程进入了不合理的阻塞状态。

现场信息

ANRCanary 提供的信息如下：

{
    "messageStr":">>>>> Dispatching to Handler (hfs) {d16871b} cyk$5@a26c4b7: 0",
    "threadStackList":[
        {
            "stackTrace":[
                "sun.misc.Unsafe.park(Native Method)",
                "java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:230)",
                "java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedNanos(AbstractQueuedSynchronizer.java:1063)",
                "java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireSharedNanos(AbstractQueuedSynchronizer.java:1358)",
                "java.util.concurrent.CountDownLatch.await(CountDownLatch.java:278)",
                "com.alibaba.dingtalk.android.xxx.waitTimeout(SourceFile:???)",
                "com.alibaba.dingtalk.android.xxx.rpc(SourceFile:??)",
                "cyk$5.run(SourceFile:???)",
                "android.os.Handler.handleCallback(Handler.java:938)",
                "android.os.Handler.dispatchMessage(Handler.java:99)",
                "android.os.Looper.loop(Looper.java:257)",
                "android.app.ActivityThread.main(ActivityThread.java:8399)",
                "java.lang.reflect.Method.invoke(Native Method)",
                "com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:631)",
                "com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1032)"
            ],
            "state":"TIMED_WAITING",
            "wallTime":217
        },
        ...
        {
            "stackTrace":[
                "sun.misc.Unsafe.park(Native Method)",
                "java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:230)",
                "java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedNanos(AbstractQueuedSynchronizer.java:1063)",
                "java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireSharedNanos(AbstractQueuedSynchronizer.java:1358)",
                "java.util.concurrent.CountDownLatch.await(CountDownLatch.java:278)",
                "com.alibaba.dingtalk.android.tpn.waitTimeout(SourceFile:???)",
                "com.alibaba.dingtalk.android.tpn.rpc(SourceFile:??)",
                "cyk$5.run(SourceFile:???)",
                "android.os.Handler.handleCallback(Handler.java:938)",
                "android.os.Handler.dispatchMessage(Handler.java:99)",
                "android.os.Looper.loop(Looper.java:257)",
                "android.app.ActivityThread.main(ActivityThread.java:8399)",
                "java.lang.reflect.Method.invoke(Native Method)",
                "com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:631)",
                "com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1032)"
            ],
            "state":"TIMED_WAITING",
            "wallTime":11284
        }
    ],
    "type":"HUGE",
    "wallDuration":12016
}

信息解读

可以看到该任务类型为 Huge，任务耗时为 12016 毫秒。ANRCanary 通过定时采样得到的多个堆栈显示主线程处于 TIMED_WAITING 状态至少有：11284 - 217 = 11067 毫秒，也就是说主线程长时间处于阻塞状态。

阻塞的原因从线程堆栈可以看到是因为调用了：CountDownLatch#await 函数。

问题结论

通过查阅对应的 CountDownLatch 对象的使用范围，发现原来主线程在等待一个子线程网络请求的返回，等待超时时间最长为 30 秒。

如果用户处于弱网状态，网络请求耗时比较长，就会触发这个问题。

通过代码历史回溯，发现这个等待机制最初设计的也没有问题，因为只会在子线程执行，但是后续随着代码迭代，新增的代码开始在主线程执行，然后又仅在弱网下会有问题，隐藏的比较深，因此一直没有发现这个问题。

其实这类随着代码迭代，不小心踩坑的现象大量存在，需要在机制实现之初，增加一些防卫型的告警逻辑。

1.3 密集型场景：日志模块将消息队列打满导致阻塞

这个案例将会告诉大家，在调用频率特别高的地方写代码一定要小心。

现场信息

ANRCanary 提供的信息如下：

"messageStr":"fakeIdle",
    "threadStackList":[
        {
            "stackTrace":[
                "android.os.MessageQueue.enqueueMessage(MessageQueue.java:656)",
                "- locked <185872167> (a android.os.MessageQueue)",
                "android.os.Handler.enqueueMessage(Handler.java:771)",
                "android.os.Handler.sendMessageAtTime(Handler.java:717)",
                "android.os.Handler.sendMessageDelayed(Handler.java:687)",
                "android.os.Handler.post(Handler.java:416)",
                "owy$a.a(SourceFile:???)",
                "owy.a(SourceFile:???)",
                "owy.k(SourceFile:???)",
                "com.alibaba.dingtalk.android.util.Log.d(SourceFile:???)",
                "com.alibaba.dingtalk.android.xxx.onLoad(SourceFile:???)",
                "org.chromium.android_webview.AwContentsClientBridge.onResourceFinishLoad(PG:???)",
                "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:8349)",
                "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:1055)"
            ],
            "state":"RUNNABLE",
            "wallTime":183
        },
        ...
        {
            "stackTrace":[
                "android.os.MessageQueue.enqueueMessage(MessageQueue.java:616)",
                "- waiting on <185872167> (a android.os.MessageQueue)",
                "android.os.Handler.enqueueMessage(Handler.java:771)",
                "android.os.Handler.sendMessageAtTime(Handler.java:717)",
                "android.os.Handler.sendMessageDelayed(Handler.java:687)",
                "android.os.Handler.post(Handler.java:416)",
                "owy$a.a(SourceFile:???)",
                "owy.a(SourceFile:???)",
                "owy.k(SourceFile:???)",
                "com.alibaba.dingtalk.android.util.Log.d(SourceFile:???)",
                "com.alibaba.dingtalk.android.mwc.onLoad(SourceFile:???)",
                "org.chromium.android_webview.AwContentsClientBridge.onResourceFinishLoad(PG:???)",
                "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:8349)",
                "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:1055)"
            ],
            "state":"BLOCKED",
            "wallTime":11260
        }
    ],
    "type":"HUGE",
    "wallDuration":13642
}

信息解读

可以看到该任务类型为 Huge，任务耗时为 13642 毫秒。

ANRCanary 通过定时采样得到的 9 个堆栈：

前面 2 个堆栈显示主线程处于 RUNNABLE 状态，处于正常运行状态。
后面 7 个堆栈显示主线程处于 BLOCKED 状态，因为等待系统底层的 MessageQueue 对象锁而被阻塞。
堆栈显示的操作都是往消息队列添加消息。

怀疑是子线程在和主线程竞争锁资源导致的问题。

源码分析

来看看 MessageQueue 的代码：MessageQueue.java^[1]

boolean enqueueMessage(Message msg, long when) {
    // 1. 请求获取锁
    synchronized (this) {
        // 2. 获取锁成功
        ...
        // 3. 取出队列里面的消息链表头
        Message p = mMessages;
        Message prev;
        // 4. 执行插入排序算法，遍历链表找到插入位置
        for (;;) {
            prev = p;
            p = p.next;
            if (p == null || when < p.when) {
                // 遍历到末尾或找到插入位置
                break;
            }
            ...
        }
        //  5. 执行消息的插入，保持消息链表依然按照时间顺序排列
        msg.next = p;
        prev.next = msg;
        ...
    }
    // 6. 释放锁
    return true;
}

如上所示：

往消息队列里面添加消息，需要先获取锁，然后执行一个插入排序的算法。
如果消息队列里面的消息积累了很多，则代码里面的循环遍历执行会比较耗时，导致锁不会释放，从而阻塞到其他线程的同样操作。

问题结论

基于 ANRCanary 提供的堆栈翻阅代码，最终发现该业务模块对接日志模块的工具函数封装的有问题，每次调用都会新增一个线程切换的 Runnable。

而该工具函数属于高频调用函数，导致线程模块的消息队列被打满，最终阻塞了主线程的执行。

这类问题隐蔽性也比较高，通常建议是：在函数里添加代码时，要先确认函数的调用频率。

1.4 极限场景：聊天框表情过多导致卡死

再来看一个极限场景下才会出现的案例。

现场信息

ANRCanary 提供的信息如下：

{
    "cpuDuration":4209,
    "messageStr":">>>>> Dispatching to Handler (com.android.internal.view.IInputConnectionWrapper$MyHandler) {e9507e8} null: 50",
    "threadStackList":[
        ...
        {
            "stackTrace":[
                "android.text.DynamicLayout.reflow(DynamicLayout.java:612)",
                "android.text.DynamicLayout$ChangeWatcher.reflow(DynamicLayout.java:1091)",
                "android.text.DynamicLayout$ChangeWatcher.onSpanRemoved(DynamicLayout.java:1116)",
                "android.text.SpannableStringBuilder.sendSpanRemoved(SpannableStringBuilder.java:1296)",
                "android.text.SpannableStringBuilder.removeSpan(SpannableStringBuilder.java:501)",
                "ehk.a(SourceFile:???)",
                "com.alibaba.dingtalk.android.xxx.onTextChanged(SourceFile:???)",
                "android.widget.TextView.handleTextChanged(TextView.java:10722)",
                "android.widget.TextView$ChangeWatcher.onTextChanged(TextView.java:13477)",
                "android.text.SpannableStringBuilder.sendTextChanged(SpannableStringBuilder.java:1267)",
                "android.text.SpannableStringBuilder.replace(SpannableStringBuilder.java:576)",
                "android.view.inputmethod.BaseInputConnection.replaceText(BaseInputConnection.java:869)",
                "android.view.inputmethod.BaseInputConnection.commitText(BaseInputConnection.java:217)",
                "com.android.internal.widget.EditableInputConnection.commitText(EditableInputConnection.java:177)",
                "com.android.internal.view.IInputConnectionWrapper.executeMessage(IInputConnectionWrapper.java:344)",
                "com.android.internal.view.IInputConnectionWrapper$MyHandler.handleMessage(IInputConnectionWrapper.java:89)",
                "android.os.Handler.dispatchMessage(Handler.java:107)",
                "android.os.Looper.loop(Looper.java:237)",
                "android.app.ActivityThread.main(ActivityThread.java:7830)",
                "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:1040)"
            ],
            "state":"RUNNABLE",
            "wallTime":3925
        }
    ],
    "type":"HUGE",
    "wallDuration":4222
},
{
    "cpuDuration":4072,
    "messageStr":">>>>> Dispatching to Handler (com.android.internal.view.IInputConnectionWrapper$MyHandler) {e9507e8} null: 50",
    "threadStackList":[
        ...
        {
            "stackTrace":[
                "android.text.DynamicLayout.reflow(DynamicLayout.java:612)",
                "android.text.DynamicLayout$ChangeWatcher.reflow(DynamicLayout.java:1091)",
                "android.text.DynamicLayout$ChangeWatcher.onSpanRemoved(DynamicLayout.java:1116)",
                "android.text.SpannableStringBuilder.sendSpanRemoved(SpannableStringBuilder.java:1296)",
                "android.text.SpannableStringBuilder.removeSpan(SpannableStringBuilder.java:501)",
                "ehk.a(SourceFile:???)",
                "com.alibaba.dingtalk.android.xxx.onTextChanged(SourceFile:???)",
                "android.widget.TextView.handleTextChanged(TextView.java:10722)",
                "android.widget.TextView$ChangeWatcher.onTextChanged(TextView.java:13477)",
                "android.text.SpannableStringBuilder.sendTextChanged(SpannableStringBuilder.java:1267)",
                "android.text.SpannableStringBuilder.replace(SpannableStringBuilder.java:576)",
                "android.view.inputmethod.BaseInputConnection.replaceText(BaseInputConnection.java:869)",
                "android.view.inputmethod.BaseInputConnection.commitText(BaseInputConnection.java:217)",
                "com.android.internal.widget.EditableInputConnection.commitText(EditableInputConnection.java:177)",
                "com.android.internal.view.IInputConnectionWrapper.executeMessage(IInputConnectionWrapper.java:344)",
                "com.android.internal.view.IInputConnectionWrapper$MyHandler.handleMessage(IInputConnectionWrapper.java:89)",
                "android.os.Handler.dispatchMessage(Handler.java:107)",
                "android.os.Looper.loop(Looper.java:237)",
                "android.app.ActivityThread.main(ActivityThread.java:7830)",
                "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:1040)"
            ],
            "state":"RUNNABLE",
            "wallTime":3704
        }
    ],
    "type":"HUGE",
    "wallDuration":4092
}

信息解读

可以看到有连续的两个 Huge 任务，每个任务的耗时都超过 4 秒。

从抓到的堆栈信息来看：

堆栈都包含 ChangeWatcher.onTextChanged，说明这些任务应该是由 EditText 的文本变更触发的，所以容易连续触发，导致出现多个任务。
堆栈都包含 SpannableStringBuilder.removeSpan，说明跟富文本有关，最常见的是表情符号。

因此怀疑是聊天框里的表情符号特别多的情况下会触发该问题。

问题结论

经过本地复现，发现当聊天框中的输入法自带 Emoji 符号超过 200 个，再进行文本变更时，可以稳定的复现该问题。

该问题的相关代码目的是为了将输入法自带 Emoji 符号转换为钉钉 Emoji 符号显示，避免显示多套 Emoji 符号。因此每次文本变更，都需要将表情符号全部删除，转换好之后再次添加进来。所以当表情符号比较多的时候，就会导致执行耗时。

这个问题的启示是：如果数据来源是用户输入（或其他不可控来源），一定要定义上限规则，避免出现极限场景的性能问题。

1.5 跨进程场景：跨进程读 SharedPreferences 导致耗时

跨进程通信由于其自身的复杂性，从系统层面来看，属于成功率还算有保障，但是耗时不可控的操作。下面看一个与之相关的案例。

现场信息

ANRCanary 提供的信息如下：

{
    "messageStr":">>>>> Dispatching to Handler (android.app.ActivityThread$H) {2c3df4} android.app.-$$Lambda$LoadedApk$ReceiverDispatcher$Args$_BumDX2UKsnxLVrE6UJsJZkotuA@abe477f: 0",
    "threadStackList":[
        ...
        {
            "stackTrace":[
                "android.os.BinderProxy.transactNative(Native Method)",
                "android.os.BinderProxy.transact(BinderProxy.java:532)",
                "android.content.ContentProviderProxy.call(ContentProviderNative.java:656)",
                "android.content.ContentResolver.call(ContentResolver.java:2080)",
                "android.content.ContentResolver.call(ContentResolver.java:2060)",
                "ecx.getString(SourceFile:???)",
                "com.alibaba.dingtalk.util.a.a(SourceFile:???)",
                "com.alibaba.dingtalk.android.d$d.onReceive(SourceFile:???)",
                "android.app.LoadedApk$ReceiverDispatcher$Args.lambda$getRunnable$0$LoadedApk$ReceiverDispatcher$Args(LoadedApk.java:1660)",
                "android.app.-$$Lambda$LoadedApk$ReceiverDispatcher$Args$_BumDX2UKsnxLVrE6UJsJZkotuA.run(Unknown Source:2)",
                "android.os.Handler.handleCallback(Handler.java:900)",
                "android.os.Handler.dispatchMessage(Handler.java:103)",
                "android.os.Looper.loop(Looper.java:219)",
                "android.app.ActivityThread.main(ActivityThread.java:8349)",
                "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:1055)"
            ],
            "state":"RUNNABLE",
            "wallTime":11331
        }
    ],
    "type":"HUGE",
    "wallDuration":12434
}

信息解读

可以看到该任务类型为 Huge，任务耗时为 13642 毫秒。

从抓到的堆栈信息来看：

多次堆栈抓取的内容都是相同的，卡在跨进程通信
该任务来自于 onRecevie 的广播生命周期函数

从监控平台的进程维度分析来看，该问题均发生在子进程，主进程没有问题。

问题结论

基于堆栈，对照源码分析发现，跨进程操作其实来自于钉钉封装的跨进程 SharedPreferences 模块，该模块通过 ContentProvider 来支持 SharedPreferences 的跨进程读写能力。

出现该问题的原因是 ContentProvider 是运行在主进程的，因为主进程不涉及跨进程通信，所以没有问题。

当子进程存活，而主进程不存活的情况，子进程读 SharedPreferences 需要先拉起主进程才能响应，整个操作过程就比较漫长，而导致子进程发生了 ANR。

从这个案例来看，跨进程属于重度操作，应该尽可能的减少非必要的跨进程操作。

1.6 小结

由于系统 ANR Trace 刻舟求剑的特性，很多时候无法提供准确有效的信息，可分析性较差。

虽然有些时候 ANR Trace 提供的堆栈和 ANRCanary 是一样的，但是 ANRCanary 会额外提供任务耗时，线程状态，锁信息以及历史堆栈等更加丰富的信息，帮助研发人员更快更准确的定位到 ANR 问题的根因。

2.工具建设

接下来将在本节跟大家聊聊钉钉 ANRCanary 在研发过程的心得与体会。

2.1 深挖根因

新工具的建设需要有的放矢，需要解决现有工具的不足及研发同学的痛点，而每个问题的背后都有其深层次的原因。

钉钉在决定自研 ANRCanary 前，面临的主要问题是 ANR Trace 的可分析性差、聚合不准。通过深入系统源码分析 ANR Trace 生成过程，发现了 ANR Trace 刻舟求剑的问题，也解释了为什么 ANR 头部问题总是 nativePollOnce 的现象，然后通过实现监控主线程历史任务的方案解决该问题。

此外同样是基于系统源码，发现了进程收到 SIGQUIT 信号和进程发生 ANR 并不能画等号的情况，解释了现有 CrashSDK ANR 误报率高的现象，然后通过实现 ANR 误报过滤算法解决该问题。

2.2 高可用

如果 ANRCanary 上线以后被发现存在误判或错漏，研发人员会倾向于不相信上报的 ANR 问题，最终影响后续的 ANR 问题的治理进度，因此我们非常重视 ANRCanary 的可靠性问题。

单元测试

使用单元测试可以快速，反复，纯粹，全面的验证代码的可靠性。

以测试 ANRCanary 死锁检测中的有向无环图算法为例，如果用黑盒测试的方式来验证该算法，需要的测试用例包括：

通过了上面测试用例的有向无环图算法，可靠性将得到极大的提升。

ANRCanary 的核心逻辑均优先用单元测试进行覆盖，单测代码覆盖率达到 80%，其中：

Junit 测试用例 203 例，全量回归一次耗时 20 秒以内。
AndroidJunit 测试用例 86 例，全量回归一次耗时 10 分钟以内。

监控指标

监控指标是工具的眼睛，没有监控指标的工具在上线以后，无异于盲人摸象，无法感知其在用户侧的真实表现。

为了验证 ANRCanary 在上线之后的可靠性，在 ANRCanary 的核心逻辑上都进行了数据埋点，涉及的监控指标包括：

主线程消息监控成功率
IdleHandler 监控成功率
死锁检测支持率
死锁监控成功率
等等

2.3 易用性

如果 ANRCanary 收集到的信息，只能发现问题，但是不能定位问题，也不能算是一个好的工具。

能快速对应到问题代码吗？

假如 ANRCanary 仅仅是监控了主线程的运行，只知道某个主线程任务的耗时很长，却没有有效的堆栈信息，令研发人员无从下手，那 ANRCanary 的价值将大打折扣。

因此堆栈抓取能力是必不可少的，同时为了避免频繁的堆栈抓取导致主线程卡顿了，ANRCanary 又改善了堆栈采样算法，采用时间对齐的采样方案。

能够快速定位原因吗？

加入了堆栈抓取机制之后，已经可以定位到 ANR 问题对应的代码了。但是由于 ANRCanary 记录了主线程过去，现在，未来的三部分信息，内容太多，想要人工分析一份 ANRCanary 日志，依然是非常麻烦的。因此又实现了 ANR 归因算法，输出一份摘要信息，放在 ANRCanary 日志的最前面，示例如下：

// ANR 归因摘要信息
"anrReasonInfo":{
    "extra":{
      // 任务耗时
        "duration":832,
        // 任务索引
        "index":14,
        // 任务信息
        "message":">>>>> Dispatching to Handler (elz) {943d152} itl$3@3134c23: 0",
    },
    // 任务聚合签名
    "signature":"F:huge:elz|itl$*|0",
    // 任务类型
    "type":"HUGE"
}

基于摘要信息里面的任务耗时或任务索引，就可以从超长的 ANRCanary 日志中快速定位到有问题的 Huge 任务。

能够快速治理用户问题吗？

有了 ANRCanary 之后，发现聚合在头部的 nativePollOnce ，其背后的真实原因并不相同，如果基于 nativePollOnce 的上报记录，挨个分析治理，可能会一直停留在边缘 Case 里面，导致整体的 ANR 问题治理推进缓慢。

因此需要基于 ANR 归因算法提取导致 ANR 的真实原因，得到聚合签名之后，上报到监控平台进行聚合，得出 ANR 归因排名。

再针对排名头部的 ANR 归因去进行治理，才能达到事半功倍的效果。

2.4 实战验证

ANRCanary 的目标是要打造一款 ANR 根因的监控工具，帮助团队解决 ANR 问题，需要在实战中验证效果。

所以 ANRCanary 每完成一个最小闭环（MVP），就会小批量灰度一次验证效果，最终在 ANRCanary 合并到主干前，经历了多轮的灰度验证。

每轮灰度，都需要仔细观察 ANRCanary 各项能力在用户侧的表现，遇到问题就解决问题，并在下一轮灰度中继续验证。举例说明：

Barrier 消息泄露

在灰度中发现部分用户的消息队列不可思议的长达 5000 个以上。经过深入分析原因之后，发现原来是发生了 Barrier 消息泄露。

因此开始探究 Barrier 消息的系统设计原理，以及如何进行 Barrier 消息泄露的检测和修复的方案。

Freeze 任务类型

在前期灰度中还发现只是简单的读一个 SharedPreferences ，却耗时长达 3 个小时。基于用户同样的机型进行测试，将钉钉切后台静置，再切回前台，复现了这个现象。

再仔细研究 Logcat 日志，发现了部分厂商手机存在进程 Freeze 机制。然后通过识别算法将 Freeze 任务标记出来。

后面还发现部分 Huge 任务同时也存在被 Freeze 的情况，因此定义了一个新的任务类型：HugeFreeze，通过改进 Freeze 识别算法将该任务类型单独识别出来。

FakeIdle 任务

ANRCanary 最初只使用了 LooperPrinter 的方式监控 Looper 里面的消息运行。在灰度中发现部分 Idle 任务也在消耗线程 CPU 时间，这明显不合常理。

经过对系统机制的深入研究之后，发现主线程任务不是仅仅有 Message 任务。还有 IdleHandler 任务，触摸事件任务，按键事件任务，传感器事件任务，浏览器事件任务等等，都是 LooperPrinter 机制感知不到的。

为此新增了：

IdleHandler 的 Hook 来感知 IdleHandler 任务的运行。
FakeIdle 识别机制将特殊事件任务，从普通的 Idle 任务中剥离出来。

2.5 小结

工具的建设是无止境的，唯有深入系统原理，贴近用户，不停的打磨，才能做出有价值又好用的工具。

3.最佳实践

在治理钉钉 ANR 问题的过程中，发现很多的研发同学在写代码的过程中，可能更关注功能实现的完整性，却比较少关注对性能的影响。

为此，总结了一下避免 ANR 问题的最佳实践，希望对大家规避性能问题能够有所帮助。

3.1 观察者模式陷阱

观察者模式是日常开发中最常见的设计模式之一，其中 Android 自带的 LocalBroadcastManager 和著名的开源组件 EventBus，也是观察者模式的实现形式。

观察者模式的特点是依赖抽象，不依赖具体实现，而正因为太过抽象，也容易导致失控。

主线程耗时

观察者在收到被观察者的通知时，通常是直接执行实现代码，不会另外再切换线程。

如果被观察者是在主线程发出的通知，而观察者直接去执行 IO 操作，就容易导致主线程耗时。

因此被观察者在实现时要有一个大概的考量：

如果对应的观察者实现大部分是需要去刷新 UI 的，则建议在主线程发出通知
如果对应的观察者实现大部分是 IO 操作，比如读写数据库或网络请求，则建议在子线程发出通知

观察者在实现时，也要注意：如果要做耗时操作，要明确通知是在主线程还是子线程发出的。

死锁

在观察者模式中，对于被观察者来说，可能只是简简单单的发出通知。

但是对应的观察者可能会有很多个，实现的代码逻辑可能是非常复杂的，无意间就可能会导致死锁。目前 ANRCanary 从线上检测到的死锁记录，大部分都属于此类场景。

3.2 密集型场景

在写代码时，要有全局意识，明白所写代码的触发频率，在高频触发的密集型场景下写代码就需要非常小心，否则容易产生严重的性能问题。

密集型场景下执行耗 CPU 的操作，比如：UI 渲染，会导致用户耗电。
密集型场景下执行 IO 操作，比如：读写数据库，到导致用户卡顿。
密集型场景下执行网络请求，这个是最危险的，会导致服务器雪崩。

具体到代码中，常见的密集型场景有：

UI 绘制函数：主要是指 onDraw 函数，一秒钟可能会执行 60 次。在这个函数里面，连创建新对象的操作，都有可能会导致频繁触发 GC 。
触摸事件：主要是指 onTouchEvent 函数，用户的一个滑动手势可能会连续触发触摸事件 10 多次。
列表滚动：主要是指 onScroll 函数，触发频率和触摸事件类似。钉钉遇到的一个 Case 就是在列表滚动的时候触发了数据库操作导致了 ANR 问题。
日志打印：主要是 App 各自实现的日志工具函数。钉钉遇到的一个 Case 就是在日志打印函数里面执行线程切换，线程队列被打满导致的 ANR 问题。

3.3 跨进程场景

跨进程通信会用到 Android 系统的公共资源，因此容易受到其他 App 的影响，耗时情况不可控。

对于跨进程的使用，建议有：

尽量避免跨进程数据依赖，做到进程内自闭环。
尽量用存活时间长的进程作为服务进程，避免跨进程通信还要等待服务进程启动的耗时。
抱着不信任的态度，尽量避免在主线程执行跨进程通信。

3.4 极限场景

一个 App 用户累计到一定程度的时候，总是会遇到一些用户侧能够必现，但本地无法复现的问题。经过仔细研究后发现其实是极限场景下才会出现的问题。

用户输入

如果 App 的数据来源是由用户输入，应该做好上限规约，比如：

限制输入框表情不应该超过 100 个，否则可能因为输入框计算耗时导致卡顿。
限制聊天消息显示长度不超过 100 行，否则可能会导致 UI 渲染耗时。

如果没有上限规约，在极限场景将会导致用户体验降低，引发各种各样的问题。这是在写代码之前就要考虑好的事情。

重度用户

重度用户属于另一种极限场景，常在老用户身上发生。

随着日积月累，重度用户遇到的典型案例就是 SharedPreferences 文件越来越大，同时

研发人员读写 SharedPreferences 通常都不会注意线程问题，在主线程操作 SharedPreferences 的情况比比皆是，导致主线程发生阻塞。

对于 SharedPreferences 的使用推荐：

在子线程写 SharedPreferences，直接调用 commit ，这种情况没有必要切线程，commit 的开销比 apply 小。
在主线程写 SharedPreferences，应该使用 apply 的方式。
SharedPreferences 应该按照模块名称去读写对应的文件，而不应该一整个应用都读写一个 SharedPreferences 文件。
SharedPreferences 仅适用于轻量级的持久化信息保存，对于数据量较大的场景，建议使用其他的存储方式。

3.5 StrictMode

在 Debug 包下，主线程访问网络，Android 会直接抛出 NetworkOnMainThreadException 异常。这个其实是 Android 自带的 StrictMode 的一项检查，StrictMode 下检测项很多，其中可能会导致 ANR 的检测项有：

主线程读写磁盘
主线程访问网络

另外 StrictMode 还支持自定义慢函数告警，如果在开发中，对于某些明确不应该在主线程执行的慢函数（比如会进入阻塞状态或耗时计算），可自行添加线程检查。

一旦发现函数在主线程执行，可以调用：android.os.StrictMode#noteSlowCall 函数进行告警和调用栈输出。

3.6 小结

通常定位一个性能问题的过程会非常曲折，可是到最后却发现，往往是因为研发人员在写代码时，没有多想一步而导致的问题。因此做好最佳实践，可以帮助研发人员在实际工作中规避掉很多性能问题。

热门

活动广场

任务中心

开发者评测

高校计划

乘风者计划

训练营

阿里云MVP

话题

直播

下载

镜像站

技术资料

插件

钉钉 ANR 实战踩坑与经验总结 | 钉钉 ANR 治理最佳实践

引言

1.实战案例

1.1 线程类：启动任务在主线程执行

现场信息

信息解读

问题结论

1.2 同步类：主线程等待子线程的网络超时

现场信息

信息解读

问题结论

1.3 密集型场景：日志模块将消息队列打满导致阻塞

现场信息

信息解读

源码分析

问题结论

1.4 极限场景：聊天框表情过多导致卡死

现场信息

信息解读

问题结论

1.5 跨进程场景：跨进程读 SharedPreferences 导致耗时

现场信息

信息解读

问题结论

1.6 小结

2.工具建设

2.1 深挖根因

2.2 高可用

单元测试

监控指标

2.3 易用性

能快速对应到问题代码吗？

能够快速定位原因吗？

能够快速治理用户问题吗？

2.4 实战验证

Barrier 消息泄露

Freeze 任务类型

FakeIdle 任务

2.5 小结

3.最佳实践

3.1 观察者模式陷阱

主线程耗时

死锁

3.2 密集型场景

3.3 跨进程场景

3.4 极限场景

用户输入

重度用户

3.5 StrictMode

3.6 小结

阿里巴巴终端技术

热门文章

最新文章

相关课程

相关电子书

相关实验场景