教你如何 分析 Android ANR 問題

ANR介紹

ANR 的全稱是 Application No Responding，即應用程式無響應，具體是一些特定的 Message (Key Dispatch、Broadcast、Service) 在應用的UI執行緒（主執行緒）沒有在規定的時間內處理完，進而觸發 ANR 異常。

ANR 由訊息處理機制保證，Android 在系統層實現了一套精密的機制來發現 ANR，核心原理是訊息排程和超時處理。ANR 機制主體實現在系統層，所有與 ANR 相關的訊息，都會經過系統程式 system_server 排程，具體是 ActivityManagerService 服務，然後派發到應用程式完成對訊息的實際處理，同時，系統程式設計了不同的超時限制來跟蹤訊息的處理。 一旦應用程式處理訊息不當，超時限制就起作用了，它收集一些系統狀態，譬如 CPU/IO 使用情況、程式函式呼叫棧 CallStack，（有些平臺比如 MTK，還會列印相應的 Message 出來供除錯分析），最後報告使用者有程式無響應了( ANR 對話方塊)。

ANR型別

ANR 一般有三種型別：

KeyDispatchTimeout

這個主要是按鍵或觸控事件在特定時間內無響應，一般 Android 平臺預設超時時間是 5s 會報 anr，不過有些平臺會修改這個時間，比如 MTK 有些平臺就是 8s 的超時時間。

這個超時時間可以在 ActivityManagerService.java 檢視：

// M: ANR debug mechanism (Ori: 5*1000)
static final int KEY_DISPATCHING_TIMEOUT = 8*1000;

BroadcastTimeout

這類超時會有 ANR 提示框彈出，使用者可以選擇 forceStop 或者繼續等待。

這個主要是 BroadcastRecevier 在規定時間無法處理完成。前臺廣播超時時間是 10s，後臺廣播超時是 60s，這類超時沒有提示框彈出。

==> AMS.java

// How long we allow a receiver to run before giving up on it.
static final int BROADCAST_FG_TIMEOUT = 10*1000;
static final int BROADCAST_BG_TIMEOUT = 60*1000;

ServiceTimeout&nbsp

Service 在規定時間內無法處理完成操作，即會報出服務超時，這類 ANR 同樣沒有提示框出現。超時時間，前臺 Service 是 20s，後臺 Service 是 200s。

==> ActivityServices.java

// How long we wait for a service to finish executing.
static final int SERVICE_TIMEOUT = 20*1000;
// How long we wait for a service to finish executing.
static final int SERVICE_BACKGROUND_TIMEOUT = SERVICE_TIMEOUT * 10;

三種 ANR 中只有第 1 種會顯示系統提示對話方塊，因為使用者正在做介面互動操作，如果長時間沒有任何響應，會讓使用者懷疑裝置當機了，大多數人此時會開始亂按，甚至拔出電池重啟，給使用者的體驗肯定是非常糟糕的。

三種 ANR 發生時都會在 log 中輸出錯誤資訊，你會發現各個應用程式和系統程式的函式堆疊資訊都輸出到了一個 /data/anr/traces.txt 的檔案中，這個檔案是分析ANR原因的關鍵檔案，同時在日誌中還會看到當時的 CPU 使用率，這也是重要資訊，在後面的章節會詳細介紹如何利用它們分析ANR問題。

這三種ANR不是孤立的，有可能會相互影響。例如一個應用程式程式中同時有一個正在顯示的 Activity 和一個正在處理訊息的 BroadcastReceiver，它們都執行在這個程式的主執行緒中。如果 BR 的 onReceive 函式沒有返回，此時使用者點選螢幕，而 onReceive 超過 5 秒仍然沒有返回，主執行緒無法處理使用者輸入事件，就會引起第 1 種 ANR。如果繼續超過 10 秒沒有返回，又會引起第 2 種ANR。

ANR發生的原理

對於ANR 發生基本原理如下：

• 在進行相關操作呼叫 hander.sendMessageAtTime() 傳送一個 ANR 的訊息，延時時間為 ANR 發生的時間(如 activity 是當前時間 5s 之後)。

• 進行相關的操作

• 操作結束後向 remove 掉該條 message。如果相關的操作在規定時間沒有執行完成，該條 message 將被 handler 取出並執行，就發生了 ANR。

Android 對於訊息的處理都是通過 Handler 來完成的，對 Handler 不瞭解的同學可以參考文章 Android Handler 原始碼分析（詳細）。

ANR 分析示例

ANR 本質上是一個 Performance 問題，發生 ANR 的時候，如果問題可能出在 APK 自己身上，那麼主要排查的方向是 apk 本身，分析看看是不是在 UI 執行緒做了耗時的操作？

個人認為，有一些 ANR 問題是很難分析的，比如 app 執行的時候由於當前系統底層的一些影響，導致當前 message 處理失敗。這類問題往往沒有規律，又難以重現。對於這類 ANR 問題，一般需要花費大量時間去了解系統的一些其他行為，而超出了 ANR 本身的範疇，這類問題就相當於一個警示訊號，告訴你係統哪個地方出問題了。

檢視 log 日誌檔案

搜尋關鍵字 ANR :

04-17 17:15:23.817 E/ActivityManager(  187): ANR in com.da.android (com.da.android/com.text.my.app.ui.activities.ContentActivity)

上面這段文字的含義是 4月17日，17點15分23秒817ms時候發生了 ANR .其實一般還會帶上 ANR 的原因，以及 CPU 使用資訊，

這裡我們寫了一個 demo，比如在廣播接收器的 onReceive 方法（廣播接收器的 onReceive 方法預設在主執行緒執行）裡面睡眠一段時間，如果這個時候主執行緒沒有任何操作了，那麼廣播接收器可以正常執行完畢。不會造成 ANR 。如果我在傳送廣播之後然後點選多次返回按鍵，這個時候因為主執行緒睡眠了，無法響應，就會出現 ANR。

其對應的完整 log 資訊如下 ：

ANR in com.brotherd.broadcastdemo (com.brotherd.broadcastdemo/.MainActivity)
    PID: 6317
    Reason: Input dispatching timed out (Waiting to send key event because the focused window has not finished processing all of the input events that were previously delivered to it.  Outbound queue length: 0.  Wait queue length: 2.)
    // 
　　 Load: 38.14 / 37.82 / 37.45
　　// ANR 發生前 cpu 使用資訊
    CPU usage from 45678ms to 0ms ago (2020-10-27 08:39:06.256 to 2020-10-27 08:39:51.933):
      15% 1265/system_server: 12% user + 3.5% kernel / faults: 6531 minor 16 major
      13% 23112/com.android.systemui: 9.7% user + 3.5% kernel / faults: 6033 minor 103 major // minor major 表示頁的錯誤
      4.7% 578/surfaceflinger: 2.6% user + 2% kernel / faults: 469 minor 2 major
      4.4% 673/hwpged: 0% user + 4.3% kernel / faults: 29 minor
      2.3% 549/android.hardware.graphics.composer@2.2-service: 1.1% user + 1.1% kernel / faults: 149 minor
      0.1% 2246/com.huawei.android.pushagent: 0% user + 0% kernel / faults: 2583 minor 22 major
      1.5% 461/logd: 0.8% user + 0.6% kernel / faults: 52 minor
      1.5% 2077/com.huawei.powergenie: 0.7% user + 0.8% kernel / faults: 843 minor 2 major
      0.5% 17384/com.android.settings: 0.4% user + 0.1% kernel / faults: 5419 minor 73 major
      1.3% 259/mmc-cmdqd/0: 0% user + 1.3% kernel
      1% 3888/kworker/u16:0: 0% user + 1% kernel / faults: 1 minor
      0.9% 18949/android.process.media: 0.5% user + 0.3% kernel / faults: 1408 minor 8 major
      0.8% 148/kswapd0: 0% user + 0.8% kernel
      0.5% 657/dubaid: 0.3% user + 0.2% kernel / faults: 139 minor
      0.5% 2105/com.huawei.android.launcher: 0.4% user + 0.1% kernel / faults: 159 minor 1 major
      0.5% 2366/com.huawei.systemmanager:service: 0.3% user + 0.1% kernel / faults: 374 minor
      0.5% 922/hisi_frw/0: 0% user + 0.5% kernel
      0.4% 3951/kworker/u16:8: 0% user + 0.4% kernel
      0.4% 27040/com.huawei.appmarket: 0.3% user + 0.1% kernel / faults: 350 minor 2 major
      0.4% 238/kworker/0:1H: 0% user + 0.4% kernel
      0.4% 2028/com.huawei.hiview: 0.1% user + 0.2% kernel / faults: 88 minor
      0.3% 577/lmkd: 0% user + 0.3% kernel
      0.3% 677/vendor.huawei.hardware.sensors@1.0-service: 0% user + 0.3% kernel / faults: 19 minor
      0.3% 3715/kworker/u16:1: 0% user + 0.3% kernel
      0.3% 29718/com.huawei.hidisk: 0.2% user + 0.1% kernel / faults: 404 minor 1 major
      0.1% 527/zygote64: 0% user + 0.1% kernel / faults: 541 minor
      0.3% 3954/kworker/u16:10: 0% user + 0.3% kernel
      0.3% 581/powerlogd: 0.2% user + 0.1% kernel / faults: 25 minor
      0.3% 3952/kworker/u16:9: 0% user + 0.3% kernel
      0% 23351/com.huawei.hwid: 0% user + 0% kernel / faults: 854 minor 10 major
      0.1% 3945/kworker/u16:6: 0% user + 0.1% kernel
      0.2% 24447/kworker/u17:0: 0% user + 0.2% kernel
      0.2% 548/android.hardware.graphics.allocator@2.0-service: 0% user + 0.2% kernel / faults: 47 minor
      0.2% 2042/com.huawei.systemserver: 0.1% user + 0.1% kernel / faults: 95 minor
      0.2% 426/oeminfo_nvm_server: 0% user + 0.1% kernel / faults: 79 minor 205 major
      0.2% 4187/kworker/u17:1: 0% user + 0.2% kernel
      0.2% 462/servicemanager: 0% user + 0.1% kernel / faults: 20 minor
      0.2% 3633/kworker/u16:2: 0% user + 0.2% kernel
      0.2% 5290/com.huawei.health:DaemonService: 0.1% user + 0% kernel / faults: 77 minor
      0.1% 7/rcu_preempt: 0% user + 0.1% kernel
      0.1% 93/sys_heap: 0% user + 0.1% kernel
      0.1% 949/hisi_hcc: 0% user + 0.1% kernel
      0.1% 637/hisecd: 0% user + 0.1% kernel / faults: 66 minor
      0.1% 2097/com.android.phone: 0% user + 0.1% kernel / faults: 97 minor
      0.1% 3441/kworker/u16:5: 0% user + 0.1% kernel
      0.1% 526/netd: 0% user + 0.1% kernel / faults: 142 minor 2 major
      0.1% 2063/com.huawei.HwOPServer: 0% user + 0% kernel / faults: 168 minor
      0.1% 1//init: 0% user + 0% kernel / faults: 263 minor 5 major
      0% 465/vendor.huawei.hardware.hwfactoryinterface@1.1-service: 0% user + 0% kernel / faults: 113 minor 5 major
      0.1% 3944/kworker/u16:4: 0% user + 0.1% kernel
      0.1% 655/displayengineserver: 0% user + 0% kernel / faults: 21 minor
      0.1% 918/oal_gpio_rx_dat: 0% user + 0.1% kernel
      0.1% 3955/com.eg.android.AlipayGphone:push: 0% user + 0% kernel / faults: 132 minor
      0.1% 26941/com.huawe
// anr 發生後 cpu 使用情況
  2020-10-27 08:39:53.753 1265-1285/? E/ActivityManager: CPU usage from 51ms to 493ms later (2020-10-27 08:39:51.984 to 2020-10-27 08:39:52.426) with 99% awake:
      48% 1265/system_server: 10% user + 37% kernel
      45% 1285/ActivityManager: 8% user + 37% kernel
      4.9% 578/surfaceflinger: 4.9% user + 0% kernel / faults: 5 minor
      2.4% 578/surfaceflinger: 2.4% user + 0% kernel
      3.1% 3952/kworker/u16:9: 0% user + 3.1% kernel
      3.7% 23112/com.android.systemui: 3.7% user + 0% kernel
      9.7% TOTAL: 5.2% user + 4.4% kernel  // 可以從 total 裡面看到整個 cpu 的情況

首先看前面幾行：

ANR in com.brotherd.broadcastdemo (com.brotherd.broadcastdemo/.MainActivity)
PID: 6317
Reason: Input dispatching timed out (Waiting to send key event because the focused window has not finished processing all of the input events that were previously delivered to it.  Outbound queue length: 0.  Wait queue length: 2.)

這幾行表明了 ANR 發生所處的 activity，程式 ID，以及 ANR 原因（input 事件分發超時）；

ANRManager會列印出anr 前後的 cpu 使用情況，這個可以反映出當時系統的Performance狀態：

• 如果 CPU 使用量接近 100%，說明當前裝置很忙，有可能是CPU飢餓導致了ANR。

• 如果 CPU 使用量很少，說明主執行緒被BLOCK了

• 如果 IOwait 很高，說明ANR有可能是主執行緒在進行 I/O 操作造成的

那麼這個時候，我們就要看看 anr 發生的時候，主執行緒在做什麼了。

Trace 檔案（data/anr/traces.txt）

log 檔案只是告訴你 ANR 發生時間，但是並具體詳細的資訊，這時候就得檢視 trace 檔案（App 的程式發生 ANR 時，系統讓活躍的 Top 程式都進行了一下 dump，程式中的各種Thread 就都 dump 到這個 trace 檔案裡了，所以 trace 檔案中包含了每一條執行緒的執行時狀態）。

對於當前這個例子的堆疊資訊如下：

 在上面的資訊中，有這樣一行

at com.brotherd.broadcastdemo.MyReceiver.onReceive(MyReceiver.java:23)

這就是造成 ANR 的根本原因。在 MyReceiver 類的 onReceive 方法中呼叫了 Thread 的 sleep 方法導致主執行緒阻塞，造成 ANR。

然後我們看一些欄位的資訊。

"main" prio=5 tid=1 Sleeping
  | group="main" sCount=1 dsCount=0 flags=1 obj=0x7682ab30 self=0x7bd3815c00
  | sysTid=6317 nice=-10 cgrp=default sched=0/0 handle=0x7c59fc8548
  | state=S schedstat=( 1009468742 32888019 224 ) utm=91 stm=9 core=4 HZ=100
  | stack=0x7ff27e1000-0x7ff27e3000 stackSize=8MB
  | held mutexes=

這些欄位含義如下執行緒名：

執行緒自身資訊

• 執行緒優先順序：prio=5

• 執行緒ID： tid=1

• 執行緒狀態：Sleeping

• 執行緒組名稱：group="main"

• 執行緒被掛起的次數：sCount=1

• 執行緒被偵錯程式掛起的次數：dsCount=0

• 執行緒的java的物件地址：obj= 0x7682ab30

• 執行緒本身的Native物件地址：self=0x7bd3815c00執行緒排程資訊：

• Linux系統中核心執行緒ID: sysTid=6317與主執行緒的程式號相同

• 執行緒排程優先順序：nice=-10

• 執行緒排程組：cgrp=default

• 執行緒排程策略和優先順序：sched=0/0

• 執行緒處理函式地址：handle= 0x7c59fc8548

執行緒的上下文資訊：

• 執行緒排程狀態：state=S

• 執行緒在CPU中的執行時間、執行緒等待時間、執行緒執行的時間片長度：schedstat=(1009468742 32888019 224)

• 執行緒在使用者態中的排程時間值：utm=91

• 執行緒在核心態中的排程時間值：stm=9

• 最後執行這個執行緒的CPU核序號：core=4

執行緒的堆疊資訊：

• 堆疊地址和大小：stack=0x7ff27e1000-0x7ff27e3000 stackSize=8MB

執行緒狀態

 此外，執行緒的狀態很重要，瞭解這些狀態的意義對分析ANR的原因是有幫助的，總結如下：

Thread.java 中的狀態和 Thread.cpp 中的狀態是有對應關係的。可以看到前者更加概括，也比較容易理解，面向 Java 的使用者；而後者更詳細，面向虛擬機器內部的環境。traces.txt 中顯示的執行緒狀態都是 Thread.cpp 中定義的。另外，所有的執行緒都是遵循 POSIX 標準的本地執行緒。

執行緒狀態示例：

• 主執行緒是 running 或者 native： 而對應的棧對應了App中的函式，則很有可能就是執行該函式時候發生了超時。

• 主執行緒被 block：非常明顯的執行緒被鎖，這時候可以看是被哪個執行緒鎖了，可以考慮優化程式碼。如果是死鎖問題，就更需要及時解決了。

死鎖demo  

我們來看一個死鎖的例子：

"PowerManagerService" prio=5 tid=24 MONITOR
| group="main" sCount=1 dsCount=0 obj=0x41dd0eb0 self=0x5241b218
| sysTid=567 nice=0 sched=0/0 cgrp=apps handle=1380038664
| state=S schedstat=( 6682116007 11324451214 33313 ) utm=450 stm=219 core=1
at com.android.server.am.ActivityManagerService.broadcastIntent(ActivityManagerService.java:~13045)
- waiting to lock <0x41a874a0> (a com.android.server.am.ActivityManagerService) held by tid=12 (android.server.ServerThread)
at android.app.ContextImpl.sendBroadcast(ContextImpl.java:1144)
at com.android.server.power.PowerManagerService$DisplayBlankerImpl.unblankAllDisplays(PowerManagerService.java:3442)
at com.android.server.power.DisplayPowerState$PhotonicModulator$1.run(DisplayPowerState.java:456)
at android.os.Handler.handleCallback(Handler.java:800)
at android.os.Handler.dispatchMessage(Handler.java:100)
at android.os.Looper.loop(Looper.java:194)
at android.os.HandlerThread.run(HandlerThread.java:60)

 tid=24 執行緒在等待一個 <0x41a874a0> 的鎖，而這個鎖被 tid=12 的執行緒佔用了，我們來看看 tid=12：

"android.server.ServerThread" prio=5 tid=12 MONITOR
| group="main" sCount=1 dsCount=0 obj=0x41a76178 self=0x507837a8
| sysTid=545 nice=-2 sched=0/0 cgrp=apps handle=1349936616
| state=S schedstat=( 15368096286 21707846934 69485 ) utm=1226 stm=310 core=0
at com.android.server.power.PowerManagerService.isScreenOnInternal(PowerManagerService.java:~2529)
- waiting to lock <0x41a7e2e8> (a java.lang.Object) held by tid=85 (Binder_B)
at com.android.server.power.PowerManagerService.isScreenOn(PowerManagerService.java:2522)
at com.android.server.wm.WindowManagerService.sendScreenStatusToClientsLocked(WindowManagerService.java:7749)
at com.android.server.wm.WindowManagerService.setEventDispatching(WindowManagerService.java:7628)
at com.android.server.am.ActivityManagerService.updateEventDispatchingLocked(ActivityManagerService.java:8083)
at com.android.server.am.ActivityManagerService.wakingUp(ActivityManagerService.java:8077)

tid=12 執行緒在等待 <0x41a7e2e8> 的鎖，而這個鎖被 tid=85 的執行緒佔用了，我們來看看 tid=85：

"Binder_B" prio=5 tid=85 MONITOR 
| group="main" sCount=1 dsCount=0 obj=0x42744770 self=0x58329e88
| sysTid=3700 nice=-20 sched=0/0 cgrp=apps handle=1471424616
| state=S schedstat=( 1663727513 2044643318 6806 ) utm=132 stm=34 core=1
at com.android.server.power.PowerManagerService$DisplayBlankerImpl.toString(PowerManagerService.java:~3449)
- waiting to lock <0x41a7e420> (a com.android.server.power.PowerManagerService$DisplayBlankerImpl) held by tid=24 (PowerManagerService)

值得注意的是，trace裡面一般會包含時間，儘量分析跟anr時間相近的trace，避免受到其他干擾。tid=85執行緒在等待<0x41a7e420>的鎖釋放，而這個鎖被tid=24佔用了，所以就傳送了死鎖。那麼這種情況下我們就需要找到發生死鎖的source code，進行分析並修改。

其他分析思路

有時候我們 log 也分析了，traces 也分析了，還是很難分析出 ANR 的原因，那麼我們可能就需要嘗試從其他方面分析了：

• 從main log 裡面找 anr 發生時間前 8s，看看 app 的 main thread 在做什麼操作？是否有異常的地方，一般 process 的 pid 會等於主執行緒 id。

• 大範圍搜尋 log，看是否 anr 發生之前，哪裡有發生 crash？是否有可能引起 anr。

• 看情況抓取平臺的一些輔助資訊，包括但不侷限於：

  • memory info

  • process status

  • cpu info

  • Binder info

  • ftrace

減少發生 ANR 概率

• 將所有耗時操作，比如訪問網路，Socket通訊，查詢大量 SQL 語句，複雜邏輯計算等都放在子執行緒中去，然 後通過 handler.sendMessage、runonUIThread、AsyncTask 等方式更新 UI。無論如何都要確保使用者介面作的流暢 度。如果耗時操作需要讓使用者等待，那麼可以在介面上顯示度條。

• 使用 AsyncTask 處理耗時 IO 操作。在一些同步的操作主執行緒有可能被鎖，需要等待其他執行緒釋放相應鎖才能繼續執行，這樣會有一定的 ANR 風險，對於這種情況有時也可以用非同步執行緒來執行相應的邏輯。另外， 要避免死鎖的發生。

• 使用 Thread 或者 HandlerThread 時，呼叫 Process.setThreadPriority(Process.THREADPRIORITYBACKGROUND) 設定優先順序，否則仍然會降低程式響應，因為預設 Thread 的優先順序和主執行緒相同。

• 使用 Handler 處理工作執行緒結果，而不是使用 Thread.wait() 或者 Thread.sleep() 來阻塞主執行緒。

• Activity 的 onCreate 和 onResume 回撥中儘量避免耗時的程式碼

• View 的 onOnTouchevent 和 onclick 中也要避免耗時的程式碼

• BroadcastReceiver 中 onReceive 程式碼也要儘量減少耗時，建議使用 IntentService 處理。

• 各個元件的生命週期函式都不應該有太耗時的操作，即使對於後臺 Service 或者 ContentProvider 來講，應用在後臺執行時候其 onCreate() 時候不會有使用者輸入引起事件無響應 ANR，但其執行時間過長也會引起 Service 的 ANR 和 ContentProvider 的ANR

 

參考文章

Android 系統穩定性 - ANR（一）

ANR問題分析指南