Android-ANR總結及日誌分析

laity0828發表於2019-08-02
Android

ANR簡述

ANR（Application Not Responding）應用程式無響應。如果你應用程式在UI執行緒被阻塞太長時間，就會出現ANR，通常出現ANR，系統會彈出一個應用無響應對話方塊，同時會產生一個日誌檔案traces.txt，位於/data/anr/資料夾下面。

ANR產生原因

出現ANR一般有以下幾種原因：

  1. KeyDispatchTimeout(常見)
    input事件在5s內沒有處理完成
    logcat日誌關鍵字：Input event dispatching timed out
  2. BroadcastTimeout
    前臺Broadcast：onReceiver在10S內沒有處理完成發生ANR。
    後臺Broadcast：onReceiver在60s內沒有處理完成發生ANR。
    logcat日誌關鍵字：Timeout of broadcast BroadcastRecord
  3. ServiceTimeout
    前臺Service：onCreate，onStart，onBind等生命週期在20s內沒有處理完成發生ANR。
    後臺Service：onCreate，onStart，onBind等生命週期在200s內沒有處理完成發生ANR。
    logcat日誌關鍵字：Timeout executing service
  4. ContentProviderTimeout
    ContentProvider 在10S內沒有處理完成發生ANR。
    logcat日誌關鍵字：timeout publishing content providers

典型的ANR場景

  1. 主執行緒頻繁進行IO操作，比如讀寫檔案或者資料庫；
  2. 硬體操作如進行呼叫照相機或者錄音等操作；
  3. 多執行緒操作的死鎖，導致主執行緒等待超時；
  4. 主執行緒操作呼叫join()方法、sleep()方法或者wait()方法；
  5. 耗時動畫/耗資源行為導致CPU負載過重
  6. system server中發生WatchDog ANR；
  7. service binder的數量達到上限

ANR日誌分析

ANR的Log資訊儲存在：/data/anr/traces.txt，每一次新的ANR發生，會把之前的ANR資訊覆蓋掉

獲取trace檔案：adb pull /data/anr/traces.txt

獲取日誌有一點需要注意，發生ANR後，不要選擇結束程式，因為這樣AMS會kill掉該程式，有些資訊會列印不出來（比如MTK平臺上會生成db.XX.ANR，寫入到aee_exp資料夾下需要時間），最好是ANR發生後等兩三分鐘左右，再獲取日誌。

例如：

04-01 13:12:11.572 I/InputDispatcher( 220): Application is not responding:Window{2b263310com.android.email/com.android.email.activity.SplitScreenActivitypaused=false}.
5009.8ms since event, 5009.5ms since waitstarted
04-0113:12:11.572 I/WindowManager( 220): Input event 
dispatching timedout sending 
tocom.android.email/com.android.email.activity.SplitScreenActivity

04-01 13:12:14.123 I/Process( 220): Sending signal. PID: 21404 SIG:3---發生ANR的時間和生成trace.txt的時間
04-01 13:12:14.123 I/dalvikvm(21404):threadid=4: reacting to signal 3 ……
04-0113:12:15.872 E/ActivityManager( 220): ANR in com.android.email(com.android.email/.activity.SplitScreenActivity)
04-0113:12:15.872 E/ActivityManager( 220): Reason:keyDispatchingTimedOut  -----ANR的型別
04-0113:12:15.872 E/ActivityManager( 220): Load: 8.68 / 8.37 / 8.53 --CPU的負載情況
04-0113:12:15.872 E/ActivityManager( 220): CPUusage from 4361ms to 699ms ago ----CPU在ANR發生前的使用情況；備註：這個ago，是發生前一段時間的使用情況，不是當前時間點的使用情況；

04-0113:12:15.872 E/ActivityManager( 220): 5.5%21404/com.android.email: 1.3% user + 4.1% kernel / faults:
10 minor
04-0113:12:15.872 E/ActivityManager( 220): 4.3%220/system_server: 2.7% user + 1.5% kernel / faults: 11
minor 2 major
04-0113:12:15.872 E/ActivityManager( 220): 0.9%52/spi_qsd.0: 0% user + 0.9% kernel
04-0113:12:15.872 E/ActivityManager( 220): 0.5%65/irq/170-cyttsp-: 0% user + 0.5% kernel
04-0113:12:15.872 E/ActivityManager( 220): 0.5%296/com.android.systemui: 0.5% user + 0% kernel
04-0113:12:15.872 E/ActivityManager( 220): 100%TOTAL: 4.8% user + 7.6% kernel + 87% iowait----注意這行：注意87%的iowait
04-0113:12:15.872 E/ActivityManager( 220): CPUusage from 3697ms to 4223ms later:-- ANR後CPU的使用量
04-0113:12:15.872 E/ActivityManager( 220): 25%21404/com.android.email: 25% user + 0% kernel / faults: 191 minor
04-0113:12:15.872 E/ActivityManager( 220): 16% 21603/__eas(par.hakan: 16% user + 0% kernel
04-0113:12:15.872 E/ActivityManager( 220): 7.2% 21406/GC: 7.2% user + 0% kernel
04-0113:12:15.872 E/ActivityManager( 220): 1.8% 21409/Compiler: 1.8% user + 0% kernel
04-0113:12:15.872 E/ActivityManager( 220): 5.5%220/system_server: 0% user + 5.5% kernel / faults: 1 minor
04-0113:12:15.872 E/ActivityManager( 220): 5.5% 263/InputDispatcher: 0% user + 5.5% kernel
04-0113:12:15.872 E/ActivityManager( 220): 32%TOTAL: 28% user + 3.7% kernel
複製程式碼

從Logcat中可以得到以下資訊：

  1. 導致ANR的包名（com.android.emai），類名（com.android.email.activity.SplitScreenActivity），程式PID（21404）
  2. 導致ANR的原因：keyDispatchingTimedOut
  3. 系統中活躍程式的CPU佔用率，關鍵的一句：100%TOTAL: 4.8% user + 7.6% kernel + 87% iowait；表示CPU佔用滿負荷了，其中絕大數是被iowait即I/O操作佔用了。我們就可以大致得出是io操作導致的ANR。

限於篇幅有限，不在分析別的ANR型別。同時需要注意：並不是所有的ANR型別都有章可循，很多偶發的ANR受限於當時發生的環境或者系統Bug；因此對ANR，更應該強調預防而不是分析。

相關文章