ANR问题分析实例 logcat anr trace

最新推荐文章于 2024-04-26 18:40:57 发布

阿杰、

最新推荐文章于 2024-04-26 18:40:57 发布

阅读量872

点赞数

分类专栏： android 文章标签： android anr

原文链接：https://www.cnblogs.com/krislight1105/p/10244994.html

版权

android 专栏收录该内容

10 篇文章 0 订阅

订阅专栏

转载：https://www.cnblogs.com/krislight1105/p/10244994.html

先说结论：排查方法

logcat 搜索【ANR in】关键字
- 查看发生问题的应用
- 查看cpu 使用情况
  - 排查是否是 io 过高或者 cpu 负载造成的卡顿，再结合 traces 分析验证
- 【am_anr】关键字查看 activitymanager 打印信息
traces, 发生ANR时，各进程的函数调用栈信息
- 查看 main thread 中的【locked】【wait】关键字，分析lock 调用栈，找到根源

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);
}

该方法的主体逻辑可以分成五个部分来看：

更新CPU的统计信息。这是发生ANR时，第一次CPU使用信息的采样，采样数据会保存在mProcessStats这个变量中
填充firstPids和lastPids数组。当前发生ANR的应用会首先被添加到firstPids中，这样打印函数栈的时候，当前进程总是在trace文件的最前面
打印函数调用栈(StackTrace)。具体实现由dumpStackTraces()函数完成
更新CPU的统计信息。这是发生ANR时，第二次CPU使用信息的采样，两次采样的数据分别对应ANR发生前后的CPU使用情况
显示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)附近的两个函数调用栈:

在ANR发生之前(00:48:06)，主线程的函数调用栈处于正常状态：消息队列中，循环中处理消息
在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问题的思路和途径

5.其他：

traces.txt是如何生成的

当APP(包括系统APP和用户APP)进程出现ANR、应用响应慢或WatchDog的监视没有得到回馈时,系统会dump此时的top进程,进程中Thread的运行状态就都dump到这个Trace文件中了.每次发生ANR，这个文件都会被清空，写入新的内容. 如果想查看以前发生ANR的信息，可以去查看DB文件.

DropBox中的log

traces.txt只保留最后一次发生ANR时的信息, android 2.2开始增加了DropBox功能, 保留历史上发生的所有ANR的log.
“/data/system/dropbox”是DB指定的文件存放位置.
日志保存的最长时间，默认是3天.

shell@sp9820a_Rui8503:/data # cd system/dropbox/
shell@sp9820a_Rui8503:/data/system/dropbox # ls
SYSTEM_BOOT@1325376052965.txt
system_app_crash@1325376052598.txt
system_app_crash@1325376054905.txt
system_app_strictmode@1325376048453.txt.gz
system_app_strictmode@1325376053442.txt.gz
system_app_strictmode@1325376058904.txt.gz
system_server_wtf@1325376043066.txt
system_server_wtf@1325376052708.txt
system_server_wtf@1325376052842.txt
shell@sp9820a_Rui8503:/data/system/dropbox #

阿杰、

关注

0
点赞
踩
3

收藏

觉得还不错? 一键收藏
0
评论
ANR问题分析实例 logcat anr trace

ANR问题分析实例ANR监测机制包含三种： Service ANR，前台进程中Service生命周期不能超过20秒，后台进程中Service的生命周期不能超过200秒。在启动Service时，抛出定时消息SERVICE_TIMEOUT_MSG或SERVICE_BACKGOURND_TIMEOUT_MSG，如果定时消息响应了，则说明发生了ANR Broadcast ANR，前台的“串行广播消息”必须在10秒内处理完毕，后台的“串行广播消息”必须在60秒处理完毕，每派发串行广播消息到一个
复制链接

扫一扫