ANR問題分析實例

ANR監測機制包含三種：

• Service ANR，前臺進程中Service生命週期不能超過20秒，後臺進程中Service的生命週期不能超過200秒。 在啓動Service時，拋出定時消息SERVICE_TIMEOUT_MSG或SERVICE_BACKGOURND_TIMEOUT_MSG，若是定時消息響應了，則說明發生了ANR

• Broadcast ANR，前臺的「串行廣播消息」必須在10秒內處理完畢，後臺的「串行廣播消息」必須在60秒處理完畢， 每派發串行廣播消息到一個接收器時，都會拋出一個定時消息BROADCAST_TIMEOUT_MSG，若是定時消息響應，則判斷是否廣播消息處理超時，超時就說明發生了ANR

• Input ANR，輸入事件必須在5秒內處理完畢。在派發一個輸入事件時，會判斷當前輸入事件是否須要等待，若是須要等待，則判斷是否等待已經超時，超時就說明發生了ANR

ANR監測機制其實是對應用程序主線程的要求，要求主線成必須在限定的時間內，完成對幾種操做的響應;不然，就能夠認爲應用程序主線程失去響應能力。

從ANR的三種監測機制中，咱們看到不一樣超時機制的設計：

Service和Broadcast都是由AMS調度，利用Handler和Looper，設計了一個TIMEOUT消息交由AMS線程來處理，整個超時機制的實現都是在Java層； InputEvent由InputDispatcher調度，待處理的輸入事件都會進入隊列中等待，設計了一個等待超時的判斷，超時機制的實如今Native層。

2.2 ANR的報告機制

不管哪一種類型的ANR發生之後，最終都會調用 AMS.appNotResponding() 方法，所謂「異曲同工」。這個方法的職能就是向用戶或開發者報告ANR發生了。 最終的表現形式是：彈出一個對話框，告訴用戶當前某個程序無響應;輸入一大堆與ANR相關的日誌，便於開發者解決問題。

最終形式咱們見過不少，但輸出日誌的原理是什麼，未必全部人都瞭解，下面咱們就來認識一下是如何輸出ANR日誌的。

final void appNotResponding(ProcessRecord app, ActivityRecord activity, ActivityRecord parent, boolean aboveSystem, final String annotation) { // app: 當前發生ANR的進程 // activity: 發生ANR的界面 // parent: 發生ANR的界面的上一級界面 // aboveSystem: // annotation: 發生ANR的緣由 ... // 1. 更新CPU使用信息。ANR的第一次CPU信息採樣 updateCpuStatsNow(); ... // 2. 填充firstPids和lastPids數組。從最近運行進程(Last Recently Used)中挑選： // firstPids用於保存ANR進程及其父進程，system_server進程和persistent的進程(譬如Phone進程) // lastPids用於保存除firstPids外的其餘進程 firstPids.add(app.pid); int parentPid = app.pid; if (parent != null && parent.app != null && parent.app.pid > 0) parentPid = parent.app.pid; if (parentPid != app.pid) firstPids.add(parentPid); if (MY_PID != app.pid && MY_PID != parentPid) firstPids.add(MY_PID); for (int i = mLruProcesses.size() - 1; i >= 0; i--) { ProcessRecord r = mLruProcesses.get(i); if (r != null && r.thread != null) { int pid = r.pid; if (pid > 0 && pid != app.pid && pid != parentPid && pid != MY_PID) { if (r.persistent) { firstPids.add(pid); } else { lastPids.put(pid, Boolean.TRUE); } } } } ... // 3. 打印調用棧 File tracesFile = dumpStackTraces(true, firstPids, processCpuTracker, lastPids, NATIVE_STACKS_OF_INTEREST); ... // 4. 更新CPU使用信息。ANR的第二次CPU使用信息採樣 updateCpuStatsNow(); ... // 5. 顯示ANR對話框 Message msg = Message.obtain(); HashMap<String, Object> map = new HashMap<String, Object>(); msg.what = SHOW_NOT_RESPONDING_MSG; ... mHandler.sendMessage(msg); }

該方法的主體邏輯能夠分紅五個部分來看：

1. 更新CPU的統計信息。這是發生ANR時，第一次CPU使用信息的採樣，採樣數據會保存在mProcessStats這個變量中

2. 填充firstPids和lastPids數組。當前發生ANR的應用會首先被添加到firstPids中，這樣打印函數棧的時候，當前進程老是在trace文件的最前面

3. 打印函數調用棧(StackTrace)。具體實現由dumpStackTraces()函數完成

4. 更新CPU的統計信息。這是發生ANR時，第二次CPU使用信息的採樣，兩次採樣的數據分別對應ANR發生先後的CPU使用狀況

5. 顯示ANR對話框。拋出SHOW_NOT_RESPONDING_MSG消息，AMS.MainHandler會處理這條消息，顯示AppNotRespondingDialog

固然，除了主體邏輯，發生ANR時還會輸出各類類別的日誌：

• event log，經過檢索」am_anr」關鍵字，能夠找到發生ANR的應用
• main log，經過檢索」ANR in 「關鍵字，能夠找到ANR的信息，日誌的上下文會包含CPU的使用狀況
• dropbox，經過檢索」anr」類型，能夠找到ANR的信息
• traces, 發生ANR時，各進程的函數調用棧信息

咱們分析ANR問題，每每是從main log中的CPU使用狀況和traces中的函數調用棧開始。因此，更新CPU的使用信息updateCpuStatsNow()方法和打印函數棧dumpStackTraces()方法，是系統報告ANR問題關鍵所在。

2.2.1 CPU的使用狀況

AMS.updateCpuStatsNow()方法的實現不在這裏列出了，只須要知道更新CPU使用信息的間隔最小是5秒，即若是5秒內連續調用updateCpuStatsNow()方法，實際上是沒有更新CPU使用信息的。

CPU使用信息由ProcessCpuTracker這個類維護， 每次調用ProcessCpuTracker.update()方法，就會讀取設備節點 /proc 下的文件，來更新CPU使用信息，具體有如下幾個維度：

• CPU的使用時間: 讀取 /proc/stat

  • user： 用戶進程的CPU使用時間
  • nice： 下降過優先級進程的CPU使用時間。Linux進程都有優先級，這個優先級能夠進行動態調整，譬如進程初始優先級的值設爲10,運行時下降爲8,那麼，修正值-2就定義爲nice。 Android將user和nice這兩個時間歸類成user
  • sys： 內核進程的CPU使用時間
  • idle： CPU空閒的時間
  • wait： CPU等待IO的時間
  • hw irq： 硬件中斷的時間。若是外設（譬如硬盤）出現故障，須要經過硬件終端通知CPU保存現場，發生上下文切換的時間就是CPU的硬件中斷時間
  • sw irg： 軟件中斷的時間。同硬件中斷同樣，若是軟件要求CPU中斷，則上下文切換的時間就是CPU的軟件中斷時間

• CPU負載: 讀取 /proc/loadavg, 統計最近1分鐘，5分鐘，15分鐘內，CPU的平均活動進程數。 CPU的負載能夠比喻成超市收銀員負載，若是有1我的正在買單，有2我的在排隊，那麼該收銀員的負載就是3。 在收銀員工做時，不斷會有人買單完成，也不斷會有人排隊，能夠在固定的時間間隔內(譬如，每隔5秒)統計一次負載，那麼，就能夠統計出一段時間內的平均負載。

• 頁錯誤信息： 進程的CPU使用率最後輸出的「faults: xxx minor/major」部分表示的是頁錯誤次數，當次數爲0時不顯示。 major是指Major Page Fault(主要頁錯誤，簡稱MPF)，內核在讀取數據時會前後查找CPU的高速緩存和物理內存，若是找不到會發出一個MPF信息，請求將數據加載到內存。 minor是指Minor Page Fault(次要頁錯誤，簡稱MnPF)，磁盤數據被加載到內存後，內核再次讀取時，會發出一個MnPF信息。 一個文件第一次被讀寫時會有不少的MPF，被緩存到內存後再次訪問MPF就會不多，MnPF反而變多，這是內核爲減小效率低下的磁盤I/O操做採用的緩存技術的結果。

2.2.2 函數調用棧

AMS.dumpStackTraces()方法用於打印進程的函數調用棧，該方法的主體邏輯以下：

private static void dumpStackTraces(String tracesPath, ArrayList<Integer> firstPids, ProcessCpuTracker processCpuTracker, SparseArray<Boolean> lastPids, String[] nativeProcs) { ... // 1. 對firstPids數組中的進程發送SIGNAL_QUIT。 // 進程在收到SIGNAL_QUIT後，會打印函數調用棧 int num = firstPids.size(); for (int i = 0; i < num; i++) { synchronized (observer) { Process.sendSignal(firstPids.get(i), Process.SIGNAL_QUIT); observer.wait(200); // Wait for write-close, give up after 200msec } } ... // 2. 打印Native進程的函數調用棧 int[] pids = Process.getPidsForCommands(nativeProcs); if (pids != null) { for (int pid : pids) { Debug.dumpNativeBacktraceToFile(pid, tracesPath); } } ... // 3. 更新CPU的使用狀況 processCpuTracker.init(); System.gc(); processCpuTracker.update(); processCpuTracker.wait(500); // measure over 1/2 second. processCpuTracker.update(); // 4. 對lastPids數組中的進程發送SIGNAL_QUIT // 只有處於工做狀態的lastPids進程，纔會收到SIGNAL_QUIT，打印函數調用棧 final int N = processCpuTracker.countWorkingStats(); int numProcs = 0; for (int i=0; i<N && numProcs<5; i++) { ProcessCpuTracker.Stats stats = processCpuTracker.getWorkingStats(i); if (lastPids.indexOfKey(stats.pid) >= 0) { numProcs++; Process.sendSignal(stats.pid, Process.SIGNAL_QUIT); observer.wait(200); // Wait for write-close, give up after 200msec } }

該方法有幾個重要的邏輯(Native進程的函數調用棧此處不表)：

• 向進程發送SIGNAL_QUIT信號，進程在收到這個信號後，就會打印函數調用棧，默認輸出到 /data/anr/traces.txt 文件中， 固然也能夠配置 dalvik.vm.stack-trace-file 這個系統屬性來指定輸出函數調用棧的位置

• traces文件中包含不少進程的函數調用棧，這是由firstPids和lastPids數組控制的，在最終的traces文件中，firstPids中的進程是先打印的， 並且當前發生ANR的進程又是排在firstPids的第一個，因此，當咱們打開traces文件，第一個看到的就是當前發生ANR的應用進程

3. 問題分析方法

分析ANR問題，有三大利器：Logcat，traces和StrictMode。 在StrictMode機制一文中，咱們介紹過StrictMode的實現機制以及用途，本文中不討論利用StrictMode來解決ANR問題，但各位讀者須要有這個意識。 在Watchdog機制以及問題分析一文中，咱們介紹過logcat和traces這兩種日誌的用途。 分析ANR問題同Watchdog問題同樣，都須要通過日誌獲取、問題定位和場景還原三個步驟。

3.1 日誌獲取

咱們在上文中分析過，ANR報告機制的重要職能就是輸出日誌， 這些日誌如何取到呢？請參見日誌獲取

3.2 問題定位

經過在event log中檢索 am_anr 關鍵字，就能夠找到發生ANR的進程，譬如如下日誌：

10-16 00:48:27 820 907 I am_anr: [0,29533,com.android.systemui,1082670605,Broadcast of Intent { act=android.intent.action.TIME_TICK flg=0x50000114 (has extras) }]

表示在 10-16 00:48:27 這個時刻，PID爲 29533 進程發生了ANR，進程名是 com.android.systemui。

接下來能夠在system log檢索 ANR in 關鍵字，找到發生ANR先後的CPU使用狀況：

10-16 00:50:10 820 907 E ActivityManager: ANR in com.android.systemui, time=130090695
10-16 00:50:10 820 907 E ActivityManager: Reason: Broadcast of Intent { act=android.intent.action.TIME_TICK flg=0x50000114 (has extras) }
10-16 00:50:10 820 907 E ActivityManager: Load: 30.4 / 22.34 / 19.94
10-16 00:50:10 820 907 E ActivityManager: Android time :[2015-10-16 00:50:05.76] [130191,266]
10-16 00:50:10 820 907 E ActivityManager: CPU usage from 6753ms to -4ms ago:
10-16 00:50:10 820 907 E ActivityManager:   47% 320/netd: 3.1% user + 44% kernel / faults: 14886 minor 3 major
10-16 00:50:10 820 907 E ActivityManager:   15% 10007/com.sohu.sohuvideo: 2.8% user + 12% kernel / faults: 1144 minor
10-16 00:50:10 820 907 E ActivityManager:   13% 10654/hif_thread: 0% user + 13% kernel
10-16 00:50:10 820 907 E ActivityManager:   11% 175/mmcqd/0: 0% user + 11% kernel
10-16 00:50:10 820 907 E ActivityManager:   5.1% 12165/app_process: 1.6% user + 3.5% kernel / faults: 9703 minor 540 major
10-16 00:50:10 820 907 E ActivityManager:   3.3% 29533/com.android.systemui: 2.6% user + 0.7% kernel / faults: 8402 minor 343 major
10-16 00:50:10 820 907 E ActivityManager:   3.2% 820/system_server: 0.8% user + 2.3% kernel / faults: 5120 minor 523 major
10-16 00:50:10 820 907 E ActivityManager:   2.5% 11817/com.netease.pomelo.push.l.messageservice_V2: 0.7% user + 1.7% kernel / faults: 7728 minor 687 major
10-16 00:50:10 820 907 E ActivityManager:   1.6% 11887/com.android.email: 0.5% user + 1% kernel / faults: 6259 minor 587 major
10-16 00:50:10 820 907 E ActivityManager:   1.4% 11854/com.android.settings: 0.7% user + 0.7% kernel / faults: 5404 minor 471 major
10-16 00:50:10 820 907 E ActivityManager:   1.4% 11869/android.process.acore: 0.7% user + 0.7% kernel / faults: 6131 minor 561 major
10-16 00:50:10 820 907 E ActivityManager:   1.3% 11860/com.tencent.mobileqq: 0.1% user + 1.1% kernel / faults: 5542 minor 470 major
...
10-16 00:50:10 820 907 E ActivityManager:  +0% 12832/cat: 0% user + 0% kernel
10-16 00:50:10 820 907 E ActivityManager:  +0% 13211/zygote64: 0% user + 0% kernel
10-16 00:50:10 820 907 E ActivityManager: 87% TOTAL: 3% user + 18% kernel + 64% iowait + 0.5% softirq

這一段日誌對於Android開發人員而言，實在太熟悉不過了，它包含的信息量巨大：

• 發生ANR的時間。event log中，ANR的時間是 00：48：27，由於AMS.appNotResponding()首先會打印event log，而後再打印system log， 因此，在system log中，找到ANR的時間是 00:50:10。能夠從這個時間點以前的日誌中，還原ANR出現時系統的運行狀態

• 打印ANR日誌的進程。ANR日誌都是在system_server進程的AMS線程打印的，在event log和system log中，都能看到 820和 907， 因此system_server的PID是 802，AMS線程的TID是 907。ANR的監測機制實如今AMS線程，分析一些受系統影響的ANR，須要知道system_server進程的運行狀態

• 發生ANR的進程。ANR in關鍵字就代表了當前ANR的進程是com.android.system.ui，經過event log，知道進程的PID是 29533

• 發生ANR的緣由。Reason關鍵字代表了當前發生ANR的緣由是，處理TIME_TICK廣播消息超時。 隱含的意思是TIME_TICK是一個串行廣播消息，在 29533 的主線程中，執行BroadcastReceiver.onReceive()方法已經超過10秒

• CPU負載。Load關鍵字代表了最近1分鐘、5分鐘、15分鐘內的CPU負載分別是30.四、22.三、19.94。CPU最近1分鐘的負載最具參考價值，由於ANR的超時限制基本都是1分鐘之內， 這能夠近似的理解爲CPU最近1分鐘平均有30.4個任務要處理，這個負載值是比較高的

• CPU使用統計時間段。CPU usage from XX to XX ago關鍵字代表了這是在ANR發生以前一段時間內的CPU統計。 相似的還有CPU usage from XX to XX after關鍵字，代表是ANR發生以後一段時間內的CPU統計

• 各進程的CPU使用率。咱們以com.android.systemui進程的CPU使用率爲例，它包含如下信息：

  • 總的CPU使用率: 3.3%，其中systemui進程在用戶態的CPU使用率是2.6%，在內核態的使用率是0.7%

  • 缺頁次數fault：8402 minor表示高速緩存中的缺頁次數，343 major表示內存的缺頁次數。minor能夠理解爲進程在作內存訪問，major能夠理解爲進程在作IO操做。 當前minor和major值都是比較高的，從側面反映了發生ANR以前，systemui進程有有較多的內存訪問操做，引起的IO次數也會較多

  • CPU使用率前面的 「+」。部分進程的CPU使用率前面有 「+」 號，譬如cat和zygote64，表示在上一次CPU統計的時間片斷內，尚未這些進程，而這一次CPU統計的時間片斷內，運行了這些進程。 相似的還有 「-」 號，表示兩次CPU統計時間片斷時，這些進程消亡了

• CPU使用匯總。TOTAL關鍵字代表了CPU使用的彙總，87%是總的CPU使用率，其中有一項iowait代表CPU在等待IO的時間，佔到64%，說明發生ANR之前，有大量的IO操做。app_process、 system_server, com.android.systemui這幾個進程的major值都比較大，說明這些進程的IO操做較爲頻繁，從而拉昇了整個iowait的時間

信息量是如此的龐大，以至於咱們都要下結論了：CPU大量的時間都在等待IO，致使systemui進程分配不到CPU時間，從而主線程處理廣播消息超時，發生了ANR。

對於一個嚴謹的開發人員而言，這種結論下得有點早，由於還有太多的疑問：

• systemui進程也分到了一些CPU時間(3.3%)，難道BroadcastReceiver.onReceive()方法就一直沒法執行嗎？

• 爲何iowait的時間會這麼多，並且多個進程的major值都很高？

接下來仍是須要從其餘日誌中還原ANR出現的場景。

3.3 場景還原

3.3.1 第一個假設和驗證

帶着上文提出來的第一個疑問，咱們先來作一個假設：若是systemui進程正在執行BroadcatReceiver.onReceive()方法，那麼從traces.txt文件中，應該能夠看到主線程的函數調用棧正在執行這個方法。

接下來，咱們首先從traces文件中，找到發生ANR時(00:48:27)，sysemtui進程的函數調用棧信息。

----- pid 29533 at 2015-10-16 00:48:06 -----
Cmd line: com.android.systemui

DALVIK THREADS (53):
"main" prio=5 tid=1 Native
  | group="main" sCount=1 dsCount=0 obj=0x75bd5818 self=0x7f8549a000
  | sysTid=29533 nice=0 cgrp=bg_non_interactive sched=0/0 handle=0x7f894bbe58
  | state=S schedstat=( 288625433917 93454573244 903419 ) utm=20570 stm=8292 core=3 HZ=100
  | stack=0x7fdffda000-0x7fdffdc000 stackSize=8MB
  | held mutexes=
  native: #00 pc 00060b0c  /system/lib64/libc.so (__epoll_pwait+8)
  native: #01 pc 0001bb54  /system/lib64/libc.so (epoll_pwait+32)
  native: #02 pc 0001b3d8  /system/lib64/libutils.so (android::Looper::pollInner(int)+144)
  native: #03 pc 0001b75c  /system/lib64/libutils.so (android::Looper::pollOnce(int, int*, int*, void**)+76)
  native: #04 pc 000d7194  /system/lib64/libandroid_runtime.so (android::NativeMessageQueue::pollOnce(_JNIEnv*, int)+48)
  at android.os.MessageQueue.nativePollOnce(Native method)
  at android.os.MessageQueue.next(MessageQueue.java:148)
  at android.os.Looper.loop(Looper.java:151)
  at android.app.ActivityThread.main(ActivityThread.java:5718)
  at java.lang.reflect.Method.invoke!(Native method)
  at java.lang.reflect.Method.invoke(Method.java:372)
  at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:975)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:770)

----- pid 29533 at 2015-10-16 00:48:29 -----
Cmd line: com.android.systemui

DALVIK THREADS (54):
"main" prio=5 tid=1 Blocked
  | group="main" sCount=1 dsCount=0 obj=0x75bd5818 self=0x7f8549a000
  | sysTid=29533 nice=0 cgrp=bg_non_interactive sched=0/0 handle=0x7f894bbe58
  | state=S schedstat=( 289080040422 93461978317 904874 ) utm=20599 stm=8309 core=0 HZ=100
  | stack=0x7fdffda000-0x7fdffdc000 stackSize=8MB
  | held mutexes=
  at com.mediatek.anrappmanager.MessageLogger.println(SourceFile:77)
  - waiting to lock <0x26b337a3> (a com.mediatek.anrappmanager.MessageLogger) held by thread 49
  at android.os.Looper.loop(Looper.java:195)
  at android.app.ActivityThread.main(ActivityThread.java:5718)
  at java.lang.reflect.Method.invoke!(Native method)
  at java.lang.reflect.Method.invoke(Method.java:372)
  at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:975)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:770)
...
"Binder_5" prio=5 tid=49 Native
  | group="main" sCount=1 dsCount=0 obj=0x136760a0 self=0x7f7e453000
  | sysTid=6945 nice=0 cgrp=default sched=0/0 handle=0x7f6e3ce000
  | state=S schedstat=( 5505571091 4567508913 30743 ) utm=264 stm=286 core=4 HZ=100
  | stack=0x7f6b83f000-0x7f6b841000 stackSize=1008KB
  | held mutexes=
  native: #00 pc 00019d14  /system/lib64/libc.so (syscall+28)
  native: #01 pc 0005b5d8  /system/lib64/libaoc.so (???)
  native: #02 pc 002c6f18  /system/lib64/libaoc.so (???)
  native: #03 pc 00032c40  /system/lib64/libaoc.so (???)
  at libcore.io.Posix.getpid(Native method)
  at libcore.io.ForwardingOs.getpid(ForwardingOs.java:83)
  at android.system.Os.getpid(Os.java:176)
  at android.os.Process.myPid(Process.java:754)
  at com.mediatek.anrappmanager.MessageLogger.dump(SourceFile:219)
  - locked <0x26b337a3> (a com.mediatek.anrappmanager.MessageLogger)
  at com.mediatek.anrappmanager.ANRAppManager.dumpMessageHistory(SourceFile:65)
  at android.app.ActivityThread$ApplicationThread.dumpMessageHistory(ActivityThread.java:1302)
  at android.app.ApplicationThreadNative.onTransact(ApplicationThreadNative.java:682)
  at android.os.Binder.execTransact(Binder.java:451)

最終，咱們找到systemui進程ANR時刻(00:48:27)附近的兩個函數調用棧:

1. 在ANR發生以前(00:48:06)，主線程的函數調用棧處於正常狀態：消息隊列中，循環中處理消息

2. 在ANR發生以後2秒(00:48:29)，主線程處於Blocked狀態，在等待一個被49號線程持有的鎖。而49號線程是一個Binder線程，anrappmanager正在作dump操做。

筆者分析的日誌是MTK平臺產生的，因此從函數調用棧中看到com.mediatek.anrappmanager.MessageLogger這樣的類，它是MTK在AOSP上的擴展，用於打印ANR日誌。

至此，systemui進程發生ANR的直接緣由咱們已經找到了，systemui進程正在打印traces，存在較長時間的IO操做，致使主線程阻塞，從而沒法處理TIME_TICK廣播消息，因此發生了ANR。

要避免這種場景下的ANR，咱們就須要打破主線程中Blocked的邏輯。其實本例是因爲MTK在AOSP的android.os.Looper.loop()擴展了打印消息隊列的功能，該功能存在設計缺陷，會致使鎖等待的狀況。

3.3.2 第二個假設和驗證

咱們進一步挖掘在systemui尚未發生ANR時，就在打印traces的緣由。帶着上文提出的第二個疑問，咱們來作另外一個假設： iowait較高，並且多個進程的major都很高，多是因爲當前正在調用AMS.dumpStackTraces()方法，不少進程都須要將本身的函數調用棧寫到traces文件，因此IO就會較高。 若是當前正在調用AMS.dumpStackTraces()方法，那說明當時系統已經發生了異常，要麼已經有ANR發生，要麼有SNR發生

從event log中，咱們檢索到了另外一個ANR：

10-16 00:47:58 820 907 I am_anr  : [0,10464,com.android.settings,1086864965,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: 1.)]

在 00:47:58 這個時刻，com.android.settings進程發生了ANR，並且ANR的時間在systemui以前(00:48:27)。這一下，咱們就找到佐證了，正是由於settings進程先發生了ANR，調用AMS.dumpStackTraces()， 從而不少進程都開始了打印traces的操做，因此係統的整個iowait比較高，大量進程的major值也比較高，systemui就在其列。在MTK邏輯的影響下，打印ANR日誌會致使主線程阻塞，從而就連帶引起了其餘應用的ANR。

在system log中，咱們檢索到了settings進程ANR的CPU使用信息：

10-16 00:48:12 820 907 E ActivityManager: ANR in com.android.settings (com.android.settings/.SubSettings), time=130063718
10-16 00:48:12 820 907 E ActivityManager: 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: 1.)
10-16 00:48:12 820 907 E ActivityManager: Load: 21.37 / 19.25 / 18.84
10-16 00:48:12 820 907 E ActivityManager: Android time :[2015-10-16 00:48:12.24] [130077,742]
10-16 00:48:12 820 907 E ActivityManager: CPU usage from 0ms to 7676ms later:
10-16 00:48:12 820 907 E ActivityManager:   91% 820/system_server: 16% user + 75% kernel / faults: 13192 minor 167 major
10-16 00:48:12 820 907 E ActivityManager:   3.2% 175/mmcqd/0: 0% user + 3.2% kernel
10-16 00:48:12 820 907 E ActivityManager:   2.9% 29533/com.android.systemui: 2.3% user + 0.6% kernel / faults: 1352 minor 10 major
10-16 00:48:12 820 907 E ActivityManager:   2.2% 1736/com.android.phone: 0.9% user + 1.3% kernel / faults: 1225 minor 1 major
10-16 00:48:12 820 907 E ActivityManager:   2.2% 10464/com.android.settings: 0.7% user + 1.4% kernel / faults: 2801 minor 105 major
10-16 00:48:12 820 907 E ActivityManager:   0% 1785/com.meizu.experiencedatasync: 0% user + 0% kernel / faults: 3478 minor 2 major
10-16 00:48:12 820 907 E ActivityManager:   1.8% 11333/com.meizu.media.video: 1% user + 0.7% kernel / faults: 3843 minor 89 major
10-16 00:48:12 820 907 E ActivityManager:   1.5% 332/mobile_log_d: 0.5% user + 1% kernel / faults: 94 minor 1 major
10-16 00:48:12 820 907 E ActivityManager:   1% 11306/com.meizu.media.gallery: 0.7% user + 0.2% kernel / faults: 2204 minor 55 major
...
10-16 00:48:12 820 907 E ActivityManager:  +0% 11397/sh: 0% user + 0% kernel
10-16 00:48:12 820 907 E ActivityManager:  +0% 11398/app_process: 0% user + 0% kernel
10-16 00:48:12 820 907 E ActivityManager: 29% TOTAL: 5.1% user + 15% kernel + 9.5% iowait + 0% softirq

具體的涵義咱們再也不贅述了，只關注一下ANR的緣由:

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: 1.)

以前對Input ANR機制的分析派上用長了，咱們輕鬆知道這種ANR的緣由是什麼。 Wait queue length： 1表示以前的輸入事件已經派發到Settings進程了，但Settings進程尚未處理完畢，新來的KeyEvent事件已經等待超過了5秒，因此ANR產生了。

接下來，又須要找到Settings的traces，分析Settings主線程處理輸入事件超時的緣由，咱們點到爲止。

4. 總結

本文對Android ANR機制進行了深刻的分析：

• ANR的監測機制，從Service，Broadcast，InputEvent三種不一樣的ANR監測機制的源碼實現開始，分析了Android如何發現各種ANR。在啓動服務、派發廣播消息和輸入事件時，植入超時檢測，用於發現ANR

• ANR的報告機制，分析Android如何輸出ANR日誌。當ANR被發現後，兩個很重要的日誌輸出是：CPU使用狀況和進程的函數調用棧，這兩類日誌是咱們解決ANR問題的利器

• ANR的解決方法，經過一個案例，對ANR日誌進行了深刻解讀，梳理了分析ANR問題的思路和途徑