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问题的思路和途径