Android ANR 分析

ANR``Application Not Responding。在Android中，如果一些耗時操作造成主線程阻塞了一定時間，則系統會顯示ANR提示用戶此應用處於未響應的狀態。

ANR

ANR出現的原因

• 用戶的輸入在5s內沒被App響應

• BroadcastReceiver的onReceiver()超過10s

• Service中各生命周期函數執行超過20s

ANR經典場景

1. UI線程等待其它線程釋放某個鎖，導致UI線程無法處理用戶輸入

2. 游戲中每幀動畫都進行了比較耗時的大量計算，導致CPU忙不過來

3. Web應用中，網絡狀態不穩定，而界面在等待網絡數據

4. UI線程中進行了一些磁盤IO（包括數據庫、SD卡等等）的操作，在個別設備上因為硬件損壞等原因阻塞住了

5. 手機被其他App占用着CPU

ANR日志分析

當app出現ANR會在data/anr/目錄下生成traces.txt日志文件。每次發生ANR時都會刪除舊的traces文件，重新創建新文件。也就是說Android只保留最后一次發生ANR時的信息。

我們可以使用adb導出

adb pull /data/anr/traces.txt  d:\

以最近發生的ANR為例，我們可以從Android studio logcat很明顯的看出ANR發生的原因，用戶的輸入超時了，問題線程的PID:879

同時我們還可以通俗易懂的看出來 CPU平均負載，CPU的使用情況

// 4.67 ,3.32 ,1.49 分別表示 發生`ANR` 前一分鍾，五分鍾，十五分鍾 `CPU`的平均負載
Load: 4.67 / 3.32 / 1.49

CPU usage from 6021ms to 79ms ago:

但是要進一步分析問題還需要看traces.txt

----- pid 879 at 1970-01-02 08:05:04 -----
Cmd line: com.sandiyu.lcd

JNI: CheckJNI is off; workarounds are off; pins=2; globals=273

DALVIK THREADS:
(mutexes: tll=0 tsl=0 tscl=0 ghl=0)

"main" prio=5 tid=1 WAIT
  | group="main" sCount=1 dsCount=0 obj=0x4159cd68 self=0x414d6510
  | sysTid=879 nice=0 sched=0/0 cgrp=apps handle=1074020692
  | state=S schedstat=( 0 0 0 ) utm=602 stm=168 core=1
  at java.lang.Object.wait(Native Method)
  - waiting on <0x4159ce38> (a java.lang.VMThread) held by tid=1 (main)
  at java.lang.Thread.parkFor(Thread.java:1205)
  at sun.misc.Unsafe.park(Unsafe.java:325)
  at java.util.concurrent.locks.LockSupport.park(LockSupport.java:157)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2017)
  at java.util.concurrent.LinkedBlockingQueue.put(LinkedBlockingQueue.java:318)
  at com.sandiyu.lcd.utils.DeviceCommandSender$CommandSendThread.send(DeviceCommandSender.java:156)
  at com.sandiyu.lcd.utils.DeviceCommandSender.displayNull(DeviceCommandSender.java:81)
  at com.sandiyu.lcd.DlpPrintActivity$PrintRunnable.clearImage(DlpPrintActivity.java:884)
  at com.sandiyu.lcd.DlpPrintActivity$PrintRunnable.access$1900(DlpPrintActivity.java:253)
  at com.sandiyu.lcd.DlpPrintActivity.onBackPressed(DlpPrintActivity.java:954)
  at android.app.Activity.onKeyUp(Activity.java:2193)
  
  ...

一般trace文件頂部的線程即為ANR的元凶，找到了犯罪線程我們就可以查看、分析一下犯罪現場。

• line 1,2

----- pid 879 at 1970-01-02 08:05:04 -----
Cmd line: com.sandiyu.lcd

發現ANR 線程id，時間，名稱

• line 3,4,5

JNI: CheckJNI is off; workarounds are off; pins=2; globals=273

DALVIK THREADS:
(mutexes: tll=0 tsl=0 tscl=0 ghl=0)

線程的基本信息（tll：thread list lock，tsl：thread suspend lock，tscl：thread suspend count lock，ghl：gc heap lock）

• line "main"

"main" prio=5 tid=1 WAIT

分別說明了線程名稱，優先級，線程鎖id和線程狀態。

線程狀態有如下幾種，可以看到本次ANR 線程為WAIT狀態

java thread 狀態	cpp thread狀態	說明
TERMINATED	ZOMBIE	線程死亡，終止運行
RUNNABLE	RUNNING/RUNNABLE	線程可運行或正在運行
TIMED_WAITING	TIMED_WAIT	執行了帶有超時參數的wait、sleep或join函數
BLOCKED	MONITOR	線程阻塞，等待獲取對象鎖
WAITING	WAIT	執行了無超時參數的wait函數
NEW	INITIALIZING	新建，正在初始化，為其分配資源
NEW	STARTING	新建，正在啟動
RUNNABLE	NATIVE	正在執行JNI本地函數
WAITING	VMWAIT	正在等待VM資源
RUNNABLE	SUSPENDED	線程暫停，通常是由於GC或debug被暫停
	UNKNOWN	未知狀態

接着看

at com.sandiyu.lcd.utils.DeviceCommandSender$CommandSendThread.send(DeviceCommandSender.java:156)
  at com.sandiyu.lcd.utils.DeviceCommandSender.displayNull(DeviceCommandSender.java:81)
  at com.sandiyu.lcd.DlpPrintActivity$PrintRunnable.clearImage(DlpPrintActivity.java:884)
  at com.sandiyu.lcd.DlpPrintActivity$PrintRunnable.access$1900(DlpPrintActivity.java:253)
  at com.sandiyu.lcd.DlpPrintActivity.onBackPressed(DlpPrintActivity.java:954)

我們找到了原因，CommandSendThread.send需要等待網絡資源來更新UI，連接中斷了。這時候點擊onBackPressed長時間得不到相應，它就掛了。