釘釘 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 的坎坷升級之路