應用與系統穩定性第一篇---ANR問題分析的一般套路

安卓開發 · 發表 2018-10-20 17:39:49

摘要： ANR（App Not Responding）基本上99%的App都有，即使是系統，也有system_anr，我相信雖然ANR問題這樣的普遍，還是有很多人對ANR問題即熟悉又陌生的，ANR中log資訊怎麼看？發生的場景有哪些？廣播會發生ANR嗎？我的App啥事都沒有幹怎麼發生了ANR了等等...

ANR（App Not Responding）基本上99%的App都有，即使是系統，也有system_anr，我相信雖然ANR問題這樣的普遍，還是有很多人對ANR問題即熟悉又陌生的，ANR中log資訊怎麼看？發生的場景有哪些？廣播會發生ANR嗎？我的App啥事都沒有幹怎麼發生了ANR了等等一些問題，今天通過三個案例總結一下ANR問題分析的一般套路，以做備忘。

一、ANR初步瞭解

1、發生原因

一句話總結：沒有在規定的時間內，幹完要乾的事情，就會發生ANR。

2、ANR分類

從發生的場景分類：

Input事件超過5s沒有被處理完
Service處理超時，前臺20s，後臺200s
BroadcastReceiver處理超時，前臺10S，後臺60s
ContentProvider執行超時，比較少見

從發生的原因分：

主執行緒有耗時操作，如有複雜的layout佈局，IO操作等。
被Binder對端block
被子執行緒同步鎖block
Binder被佔滿導致主執行緒無法和SystemServer通訊
得不到系統資源（CPU/RAM/IO）

從程序的角度分：

問題出在當前程序:
主執行緒本身耗時, 或則主執行緒的訊息佇列存在耗時操作;
主執行緒被本程序的其他子執行緒所blocked;
問題出在遠端程序(一般是binder call或socket等通訊方式)

二、ANR的Log解讀

2.1、Log獲取

發生了ANR問題，通常會抓一份bugreport

adb bugreprotxxx

最為重要的是，生成的bugreport有anr的trace，如果要單獨拿出來也行

adb pull /data/anr/traces.txtxxx

一份完整的bugreport包含下面的資訊，對分析ANR問題很關鍵

Log名稱	作用	獲取命令
system.log	包含ANR發生時間點資訊、ANR發生前的CPU資訊,還包含大量系統服務輸出的資訊	adb logcat –b system
main.log	包含ANR發生前應用自身輸出的資訊,可供分析應用是否有異常;此外還包含輸出的GC資訊，可供分析記憶體回收的速度,判斷系統是否處於低記憶體或記憶體碎片化狀態	adb logcat –b main
event.log	包含AMS與WMS輸出的應用程式宣告週期資訊,可供分析視窗建立速度以及焦點轉換情況	adb logcat –b event
kernel.log	包含kernel打出的資訊,LowMemoryKiller殺程序、記憶體碎片化或記憶體不足,mmc驅動異常都可以在這裡找到。	無

那麼這些Log怎麼看呢？看下面案例一

2.1、案例一：sp耗時問題導致應用ANR

一般先搜尋ANR in 獲取最直觀的資訊，如下：

06-16 16:16:28.59018532073 E ActivityManager: ANR in com.android.camera (com.android.camera/.Camera)
06-16 16:16:28.59018532073 E ActivityManager: PID: 27661
06-16 16:16:28.59018532073 E ActivityManager: Reason: Input dispatching timed out (com.android.camera/com.android.camera.Camera, Waiting to send non-key event because the touched window has not finished processing certain input events that were delivered to it over 500.0ms ago.Wait queue length: 24.Wait queue head age: 5511.1ms.)
06-16 16:16:28.59018532073 E ActivityManager: Load: 16.25 / 29.48 / 38.33
06-16 16:16:28.59018532073 E ActivityManager: CPU usage from 0ms to 8058ms later:
06-16 16:16:28.59018532073 E ActivityManager:58% 291/mediaserver: 51% user + 6.7% kernel / faults: 2457 minor 4 major
06-16 16:16:28.59018532073 E ActivityManager:27% 317/mm-qcamera-daemon: 21% user + 5.8% kernel / faults: 15965 minor
06-16 16:16:28.59018532073 E ActivityManager:0.4% 288/debuggerd: 0% user + 0.3% kernel / faults: 21615 minor 87 major
06-16 16:16:28.59018532073 E ActivityManager:17% 27661/com.android.camera: 10% user + 6.8% kernel / faults: 2412 minor 34 major
06-16 16:16:28.59018532073 E ActivityManager:16% 1853/system_server: 10% user + 6.4% kernel / faults: 1754 minor 87 major
06-16 16:16:28.59018532073 E ActivityManager:10% 539/sensors.qcom: 7.8% user + 2.6% kernel / faults: 16 minor
06-16 16:16:28.59018532073 E ActivityManager:4.4% 277/surfaceflinger: 1.8% user + 2.6% kernel / faults: 14 minor
06-16 16:16:28.59018532073 E ActivityManager:4% 203/mmcqd/0: 0% user + 4% kernel
06-16 16:16:28.59018532073 E ActivityManager:2.6% 3510/com.android.phone: 1.9% user + 0.6% kernel / faults: 1148 minor 8 major
06-16 16:16:28.59018532073 E ActivityManager:2.1% 2902/com.android.systemui: 1.6% user + 0.4% kernel / faults: 1272 minor 32 major
06-16 16:16:28.59018532073 E ActivityManager:1.6% 3110/com.miui.whetstone: 1.6% user + 0% kernel / faults: 2614 minor 22 major
06-16 16:16:28.59018532073 E ActivityManager:0.8% 99/kswapd0: 0% user + 0.8% kernel
06-16 16:16:28.59018532073 E ActivityManager:1.4% 217/jbd2/mmcblk0p25: 0% user + 1.4% kernel
06-16 16:16:28.59018532073 E ActivityManager:1.4% 223/logd: 0.7% user + 0.7% kernel / faults: 4 minor
06-16 16:16:28.59018532073 E ActivityManager:0.9% 12808/kworker/0:1: 0% user + 0.9% kernel
06-16 16:16:28.59018532073 E ActivityManager:0.8% 35/kworker/u:2: 0% user + 0.8% kernel
06-16 16:16:28.59018532073 E ActivityManager:0% 3222/com.miui.sysbase: 0% user + 0% kernel / faults: 1314 minor 12 major
06-16 16:16:28.59018532073 E ActivityManager:0.8% 3446/com.android.nfc: 0.4% user + 0.3% kernel / faults: 1223 minor 9 major
06-16 16:16:28.59018532073 E ActivityManager:0.7% 10866/kworker/u:1: 0% user + 0.7% kernel
06-16 16:16:28.59018532073 E ActivityManager:0.6% 642/mdss_fb0: 0% user + 0.6% kernel
06-16 16:16:28.59018532073 E ActivityManager:0.6% 29336/kworker/u:7: 0% user + 0.6% kernel
06-16 16:16:28.59018532073 E ActivityManager:0.4% 6/kworker/u:0: 0% user + 0.4% kernel
06-16 16:16:28.59018532073 E ActivityManager:0.4% 22924/kworker/u:6: 0% user + 0.4% kernel
06-16 16:16:28.59018532073 E ActivityManager:0.3% 4421/mpdecision: 0% user + 0.3% kernel
06-16 16:16:28.59018532073 E ActivityManager:0.2% 276/servicemanager: 0.1% user + 0.1% kernel
06-16 16:16:28.59018532073 E ActivityManager:0.2% 289/rild: 0.2% user + 0% kernel / faults: 20 minor
06-16 16:16:28.59018532073 E ActivityManager:0.1% 4161/mcd: 0% user + 0% kernel / faults: 9 minor 1 major
06-16 16:16:28.59018532073 E ActivityManager:0.1% 3/ksoftirqd/0: 0% user + 0.1% kernel
06-16 16:16:28.59018532073 E ActivityManager:0.1% 5/kworker/0:0H: 0% user + 0.1% kernel
06-16 16:16:28.59018532073 E ActivityManager:0.1% 7/kworker/u:0H: 0% user + 0.1% kernel
06-16 16:16:28.59018532073 E ActivityManager:0% 215/flush-179:0: 0% user + 0% kernel
06-16 16:16:28.59018532073 E ActivityManager:0.1% 321/displayfeature: 0.1% user + 0% kernel
06-16 16:16:28.59018532073 E ActivityManager:0.1% 368/irq/33-cpubw_hw: 0% user + 0.1% kernel
06-16 16:16:28.59018532073 E ActivityManager:0.1% 403/qmuxd: 0% user + 0.1% kernel / faults: 60 minor
06-16 16:16:28.59018532073 E ActivityManager:0% 3491/com.xiaomi.finddevice: 0% user + 0% kernel / faults: 706 minor
06-16 16:16:28.59018532073 E ActivityManager:0.1% 29330/ksoftirqd/1: 0% user + 0.1% kernel
06-16 16:16:28.59018532073 E ActivityManager: 96% TOTAL: 56% user + 29% kernel + 6.3% iowait + 4.1% softirq

遇到ANR問題，擺在我們面前的trace是不是第一案發現場，如果ANR發生的輸出的資訊很多，當時的CPU和I/O資源比較緊張，那麼這段日誌輸出的時間點可能會延遲10秒到20秒都有可能，所以我們有時候需要提高警惕，現在舉例逐行解讀一下：

06-16 16:16:28.59018532073 E ActivityManager: ANR in com.android.camera (com.android.camera/.Camera)

這一行得知ANR發生的時間是06-16 16:16:28.590，發生的程序是com.android.camera ，具體在com.android.camera/.Camera，其中1853是systemserver的pid，2073是ActivityManager執行緒的pid，ActivityManager是一個系統執行緒。其實在Events log中也有對應的資訊，搜尋關鍵字am_anr

06-16 16:16:20.53618532073 I am_anr: [0,27661,com.android.camera,952745541,Input dispatching timed out (com.android.camera/com.android.camera.Camera, Waiting to send non-key event because the touched window has not finished processing certain input events that were delivered to it over 500.0ms ago.Wait queue length: 24.Wait queue head age: 5511.1ms.)]

由此同樣可以確定ANR的時間點，型別，程序pid，程序名稱等，繼續看下一行

06-16 16:16:28.59018532073 E ActivityManager: PID: 27661

這一行得知ANR程序的pid是27661，特殊情況，如果pid為0，說明在發生ANR之前，這個程序就被LowMemoryKiller殺死了或者出現了Crash，這種情況下，是無法接收到系統的廣播或者按鍵訊息的，故出現ANR

06-16 16:16:28.59018532073 E ActivityManager: Reason: Input dispatching timed out (com.android.camera/com.android.camera.Camera, Waiting to send non-key event because the touched window has not finished processing certain input events that were delivered to it over 500.0ms ago.Wait queue length: 24.Wait queue head age: 5511.1ms.)

這一行得知ANR發生的原因是Input dispatching timed out

06-16 16:16:28.59018532073 E ActivityManager: Load: 16.25 / 29.48 / 38.33

這行得知Cpu的負載，在Linux作業系統上，輸入uptime也能得到一段時間的負載。

wangjing@wangjing-OptiPlex-7050:~$ uptime
20:09:54 up 71 days, 10:48,1 user,load average: 0.99, 0.78, 0.86

那麼負載是什麼意思呢？Load後面的三個數字的意思分別是1分鐘、5分鐘、15分鐘內系統的平均負荷。當CPU完全空閒的時候，平均負荷為0；當CPU工作量飽和的時候，平均負荷為1，通過Load可以判斷系統負荷是否過重。有一個形象的比喻：個CPU想象成一座大橋，橋上只有一根車道，所有車輛都必須從這根車道上通過，系統負荷為0，意味著大橋上一輛車也沒有，系統負荷為0.5，意味著大橋一半的路段有車，系統負荷為1.0，意味著大橋的所有路段都有車，也就是說大橋已經"滿"了，系統負荷為2.0，意味著車輛太多了，大橋已經被佔滿了（100%），後面等著上橋的車輛還有一倍。大橋的通行能力，就是CPU的最大工作量；橋樑上的車輛，就是一個個等待CPU處理的程序（process）。

經驗法則是這樣的：

當系統負荷持續大於0.7，你必須開始調查了，問題出在哪裡，防止情況惡化。

當系統負荷持續大於1.0，你必須動手尋找解決辦法，把這個值降下來。

當系統負荷達到5.0，就表明你的系統有很嚴重的問題

而我們現在的手機是多核CPU架構，八核的多的是，意味著Cpu處理的能力就乘以了８，每個核執行的時間可以從下面的檔案中得到，/sys/devices/system/cpu/cpu%d/cpufreq/stats/time_in_state 中讀取的，%d代表是CPU的核。檔案中記錄了 CPU 從開機到讀取檔案時，在各個頻率下的執行時間，單位：10 mS。

使用adb shell cat /sys/devices/system/cpu/cpu1/cpufreq/stats/time_in_state檢視
頻度時間
652800 1813593
1036800 46484
1401600 521974
1689600 2956667
1843200 83065
1958400 53516
2016000 251693

關於負荷詳細的可以看ofollow,noindex">理解Linux系統負荷，不過多擴充套件。

06-16 16:16:28.59018532073 E ActivityManager: CPU usage from 0ms to 8058ms later:
06-16 16:16:28.59018532073 E ActivityManager:58% 291/mediaserver: 51% user + 6.7% kernel / faults: 2457 minor 4 major
06-16 16:16:28.59018532073 E ActivityManager:27% 317/mm-qcamera-daemon: 21% user + 5.8% kernel / faults: 15965 minor
06-16 16:16:28.59018532073 E ActivityManager:0.4% 288/debuggerd: 0% user + 0.3% kernel / faults: 21615 minor 87 major
06-16 16:16:28.59018532073 E ActivityManager:17% 27661/com.android.camera: 10% user + 6.8% kernel / faults: 2412 minor 34 major
....
06-16 16:16:28.59018532073 E ActivityManager: 96% TOTAL: 56% user + 29% kernel + 6.3% iowait + 4.1% softirq
.....

這一段日誌可以得到ANR發生的時候，Top程序的Cpu佔用情況，user代表是使用者空間，kernel是核心空間，一般的有如下的規律。

kswapd0 cpu佔用率偏高，系統整體執行會緩慢，從而引起各種ANR。把問題轉給"記憶體優化"，請他們進行優化。
logdCPU佔用率偏高，也會引起系統卡頓和ANR，因為各個程序輸出LOG的操作被阻塞從而執行的極為緩慢。
Vold佔用CPU過高，會引起系統卡頓和ANR，請負責儲存的同學先調查
qcom.sensor CPU佔用率過高，會引起卡頓，請系統同學調查
應用自身CPU佔用率較高，高概率應用自身問題
系統CPU佔用率不高，但主執行緒在等待一個鎖，高概率應用自身問題
應用處於D狀態，發生ANR，如果最後的操作是refriger，那麼是應用被凍結了，正常情況下是功耗優化引起的。

好了，通過上面的日誌我們得到了ANR的基本資訊，要得到阻塞的地方，還要靠trace檔案。一般都在anr目錄下。在這個trace檔案中搜索主執行緒的堆疊，如下：

----- pid 27661 at 2017-06-16 16:16:20 -----
Cmd line: com.android.camera
"main" prio=5 tid=1 Waiting
 | group="main" sCount=1 dsCount=0 obj=0x75a4b5c8 self=0xb4cf6500
 | sysTid=27661 nice=-10 cgrp=default sched=0/0 handle=0xb6f6cb34
 | state=S schedstat=( 11242036155 8689191757 38520 ) utm=895 stm=229 core=0 HZ=100
 | stack=0xbe4ea000-0xbe4ec000 stackSize=8MB
 | held mutexes=
 at java.lang.Object.wait!(Native method)
 - waiting on <0x09e6a059> (a java.lang.Object)
 at java.lang.Thread.parkFor$(Thread.java:1220)
 - locked <0x09e6a059> (a java.lang.Object)
 at sun.misc.Unsafe.park(Unsafe.java:299)
 at java.util.concurrent.locks.LockSupport.park(LockSupport.java:158)
 at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:810)
 at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:970)
 at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1278)
 at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:203)
 at android.app.SharedPreferencesImpl$EditorImpl$1.run(SharedPreferencesImpl.java:366)
 at android.app.QueuedWork.waitToFinish(QueuedWork.java:88)
 at android.app.ActivityThread.handleStopActivity(ActivityThread.java:3605)
 at android.app.ActivityThread.access$1300(ActivityThread.java:153)
 at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1399)
 at android.os.Handler.dispatchMessage(Handler.java:102)
 at android.os.Looper.loop(Looper.java:154)
 at android.app.ActivityThread.main(ActivityThread.java:5528)
 at java.lang.reflect.Method.invoke!(Native method)
 at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:740)
 at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:630)

解讀一下部分欄位的含義

欄位	含義
tid=1	執行緒號
sysTid=27661	主執行緒的執行緒號和程序號相同
Waiting	執行緒狀態，其中state也是執行緒狀態，如果state=D代表底層被blocked了。
nice	nice值越小，則優先順序越高。因為是主執行緒此處nice=-10, 可以看到優先順序很高了
schedstat	括號中的3個數字，依次是Running, Runable, Switch，Running時間。Running時間：CPU執行的時間，單位ns。 Runable時間：RQ佇列的等待時間，單位ns。Switch次數：CPU排程切換次數
utm	該執行緒在使用者態所執行的時間，單位是jiffies
stm	該執行緒在核心態所執行的時間，單位是jiffies
sCount	此執行緒被掛起的次數
dsCount	執行緒被偵錯程式掛起的次數，當一個程序被除錯後，sCount會重置為0，除錯完畢後sCount會根據是否被正常掛起增長，但是dsCount不會被重置為0，所以dsCount也可以用來判斷這個執行緒是否被除錯過
self	執行緒本身的地址

在說一下執行緒的狀態

狀態	值	說明
THREAD_ZOMBIE	0	TERMINATED
THREAD_RUNNING	1	RUNNABLE or running now
THREAD_TIMED_WAIT	2	TIMED_WAITING in Object.wait()
THREAD_MONITOR	3	BLOCKED on a monitor
THREAD_INITIALIZING	5	allocated not yet running
THREAD_STARTING	6	started not yet on thread list
THREAD_NATIVE	7	off in a JNI native method
THREAD_VMWAIT	8	waiting on a VM resource
THREAD_SUSPENDED	9	suspended usually by GC or debugger

那麼這個問題怎麼搞呢，通過上面的基礎介紹與trace檔案，我們知道，blocked點是

at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:203)
 at android.app.SharedPreferencesImpl$EditorImpl$1.run(SharedPreferencesImpl.java:366)
 at android.app.QueuedWork.waitToFinish(QueuedWork.java:88)
 at android.app.ActivityThread.handleStopActivity(ActivityThread.java:3605)
 at android.app.ActivityThread.access$1300(ActivityThread.java:153)

先來看QueuedWork.waitToFinish

77/**
78* Finishes or waits for async operations to complete.
79* (e.g. SharedPreferences$Editor#startCommit writes)
80*
81* Is called from the Activity base class's onPause(), after
82* BroadcastReceiver's onReceive, after Service command handling,
83* etc.(so async work is never lost)
84*/
85public static void waitToFinish() {
86Runnable toFinish;
　　　　　//等待所有等待完成的任務完成
87while ((toFinish = sPendingWorkFinishers.poll()) != null) {
88toFinish.run();
89}
90}

QueuedWork.waitToFinish會在Activity的onPause或者BroadcastReceiver的onReceive之後被呼叫，目的是確保非同步任務執行完成．在waitToFinish中遍歷sPendingWorkFinishers所有等待完成的任務，並等待他們的完成。在來看SharedPreferencesImpl.apply，這個方法裡面會將等待寫入到檔案系統的任務放到QueuedWork的等待完成佇列裡

361public void apply() {
362final MemoryCommitResult mcr = commitToMemory();
363final Runnable awaitCommit = new Runnable() {
364public void run() {
365try {
366mcr.writtenToDiskLatch.await();
367} catch (InterruptedException ignored) {
368}
369}
370};
371
　　　　　//將等待寫入到檔案系統的任務放到QueuedWork的等待佇列中
372QueuedWork.add(awaitCommit);
373... ... ... ... ... ...
388}

雖然apply方法本身可以很快返回，但是當Activity的onPause被呼叫時，會等待寫入到檔案系統的任務完成．也就是說，雖然apply本身不會阻塞呼叫執行緒，但是會將等待時間轉嫁到主執行緒．因此，如果寫入任務執行比較慢，activity, service, broadcast在生命週期結束時, sp操作沒有完成,就會阻塞主執行緒造成ANR。分析到這裡，明顯是個系統問題了，而App也是無能為力，好在小米手機上已經緩解了這個問題，方案不透露了。一般的看trace有如下規律：

發生ANR時，trace中找不到相應程序，檢查一下Android Runtime是否因為應用的崩潰給ShutDown了，如果ShutDown了，此時要去查ShutDown的原因。
應用發生ANR，如果主執行緒正在執行getContentProvider，那麼它正在請求另一個應用的ContentProvider，此時要查一下目標ContentProvider的宿主程序，看看正在做什麼
主執行緒執行資料庫操作或網路請求，應該是應用自身問題
主執行緒等待其他執行緒持有的鎖，而目標執行緒執行資料庫操作或網路請求，那麼是應用自身問題。

這裡只是先搞一個案例熟悉一下ANR分析基本流程。到這裡總結一下上面的套路：

抓取bugreport，搜尋ANR in，檢視發生的時間和程序
根據程序尋找主執行緒的trace，發現被blocked的地方
結合原始碼進行分析解決
當然通過這兩個步驟就定位到ANR發生的原因，說明我們的運氣比較好，然而大多數時候不是這個樣子的。

上面我們分析了一個系統問題導致的ANR，這裡你可能會想，我的app什麼活都沒有幹，竟然發生ANR了，以後可以把鍋直接甩給系統了，非也，具體問題還是要具體分析，懷疑係統，我們要有證據，證據從哪裡來，還是從Log裡面來，繼續看第三節，系統耗時分析方案

三、系統耗時分析方案

系統做了一些耗時分析的操作，在一些手機廠商中，Log裡面還有其他的加強，這裡列舉比較通用的一些

1.binder_sample

A.功能說明: 監控每個程序的主執行緒的binder transaction的耗時情況, 當超過閾值時,則輸出相應的目標呼叫資訊，預設1000ms開啟。
B.log格式: 52004 binder_sample (descriptor|3),(method_num|1|5),(time|1|3),(blocking_package|3),(sample_percent|1|6)
C.log例項:

2754 2754 I binder_sample: [android.app.IActivityManager,35,2900,android.process.media,5]

從上面的log中可以得出

1.主執行緒2754;

2.執行android.app.IActivityManager介面

所對應方法code =35(即STOP_SERVICE_TRANSACTION),
所花費時間為2900ms.
該block所在package為 android.process.media，最後一個引數是sample比例(沒有太大價值)

2、dvm_lock_sample

A.功能說明: 當某個執行緒等待lock的時間blocked超過閾值,則輸出當前的持鎖狀態 ;
B.log格式: 20003 dvm_lock_sample (process|3),(main|1|5),(thread|3),(time|1|3),(file|3),(line|1|5),(ownerfile|3),(ownerline|1|5),(sample_percent|1|6)
C.log例項:

dvm_lock_sample: [system_server,1,Binder_9,1500,ActivityManagerService.java,6403,-,1448,0]

意思是system_server: Binder_9,執行到ActivityManagerService.java的6403行程式碼,一直在等待AMS鎖, 而該鎖所同一檔案的1448行程式碼所持有, 從而導致Binder_9執行緒被阻塞1500ms.

3、 binder starved

A.功能說明:當system_server等程序的執行緒池使用完, 無空閒執行緒時, 則binder通訊都處於飢餓狀態, 則飢餓狀態超過一定閾值則輸出資訊;
B.雲控引數: persist.sys.binder.starvation(預設值16ms)
C.log例項:

1232 1232 "binder thread pool (16 threads) starved for 100 ms"

D.log解析:system_server程序的執行緒池已滿的持續長達100ms

一般有了這些資訊之後，可以輔助我們確定問題原因歸屬是系統原因還是App原因，看下面的案例二：

4、案例二：瘋狂Binder Call導致應用ANR

搜尋ANR in

08-28 18:54:00.110100018251848 E ActivityManager: ANR in com.jeejen.family (com.jeejen.family/com.jeejen.home.launcher.ShoppingActivity)
08-28 18:54:00.110100018251848 E ActivityManager: PID: 20576
08-28 18:54:00.110100018251848 E ActivityManager: Reason: Input dispatching timed out (com.jeejen.family/com.jeejen.home.launcher.WelcomeActivity, Waiting to send non-key event because the touched window has not finished processing certain input events that were delivered to it over 500.0ms ago.Wait queue length: 2.Wait queue head age: 10064.4ms.)
08-28 18:54:00.110100018251848 E ActivityManager: Parent: com.jeejen.family/com.jeejen.home.launcher.WelcomeActivity
08-28 18:54:00.110100018251848 E ActivityManager: Load: 1.25 / 1.1 / 1.37
08-28 18:54:00.110100018251848 E ActivityManager: CPU usage from 5166ms to 0ms ago (2018-08-28 18:53:51.270 to 2018-08-28 18:53:56.436):
08-28 18:54:00.110100018251848 E ActivityManager:7.7% 1825/system_server: 5.6% user + 2.1% kernel / faults: 1329 minor
08-28 18:54:00.110100018251848 E ActivityManager:3.6% 20683/com.jeejen.family:pushcenter_pushservice: 3% user + 0.5% kernel / faults: 542 minor
08-28 18:54:00.110100018251848 E ActivityManager:2.7% 4114/cnss_diag: 1.9% user + 0.7% kernel
08-28 18:54:00.110100018251848 E ActivityManager:2.1% 422/kworker/u16:7: 0% user + 2.1% kernel
08-28 18:54:00.110100018251848 E ActivityManager:1.9% 20830/com.jeejen.family:store: 1.3% user + 0.5% kernel / faults: 199 minor
08-28 18:54:00.110100018251848 E ActivityManager:1.7% 20608/com.jeejen.family:pushcenter: 1.1% user + 0.5% kernel
08-28 18:54:00.110100018251848 E ActivityManager:1.5% 725/[email protected]: 0.7% user + 0.7% kernel / faults: 1 minor
08-28 18:54:00.110100018251848 E ActivityManager:0.9% 3538/com.android.systemui: 0.7% user + 0.1% kernel / faults: 11 minor
08-28 18:54:00.110100018251848 E ActivityManager:0.5% 241/crtc_commit:111: 0% user + 0.5% kernel
08-28 18:54:00.110100018251848 E ActivityManager:0.5% 419/kworker/u16:4: 0% user + 0.5% kernel
08-28 18:54:00.110100018251848 E ActivityManager:0.5% 786/surfaceflinger: 0.5% user + 0% kernel
08-28 18:54:00.110100018251848 E ActivityManager:0.3% 185/IPCRTR_dsps_sme: 0% user + 0.3% kernel
08-28 18:54:00.110100018251848 E ActivityManager:0.3% 730/[email protected]: 0.1% user + 0.1% kernel / faults: 28 minor
08-28 18:54:00.110100018251848 E ActivityManager:0.3% 820/dsps_IPCRTR: 0% user + 0.3% kernel
08-28 18:54:00.110100018251848 E ActivityManager:0.3% 1147/msm_irqbalance: 0.1% user + 0.1% kernel
08-28 18:54:00.110100018251848 E ActivityManager:0.3% 4113/sugov:0: 0% user + 0.3% kernel
08-28 18:54:00.110100018251848 E ActivityManager:0.1% 10/rcuop/0: 0% user + 0.1% kernel
08-28 18:54:00.110100018251848 E ActivityManager:0.1% 18/ksoftirqd/1: 0% user + 0.1% kernel
08-28 18:54:00.110100018251848 E ActivityManager:0% 34/ksoftirqd/3: 0% user + 0% kernel
08-28 18:54:00.110100018251848 E ActivityManager:0% 53/rcuop/5: 0% user + 0% kernel
08-28 18:54:00.110100018251848 E ActivityManager:0% 61/rcuop/6: 0% user + 0% kernel
08-28 18:54:00.110100018251848 E ActivityManager:0.1% 242/crtc_event:111: 0% user + 0.1% kernel
08-28 18:54:00.110100018251848 E ActivityManager:0.1% 538/ueventd: 0.1% user + 0% kernel
08-28 18:54:00.110100018251848 E ActivityManager:0.1% 577/jbd2/sda22-8: 0% user + 0.1% kernel
08-28 18:54:00.110100018251848 E ActivityManager:0.1% 591/logd: 0.1% user + 0% kernel
08-28 18:54:00.110100018251848 E ActivityManager:0.1% 719/[email protected]: 0.1% user + 0% kernel
08-28 18:54:00.110100018251848 E ActivityManager:0.1% 928/thermal-engine: 0% user + 0.1% kernel
08-28 18:54:00.110100018251848 E ActivityManager:0.1% 3490/cds_mc_thread: 0% user + 0.1% kernel
08-28 18:54:00.110100018251848 E ActivityManager:0.1% 3491/cds_ol_rx_threa: 0% user + 0.1% kernel
08-28 18:54:00.110100018251848 E ActivityManager:0.1% 3680/com.android.phone: 0% user + 0.1% kernel / faults: 16 minor
08-28 18:54:00.110100018251848 E ActivityManager:0.1% 4248/com.miui.daemon: 0.1% user + 0% kernel / faults: 4 minor
08-28 18:54:00.110100018251848 E ActivityManager:0.1% 4488/com.miui.powerkeeper: 0.1% user + 0% kernel / faults: 10 minor
08-28 18:54:00.110100018251848 E ActivityManager:0.1% 5545/com.lbe.security.miui: 0% user + 0.1% kernel / faults: 6 minor
08-28 18:54:00.110100018251848 E ActivityManager:0.1% 6490/kworker/u17:2: 0% user + 0.1% kernel
08-28 18:54:00.110100018251848 E ActivityManager:0.1% 7535/kworker/u16:15: 0% user + 0.1% kernel
08-28 18:54:00.110100018251848 E ActivityManager:0% 7723/kworker/3:5: 0% user + 0% kernel
08-28 18:54:00.110100018251848 E ActivityManager:0.1% 15111/kworker/1:0: 0% user + 0.1% kernel
08-28 18:54:00.110100018251848 E ActivityManager:0.1% 15138/kworker/3:0: 0% user + 0.1% kernel
08-28 18:54:00.110100018251848 E ActivityManager:0% 19857/kworker/0:3: 0% user + 0% kernel
08-28 18:54:00.110100018251848 E ActivityManager:0.1% 20492/kworker/5:3: 0% user + 0.1% kernel
08-28 18:54:00.110100018251848 E ActivityManager: 3.8% TOTAL: 2% user + 1.1% kernel + 0% iowait + 0.3% irq + 0.1% softirq

按照上面的套路看看，各方面比較正常，發生時間大概是08-28 18:54:00.110 ，在看主執行緒的trace。

----- pid 20576 at 2018-08-28 18:53:56 -----
Cmd line: com.jeejen.family
"main" prio=5 tid=1 Native
| group="main" sCount=1 dsCount=0 flags=1 obj=0x77ffca18 self=0xecfce000
| sysTid=20576 nice=-10 cgrp=default sched=0/0 handle=0xf0bf2494
| state=S schedstat=( 628294395 402363898 957 ) utm=42 stm=20 core=4 HZ=100
| stack=0xff5fe000-0xff600000 stackSize=8MB
| held mutexes=
kernel: (couldn't read /proc/self/task/20576/stack)
native: #00 pc 00053cfc /system/lib/libc.so (__ioctl+8)
native: #01 pc 00021cd3 /system/lib/libc.so (ioctl+30)
native: #02 pc 0003d3f5 /system/lib/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+204)
native: #03 pc 0003dde3 /system/lib/libbinder.so (android::IPCThreadState::waitForResponse(android::Parcel*, int*)+26)
native: #04 pc 0003713d /system/lib/libbinder.so (android::BpBinder::transact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+36)
native: #05 pc 000c3cf1 /system/lib/libandroid_runtime.so (android_os_BinderProxy_transact(_JNIEnv*, _jobject*, int, _jobject*, _jobject*, int)+200)
at android.os.BinderProxy.transactNative(Native method)
at android.os.BinderProxy.transact(Binder.java:1127)
at android.net.wifi.IWifiManager$Stub$Proxy.getConnectionInfo(IWifiManager.java:1441)
at android.net.wifi.WifiManager.getConnectionInfo(WifiManager.java:1778)
at org.chromium.net.NetworkChangeNotifierAutoDetect$WifiManagerDelegate.getWifiInfoLocked(NetworkChangeNotifierAutoDetect.java:28)
at org.chromium.net.NetworkChangeNotifierAutoDetect$WifiManagerDelegate.getWifiSsid(NetworkChangeNotifierAutoDetect.java:22)
- locked <0x0f4edae7> (a java.lang.Object)
at org.chromium.net.NetworkChangeNotifierAutoDetect.getCurrentNetworkState(NetworkChangeNotifierAutoDetect.java:67)
at org.chromium.net.NetworkChangeNotifierAutoDetect.<init>(NetworkChangeNotifierAutoDetect.java:21)
at org.chromium.net.NetworkChangeNotifier.setAutoDetectConnectivityStateInternal(NetworkChangeNotifier.java:61)

看樣子是binder call阻塞了，呼叫的介面是IWifiManager.getConnectionInfo()。因為是binder呼叫，檢視一下binder_sample。

08-28 18:54:01.384 10171 20576 20576 I binder_sample: [android.net.wifi.IWifiManager,24,16004,com.jeejen.family,100]
08-28 18:54:04.868 10171 20576 20576 I binder_sample: [android.net.wifi.IWifiManager,24,3479,com.jeejen.family,100]
08-28 18:56:12.712 10171 21885 21885 I binder_sample: [android.net.wifi.IWifiManager,24,8963,com.jeejen.family,100]

可以看到在ANR附近的時間，使用IWifiManager介面的binder呼叫確實耗時比較長，那麼這個是不是系統原因呢？那麼去看他的對端Sysytem的程式碼。

1763/**
1764* See {@link android.net.wifi.WifiManager#getConnectionInfo()}
1765* @return the Wi-Fi information, contained in {@link WifiInfo}.
1766*/
1767@Override
1768public WifiInfo getConnectionInfo() {
1769enforceAccessPermission();
1770mLog.trace("getConnectionInfo uid=%").c(Binder.getCallingUid()).flush();
1771/*
1772* Make sure we have the latest information, by sending
1773* a status request to the supplicant.
1774*/
1775return mWifiStateMachine.syncRequestConnectionInfo();
1776}

1521public WifiInfo syncRequestConnectionInfo() {
1522WifiInfo result = new WifiInfo(mWifiInfo);
1523return result;
1524}

getConnectionInfo直接通過wifiService呼叫wifiStateMachine中syncRequestConnectionInfo,這部分的實現不會阻塞住，難道Binder被沾滿了？從trace中並沒有看出這一點，那麼怎麼回事呢？我們嘗試復現這個問題，好在比較容易復現。

09-04 18:24:29.182 D/WifiStateMachine( 1312): syncRequestConnectionInfo/in SSID: MIOffice-5G, BSSID: 70:3a:0e:2c:bb:f1, MAC: 80:ad:16:4c:0b:fe, Supplicant state: COMPLETED, RSSI: -44, Link speed: 400Mbps, Frequency: 5180MHz, Net ID: 0, Metered hint: false, score: 60
09-04 18:24:29.182 D/WifiStateMachine( 1312): syncRequestConnectionInfo/out SSID: MIOffice-5G, BSSID: 70:3a:0e:2c:bb:f1, MAC: 80:ad:16:4c:0b:fe, Supplicant state: COMPLETED, RSSI: -44, Link speed: 400Mbps, Frequency: 5180MHz, Net ID: 0, Metered hint: false, score: 60

發現在主執行緒進行大量輸出上面的Log，極簡桌面在1分鐘內呼叫此介面160次，導致了SystemServer不能及時響應這個App，造成了App自己的ANR。像Binder call導致ANR的問題很常見，存在被blocked的風險，此刻可以嘗試放到非同步裡面執行，其次不要短時間的大量Binder呼叫，這樣行為輕則App自己有問題，重則系統發生Watchdog宕機重啟。

4、案例三：廣播超時導致App的ANR

繼續看一個案例三，按照上面的套路，首先在eventlog中檢視發生ANR的時間。

12-17 06:02:14.46315661583 I am_anr: [0,8769,com.android.updater,952680005,Broadcast of Intent { act=android.intent.action.BOOT_COMPLETED flg=0x9000010 cmp=com.android.updater/.BootCompletedReceiver (has extras) }]

發生ANR的時間是am_anr 時間點是12-17 06:02:14.463，繼續看Log

12-17 06:02:00.37015661583 W BroadcastQueue: Timeout of broadcast BroadcastRecord{21ef8c2 u0 android.intent.action.BOOT_COMPLETED} - receiver=android.os.BinderProxy@2a6c365, started 60006ms ago
12-17 06:02:00.37015661583 W BroadcastQueue: Receiver during timeout: ResolveInfo{5a8283a com.android.updater/.BootCompletedReceiver m=0x108000}
12-17 06:02:00.37015661583 I am_broadcast_discard_app: [0,35584194,android.intent.action.BOOT_COMPLETED,49,ResolveInfo{5a8283a com.android.updater/.BootCompletedReceiver m=0x108000}]

但是我們發現在12-17 06:02:00.370 已經發生ANR，說明eventlog中的時間是個大概值，可能由於系統資源比較緊張造成一定程度的滯後。由於是android.intent.action.BOOT_COMPLETED這個廣播接收出現的ANR，那麼我們順藤摸瓜。

12-17 06:01:00.38315663524 I ActivityManager: Start proc 8769:com.android.updater/9802 for broadcast com.android.updater/.BootCompletedReceiver caller=null

在12-17 06:01:00.383的時候啟動了廣播程序

12-17 06:01:36.72187698769 D BootCompletedReceiver: onReceive android.intent.action.BOOT_COMPLETED
12-17 06:02:14.725 8769 8769 D UpdateService: onCreate

在12-17 06:01:36.721的時候，客戶端BootCompletedReceiver onReceiver方法開始回撥，然後onReceive 啟動UpdateService，呼叫UpdateService.onCreate時間是12-17 06:02:14.725。根據上面的分析有兩個初步的疑問。

啟動廣播是在12-17 06:01:00.383，廣播的onReceiver方法開始回撥是在12-17 06:01:36.721，ANR的時間是在12-17 06:02:00.370 ，那麼為什麼啟動了36s後我才收到bootcompleted廣播，這本身就不正常吧，其次為什麼廣播啟動UpdateService耗時將近化了一分多鐘？分析到這裡App同學認為無法分析下去，八成是系統原因，從cpu的統計上來看，認為是某些程式佔用過高導致的，貼出下面的Log。

12-17 06:02:19.28615661583 E ActivityManager: ANR in com.android.updater
12-17 06:02:19.28615661583 E ActivityManager: PID: 8769
12-17 06:02:19.28615661583 E ActivityManager: Reason: Broadcast of Intent { act=android.intent.action.BOOT_COMPLETED flg=0x9000010 cmp=com.android.updater/.BootCompletedReceiver (has extras) }
12-17 06:02:19.28615661583 E ActivityManager: Load: 0.0 / 0.0 / 0.0
12-17 06:02:19.28615661583 E ActivityManager: CPU usage from 0ms to 18846ms later (2017-12-17 06:02:00.379 to 2017-12-17 06:02:19.224):
12-17 06:02:19.28615661583 E ActivityManager:195% 6142/com.immomo.momo: 195% user + 0% kernel
12-17 06:02:19.28615661583 E ActivityManager:2.3% 8170/com.tencent.mm: 2.3% user + 0% kernel / faults: 448 minor
12-17 06:02:19.28615661583 E ActivityManager:0.7% 1566/system_server: 0.4% user + 0.3% kernel / faults: 150 minor 1 major
12-17 06:02:19.28615661583 E ActivityManager:0.4% 90/kworker/u16:3: 0% user + 0.4% kernel
12-17 06:02:19.28615661583 E ActivityManager:0.3% 4704/com.tencent.mm:push: 0.1% user + 0.2% kernel / faults: 116 minor
12-17 06:02:19.28615661583 E ActivityManager:0.3% 8769/com.android.updater: 0.2% user + 0.1% kernel / faults: 1600 minor 2 major
12-17 06:02:19.28615661583 E ActivityManager:0.2% 4790/com.tencent.mm:patch: 0.2% user + 0% kernel / faults: 748 minor
12-17 06:02:19.28615661583 E ActivityManager:0.2% 329/mmc-cmdqd/0: 0% user + 0.2% kernel
12-17 06:02:19.28615661583 E ActivityManager:0.2% 5429/com.tencent.mm:push: 0% user + 0.1% kernel / faults: 17 minor
12-17 06:02:19.28615661583 E ActivityManager:0.2% 5435/com.tencent.mm:patch: 0.2% user + 0% kernel / faults: 82 minor
12-17 06:02:19.28615661583 E ActivityManager:0.2% 8712/com.tencent.mm:exdevice: 0.1% user + 0% kernel
12-17 06:02:19.28615661583 E ActivityManager:0.1% 432/logd: 0.1% user + 0% kernel / faults: 4 minor
12-17 06:02:19.28615661583 E ActivityManager:0.1% 844/msm_irqbalance: 0% user + 0.1% kernel / faults: 4 minor
12-17 06:02:19.28615661583 E ActivityManager:0.1% 7580/kworker/u16:2: 0% user + 0.1% kernel
12-17 06:02:19.28615661583 E ActivityManager:0.1% 7/rcu_preempt: 0% user + 0.1% kernel
12-17 06:02:19.28615661583 E ActivityManager:0.1% 1240/zygote: 0% user + 0.1% kernel / faults: 84 minor
12-17 06:02:19.28615661583 E ActivityManager:0% 3216/com.xiaomi.simactivate.service: 0% user + 0% kernel / faults: 5 minor
12-17 06:02:19.28615661583 E ActivityManager:0.1% 8645/kworker/7:0: 0% user + 0.1% kernel
12-17 06:02:19.28615661583 E ActivityManager:0.1% 8730/kworker/4:2: 0% user + 0.1% kernel
12-17 06:02:19.28615661583 E ActivityManager:0% 45/rcuop/4: 0% user + 0% kernel

然而cpu佔用195%並不算高，在多核中每個核最大佔用率都是100%（八核佔用率是800%），其次Load: 0.0 / 0.0 / 0.0，Load在15分鐘這段時間都是０，停止運轉了？貌似這個Log也不太正確。然而在小米手機上，ANR的監控會有加強的，輸出了下面的Log。

12-17 06:02:14.69387698769 W MIUI-BLOCK-MONITOR: The msg { when=-36s107ms what=113 obj=ReceiverData{intent=Intent { act=android.intent.action.BOOT_COMPLETED flg=0x9000010 cmp=com.android.updater/.BootCompletedReceiver (has extras) } packageName=com.android.updater resultCode=0 resultData=null resultExtras=null} target=android.app.ActivityThread$H planTime=1513461660613 dispatchTime=1513461696720 finishTime=0 } took 74080ms and took 37973ms after dispatch.

我們對每一個Message都額外記錄了它各個狀態的時間點，方便我們進行分析

when:訊息從應該被執行到發生anr的時間
planTime：訊息計劃被執行的時間點
dispatchTime：訊息真正被執行的時間點
finishTime：訊息完成時的時間點
計算訊息執行的時間為:-when-(dispatchTime-planTime)=0，那麼這意味著什麼呢？意味著113這個Message正要開始執行，還沒有開始執行就發生了ANR，在主執行緒的Looper訊息佇列中，等待了36秒。這份日誌中沒有主執行緒的trace，有也沒有作用，因為可以看到這個訊息還沒有執行呢？那麼這個36秒期間在做什麼呢？有比較多下面的Log。

12-17 06:01:29.334 8769 8769 W MIUI-BLOCK-MONITOR: The binder call took 3973ms.
12-17 06:01:29.334 8769 8769 W MIUI-BLOCK-MONITOR: java.lang.Throwable
12-17 06:01:29.334 8769 8769 W MIUI-BLOCK-MONITOR: at android.os.AnrMonitor.checkBinderCallTime(AnrMonitor.java:591)
12-17 06:01:29.334 8769 8769 W MIUI-BLOCK-MONITOR: at android.os.BinderProxy.transact(Binder.java:623)
12-17 06:01:29.334 8769 8769 W MIUI-BLOCK-MONITOR: at android.content.pm.IPackageManager$Stub$Proxy.getApplicationInfo(IPackageManager.java:2658)
12-17 06:01:29.334 8769 8769 W MIUI-BLOCK-MONITOR: at android.app.ApplicationPackageManager.getApplicationInfoAsUser(ApplicationPackageManager.java:340)
12-17 06:01:29.334 8769 8769 W MIUI-BLOCK-MONITOR: at android.app.ApplicationPackageManager.getApplicationInfo(ApplicationPackageManager.java:333)
12-17 06:01:29.334 8769 8769 W MIUI-BLOCK-MONITOR: at miui.core.ManifestParser.create(SourceFile:64)
12-17 06:01:29.334 8769 8769 W MIUI-BLOCK-MONITOR: at miui.core.SdkManager.start(SourceFile:186)
12-17 06:01:29.334 8769 8769 W MIUI-BLOCK-MONITOR: at java.lang.reflect.Method.invoke(Native Method)
12-17 06:01:29.334 8769 8769 W MIUI-BLOCK-MONITOR: at miui.external.a.abx()
12-17 06:01:29.334 8769 8769 W MIUI-BLOCK-MONITOR: at miui.external.a.attachBaseContext()
12-17 06:01:29.334 8769 8769 W MIUI-BLOCK-MONITOR: at android.app.Application.attach(Application.java:193)
12-17 06:01:29.334 8769 8769 W MIUI-BLOCK-MONITOR: at android.app.Instrumentation.newApplication(Instrumentation.java:1009)
12-17 06:01:29.334 8769 8769 W MIUI-BLOCK-MONITOR: at android.app.Instrumentation.newApplication(Instrumentation.java:993)
12-17 06:01:29.334 8769 8769 W MIUI-BLOCK-MONITOR: at android.app.LoadedApk.makeApplication(LoadedApk.java:800)
12-17 06:01:29.334 8769 8769 W MIUI-BLOCK-MONITOR: at android.app.ActivityThread.handleBindApplication(ActivityThread.java:5471)
12-17 06:01:29.334 8769 8769 W MIUI-BLOCK-MONITOR: at android.app.ActivityThread.-wrap2(ActivityThread.java)
12-17 06:01:29.334 8769 8769 W MIUI-BLOCK-MONITOR: at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1584)
12-17 06:01:29.334 8769 8769 W MIUI-BLOCK-MONITOR: at android.os.Handler.dispatchMessage(Handler.java:102)
12-17 06:01:29.334 8769 8769 W MIUI-BLOCK-MONITOR: at android.os.Looper.loop(Looper.java:163)
12-17 06:01:29.334 8769 8769 W MIUI-BLOCK-MONITOR: at android.app.ActivityThread.main(ActivityThread.java:6221)
12-17 06:01:29.334 8769 8769 W MIUI-BLOCK-MONITOR: at java.lang.reflect.Method.invoke(Native Method)
12-17 06:01:29.334 8769 8769 W MIUI-BLOCK-MONITOR: at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:904)
12-17 06:01:29.334 8769 8769 W MIUI-BLOCK-MONITOR: at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:794)

36秒期間都在做bindApplication操作，這種情況下極有可能是系統狀態此時並不樂觀的原因，其次通過上面的分析也可以看到BootCompletedReceiver的onReceiver是在主執行緒處理的，啟動Service也花費了很多的時間，我們也可以考慮在註冊Receiver的時候，可以指定Handler，讓onReceiver執行在子執行緒中(怎麼做，可以看原始碼哦)

本篇文章主要梳理三個小案例，總結ANR問題的分析套路，最後在次總結分析步驟：

抓取bugreport，搜尋ANR in，檢視發生的時間和程序，Cpu的負載有沒有問題
根據程序尋找主執行緒的trace，發現被blocked的地方，如果是Binder call則，進一步確認下對端的情況；如果是耗時操作，直接修改成非同步，懷疑係統執行慢可以看看binder_sample，dvm_lock等資訊，其次gc多不多，lmk殺程序是不是很頻繁，都可以看出系統的健康狀態。
結合原始碼進行分析解決

本文只是記錄一些案例和分析手段，指導思想就是找出主執行緒在過去一段時間內被block的原因。總體上比較容易掌握，還沒有到深入具體的原理，比如ANR的dump原理，系統怎麼判定ANR，ANR的無效trace怎麼辦等等比較深入的問題。因為ANR問題有時候確實比較頭疼，trace可能並不是第一案發現場，對於一些手機廠商，對ANR都做了加強的監控，可以輸出來更多的資訊，提高了ANR問題的分析效率，另外也可以看出來對於ANR問題做Room的同學會由於工作中閱讀原始碼的經驗，會更加得心應手一些。