釘釘 ANR 治理最佳實踐 | 定位 ANR 不再霧裏看花
作者：姜凡(步定)
本文為《釘釘 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 問題。
「其他文章」
- 為iframe正名，你可能並不需要微前端
- SLS：基於 OTel 的移動端全鏈路 Trace 建設思考和實踐
- 為iframe正名，你可能並不需要微前端
- 釘釘 ANR 治理最佳實踐 | 定位 ANR 不再霧裏看花
- 釘釘 ANR 治理最佳實踐 | 定位 ANR 不再霧裏看花
- 低代碼多分支協同開發的建設與實踐
- Flutter for Web 首次首屏優化——JS 分片優化
- 全新的 React 組件設計理念 Headless UI
- 我們是如何追逐元宇宙、XR等“概念股”浪潮的？
- 盒馬 iOS Live Activity &“靈動島”配送場景實踐
- ECMAScript 雙月報告：Hashbang Grammer 提案成功進入到 Stage 4
- 如何根治 Script Error.
- 語雀桌面端技術架構實踐
- 語雀桌面端技術架構實踐
- Clang Module 內部實現原理及源碼分析
- 基於 LowCodeEngine 的調試能力建設與實踐
- 基於 LowCodeEngine 的調試能力建設與實踐
- Android Target 31 升級全攻略 —— 記阿里首個超級 App 的坎坷升級之路