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.4、22.3、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問題的思路和途徑