作者:姜凡(步定)
本文为《钉钉 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 问题。