教你如何分析 Android ANR 问题

ANR介绍

ANR 的全称是 Application No Responding，即应用程序无响应，具体是一些特定的 Message (Key Dispatch、Broadcast、Service) 在应用的UI线程（主线程）没有在规定的时间内处理完，进而触发 ANR 异常。

ANR 由消息处理机制保证，Android 在系统层实现了一套精密的机制来发现 ANR，核心原理是消息调度和超时处理。ANR 机制主体实现在系统层，所有与 ANR 相关的消息，都会经过系统进程 system_server 调度，具体是 ActivityManagerService 服务，然后派发到应用进程完成对消息的实际处理，同时，系统进程设计了不同的超时限制来跟踪消息的处理。一旦应用程序处理消息不当，超时限制就起作用了，它收集一些系统状态，譬如 CPU/IO 使用情况、进程函数调用栈 CallStack，（有些平台比如 MTK，还会打印相应的 Message 出来供调试分析），最后报告用户有进程无响应了( ANR 对话框)。

ANR类型

ANR 一般有三种类型：

KeyDispatchTimeout

这个主要是按键或触摸事件在特定时间内无响应，一般 Android 平台默认超时时间是 5s 会报 anr，不过有些平台会修改这个时间，比如 MTK 有些平台就是 8s 的超时时间。

这个超时时间可以在 ActivityManagerService.java 查看：

// M: ANR debug mechanism (Ori: 5*1000)
static final int KEY_DISPATCHING_TIMEOUT = 8*1000;

BroadcastTimeout

这类超时会有 ANR 提示框弹出，用户可以选择 forceStop 或者继续等待。

这个主要是 BroadcastRecevier 在规定时间无法处理完成。前台广播超时时间是 10s，后台广播超时是 60s，这类超时没有提示框弹出。

==> AMS.java

// How long we allow a receiver to run before giving up on it.
static final int BROADCAST_FG_TIMEOUT = 10*1000;
static final int BROADCAST_BG_TIMEOUT = 60*1000;

ServiceTimeout&nbsp

Service 在规定时间内无法处理完成操作，即会报出服务超时，这类 ANR 同样没有提示框出现。超时时间，前台 Service 是 20s，后台 Service 是 200s。

==> ActivityServices.java

// How long we wait for a service to finish executing.
static final int SERVICE_TIMEOUT = 20*1000;
// How long we wait for a service to finish executing.
static final int SERVICE_BACKGROUND_TIMEOUT = SERVICE_TIMEOUT * 10;

三种 ANR 中只有第 1 种会显示系统提示对话框，因为用户正在做界面交互操作，如果长时间没有任何响应，会让用户怀疑设备死机了，大多数人此时会开始乱按，甚至拔出电池重启，给用户的体验肯定是非常糟糕的。

三种 ANR 发生时都会在 log 中输出错误信息，你会发现各个应用进程和系统进程的函数堆栈信息都输出到了一个 /data/anr/traces.txt 的文件中，这个文件是分析ANR原因的关键文件，同时在日志中还会看到当时的 CPU 使用率，这也是重要信息，在后面的章节会详细介绍如何利用它们分析ANR问题。

这三种ANR不是孤立的，有可能会相互影响。例如一个应用程序进程中同时有一个正在显示的 Activity 和一个正在处理消息的 BroadcastReceiver，它们都运行在这个进程的主线程中。如果 BR 的 onReceive 函数没有返回，此时用户点击屏幕，而 onReceive 超过 5 秒仍然没有返回，主线程无法处理用户输入事件，就会引起第 1 种 ANR。如果继续超过 10 秒没有返回，又会引起第 2 种ANR。

ANR发生的原理

对于ANR 发生基本原理如下：

在进行相关操作调用 hander.sendMessageAtTime() 发送一个 ANR 的消息，延时时间为 ANR 发生的时间(如 activity 是当前时间 5s 之后)。
进行相关的操作
操作结束后向 remove 掉该条 message。如果相关的操作在规定时间没有执行完成，该条 message 将被 handler 取出并执行，就发生了 ANR。

Android 对于消息的处理都是通过 Handler 来完成的，对 Handler 不了解的同学可以参考文章 Android Handler 源码分析（详细）。

ANR 分析示例

ANR 本质上是一个 Performance 问题，发生 ANR 的时候，如果问题可能出在 APK 自己身上，那么主要排查的方向是 apk 本身，分析看看是不是在 UI 线程做了耗时的操作？

个人认为，有一些 ANR 问题是很难分析的，比如 app 运行的时候由于当前系统底层的一些影响，导致当前 message 处理失败。这类问题往往没有规律，又难以重现。对于这类 ANR 问题，一般需要花费大量时间去了解系统的一些其他行为，而超出了 ANR 本身的范畴，这类问题就相当于一个警示信号，告诉你系统哪个地方出问题了。

查看 log 日志文件

搜索关键字 ANR :

04-17 17:15:23.817 E/ActivityManager(  187): ANR in com.da.android (com.da.android/com.text.my.app.ui.activities.ContentActivity)

上面这段文字的含义是 4月17日，17点15分23秒817ms时候发生了 ANR .其实一般还会带上 ANR 的原因，以及 CPU 使用信息，

这里我们写了一个 demo，比如在广播接收器的 onReceive 方法（广播接收器的 onReceive 方法默认在主线程执行）里面睡眠一段时间，如果这个时候主线程没有任何操作了，那么广播接收器可以正常执行完毕。不会造成 ANR 。如果我在发送广播之后然后点击多次返回按键，这个时候因为主线程睡眠了，无法响应，就会出现 ANR。

其对应的完整 log 信息如下：

ANR in com.brotherd.broadcastdemo (com.brotherd.broadcastdemo/.MainActivity)
    PID: 6317
    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: 2.)
    // 
　　 Load: 38.14 / 37.82 / 37.45
　　// ANR 发生前 cpu 使用信息
    CPU usage from 45678ms to 0ms ago (2020-10-27 08:39:06.256 to 2020-10-27 08:39:51.933):
      15% 1265/system_server: 12% user + 3.5% kernel / faults: 6531 minor 16 major
      13% 23112/com.android.systemui: 9.7% user + 3.5% kernel / faults: 6033 minor 103 major // minor major 表示页的错误
      4.7% 578/surfaceflinger: 2.6% user + 2% kernel / faults: 469 minor 2 major
      4.4% 673/hwpged: 0% user + 4.3% kernel / faults: 29 minor
      2.3% 549/android.hardware.graphics.composer@2.2-service: 1.1% user + 1.1% kernel / faults: 149 minor
      0.1% 2246/com.huawei.android.pushagent: 0% user + 0% kernel / faults: 2583 minor 22 major
      1.5% 461/logd: 0.8% user + 0.6% kernel / faults: 52 minor
      1.5% 2077/com.huawei.powergenie: 0.7% user + 0.8% kernel / faults: 843 minor 2 major
      0.5% 17384/com.android.settings: 0.4% user + 0.1% kernel / faults: 5419 minor 73 major
      1.3% 259/mmc-cmdqd/0: 0% user + 1.3% kernel
      1% 3888/kworker/u16:0: 0% user + 1% kernel / faults: 1 minor
      0.9% 18949/android.process.media: 0.5% user + 0.3% kernel / faults: 1408 minor 8 major
      0.8% 148/kswapd0: 0% user + 0.8% kernel
      0.5% 657/dubaid: 0.3% user + 0.2% kernel / faults: 139 minor
      0.5% 2105/com.huawei.android.launcher: 0.4% user + 0.1% kernel / faults: 159 minor 1 major
      0.5% 2366/com.huawei.systemmanager:service: 0.3% user + 0.1% kernel / faults: 374 minor
      0.5% 922/hisi_frw/0: 0% user + 0.5% kernel
      0.4% 3951/kworker/u16:8: 0% user + 0.4% kernel
      0.4% 27040/com.huawei.appmarket: 0.3% user + 0.1% kernel / faults: 350 minor 2 major
      0.4% 238/kworker/0:1H: 0% user + 0.4% kernel
      0.4% 2028/com.huawei.hiview: 0.1% user + 0.2% kernel / faults: 88 minor
      0.3% 577/lmkd: 0% user + 0.3% kernel
      0.3% 677/vendor.huawei.hardware.sensors@1.0-service: 0% user + 0.3% kernel / faults: 19 minor
      0.3% 3715/kworker/u16:1: 0% user + 0.3% kernel
      0.3% 29718/com.huawei.hidisk: 0.2% user + 0.1% kernel / faults: 404 minor 1 major
      0.1% 527/zygote64: 0% user + 0.1% kernel / faults: 541 minor
      0.3% 3954/kworker/u16:10: 0% user + 0.3% kernel
      0.3% 581/powerlogd: 0.2% user + 0.1% kernel / faults: 25 minor
      0.3% 3952/kworker/u16:9: 0% user + 0.3% kernel
      0% 23351/com.huawei.hwid: 0% user + 0% kernel / faults: 854 minor 10 major
      0.1% 3945/kworker/u16:6: 0% user + 0.1% kernel
      0.2% 24447/kworker/u17:0: 0% user + 0.2% kernel
      0.2% 548/android.hardware.graphics.allocator@2.0-service: 0% user + 0.2% kernel / faults: 47 minor
      0.2% 2042/com.huawei.systemserver: 0.1% user + 0.1% kernel / faults: 95 minor
      0.2% 426/oeminfo_nvm_server: 0% user + 0.1% kernel / faults: 79 minor 205 major
      0.2% 4187/kworker/u17:1: 0% user + 0.2% kernel
      0.2% 462/servicemanager: 0% user + 0.1% kernel / faults: 20 minor
      0.2% 3633/kworker/u16:2: 0% user + 0.2% kernel
      0.2% 5290/com.huawei.health:DaemonService: 0.1% user + 0% kernel / faults: 77 minor
      0.1% 7/rcu_preempt: 0% user + 0.1% kernel
      0.1% 93/sys_heap: 0% user + 0.1% kernel
      0.1% 949/hisi_hcc: 0% user + 0.1% kernel
      0.1% 637/hisecd: 0% user + 0.1% kernel / faults: 66 minor
      0.1% 2097/com.android.phone: 0% user + 0.1% kernel / faults: 97 minor
      0.1% 3441/kworker/u16:5: 0% user + 0.1% kernel
      0.1% 526/netd: 0% user + 0.1% kernel / faults: 142 minor 2 major
      0.1% 2063/com.huawei.HwOPServer: 0% user + 0% kernel / faults: 168 minor
      0.1% 1//init: 0% user + 0% kernel / faults: 263 minor 5 major
      0% 465/vendor.huawei.hardware.hwfactoryinterface@1.1-service: 0% user + 0% kernel / faults: 113 minor 5 major
      0.1% 3944/kworker/u16:4: 0% user + 0.1% kernel
      0.1% 655/displayengineserver: 0% user + 0% kernel / faults: 21 minor
      0.1% 918/oal_gpio_rx_dat: 0% user + 0.1% kernel
      0.1% 3955/com.eg.android.AlipayGphone:push: 0% user + 0% kernel / faults: 132 minor
      0.1% 26941/com.huawe
// anr 发生后 cpu 使用情况
  2020-10-27 08:39:53.753 1265-1285/? E/ActivityManager: CPU usage from 51ms to 493ms later (2020-10-27 08:39:51.984 to 2020-10-27 08:39:52.426) with 99% awake:
      48% 1265/system_server: 10% user + 37% kernel
      45% 1285/ActivityManager: 8% user + 37% kernel
      4.9% 578/surfaceflinger: 4.9% user + 0% kernel / faults: 5 minor
      2.4% 578/surfaceflinger: 2.4% user + 0% kernel
      3.1% 3952/kworker/u16:9: 0% user + 3.1% kernel
      3.7% 23112/com.android.systemui: 3.7% user + 0% kernel
      9.7% TOTAL: 5.2% user + 4.4% kernel  // 可以从 total 里面看到整个 cpu 的情况

首先看前面几行：

ANR in com.brotherd.broadcastdemo (com.brotherd.broadcastdemo/.MainActivity)
PID: 6317
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: 2.)

这几行表明了 ANR 发生所处的 activity，进程 ID，以及 ANR 原因（input 事件分发超时）；

ANRManager会打印出anr 前后的 cpu 使用情况，这个可以反映出当时系统的Performance状态：

如果 CPU 使用量接近 100%，说明当前设备很忙，有可能是CPU饥饿导致了ANR。
如果 CPU 使用量很少，说明主线程被BLOCK了
如果 IOwait 很高，说明ANR有可能是主线程在进行 I/O 操作造成的

那么这个时候，我们就要看看 anr 发生的时候，主线程在做什么了。

Trace 文件（data/anr/traces.txt）

log 文件只是告诉你 ANR 发生时间，但是并具体详细的信息，这时候就得查看 trace 文件（App 的进程发生 ANR 时，系统让活跃的 Top 进程都进行了一下 dump，进程中的各种Thread 就都 dump 到这个 trace 文件里了，所以 trace 文件中包含了每一条线程的运行时状态）。

对于当前这个例子的堆栈信息如下：

在上面的信息中，有这样一行

at com.brotherd.broadcastdemo.MyReceiver.onReceive(MyReceiver.java:23)

这就是造成 ANR 的根本原因。在 MyReceiver 类的 onReceive 方法中调用了 Thread 的 sleep 方法导致主线程阻塞，造成 ANR。

然后我们看一些字段的信息。

"main" prio=5 tid=1 Sleeping
  | group="main" sCount=1 dsCount=0 flags=1 obj=0x7682ab30 self=0x7bd3815c00
  | sysTid=6317 nice=-10 cgrp=default sched=0/0 handle=0x7c59fc8548
  | state=S schedstat=( 1009468742 32888019 224 ) utm=91 stm=9 core=4 HZ=100
  | stack=0x7ff27e1000-0x7ff27e3000 stackSize=8MB
  | held mutexes=

这些字段含义如下线程名：

线程自身信息

线程优先级：prio=5
线程ID： tid=1
线程状态：Sleeping
线程组名称：group="main"
线程被挂起的次数：sCount=1
线程被调试器挂起的次数：dsCount=0
线程的java的对象地址：obj= 0x7682ab30
线程本身的Native对象地址：self=0x7bd3815c00线程调度信息：
Linux系统中内核线程ID: sysTid=6317与主线程的进程号相同
线程调度优先级：nice=-10
线程调度组：cgrp=default
线程调度策略和优先级：sched=0/0
线程处理函数地址：handle= 0x7c59fc8548

线程的上下文信息：

线程调度状态：state=S
线程在CPU中的执行时间、线程等待时间、线程执行的时间片长度：schedstat=(1009468742 32888019 224)
线程在用户态中的调度时间值：utm=91
线程在内核态中的调度时间值：stm=9
最后执行这个线程的CPU核序号：core=4

线程的堆栈信息：

堆栈地址和大小：stack=0x7ff27e1000-0x7ff27e3000 stackSize=8MB

线程状态

此外，线程的状态很重要，了解这些状态的意义对分析ANR的原因是有帮助的，总结如下：

Thread.java 中的状态和 Thread.cpp 中的状态是有对应关系的。可以看到前者更加概括，也比较容易理解，面向 Java 的使用者；而后者更详细，面向虚拟机内部的环境。traces.txt 中显示的线程状态都是 Thread.cpp 中定义的。另外，所有的线程都是遵循 POSIX 标准的本地线程。

线程状态示例：

主线程是 running 或者 native：而对应的栈对应了App中的函数，则很有可能就是执行该函数时候发生了超时。
主线程被 block：非常明显的线程被锁，这时候可以看是被哪个线程锁了，可以考虑优化代码。如果是死锁问题，就更需要及时解决了。

死锁demo

我们来看一个死锁的例子：

"PowerManagerService" prio=5 tid=24 MONITOR
| group="main" sCount=1 dsCount=0 obj=0x41dd0eb0 self=0x5241b218
| sysTid=567 nice=0 sched=0/0 cgrp=apps handle=1380038664
| state=S schedstat=( 6682116007 11324451214 33313 ) utm=450 stm=219 core=1
at com.android.server.am.ActivityManagerService.broadcastIntent(ActivityManagerService.java:~13045)
- waiting to lock <0x41a874a0> (a com.android.server.am.ActivityManagerService) held by tid=12 (android.server.ServerThread)
at android.app.ContextImpl.sendBroadcast(ContextImpl.java:1144)
at com.android.server.power.PowerManagerService$DisplayBlankerImpl.unblankAllDisplays(PowerManagerService.java:3442)
at com.android.server.power.DisplayPowerState$PhotonicModulator$1.run(DisplayPowerState.java:456)
at android.os.Handler.handleCallback(Handler.java:800)
at android.os.Handler.dispatchMessage(Handler.java:100)
at android.os.Looper.loop(Looper.java:194)
at android.os.HandlerThread.run(HandlerThread.java:60)

tid=24 线程在等待一个 <0x41a874a0> 的锁，而这个锁被 tid=12 的线程占用了，我们来看看 tid=12：

"android.server.ServerThread" prio=5 tid=12 MONITOR
| group="main" sCount=1 dsCount=0 obj=0x41a76178 self=0x507837a8
| sysTid=545 nice=-2 sched=0/0 cgrp=apps handle=1349936616
| state=S schedstat=( 15368096286 21707846934 69485 ) utm=1226 stm=310 core=0
at com.android.server.power.PowerManagerService.isScreenOnInternal(PowerManagerService.java:~2529)
- waiting to lock <0x41a7e2e8> (a java.lang.Object) held by tid=85 (Binder_B)
at com.android.server.power.PowerManagerService.isScreenOn(PowerManagerService.java:2522)
at com.android.server.wm.WindowManagerService.sendScreenStatusToClientsLocked(WindowManagerService.java:7749)
at com.android.server.wm.WindowManagerService.setEventDispatching(WindowManagerService.java:7628)
at com.android.server.am.ActivityManagerService.updateEventDispatchingLocked(ActivityManagerService.java:8083)
at com.android.server.am.ActivityManagerService.wakingUp(ActivityManagerService.java:8077)

tid=12 线程在等待 <0x41a7e2e8> 的锁，而这个锁被 tid=85 的线程占用了，我们来看看 tid=85：

"Binder_B" prio=5 tid=85 MONITOR 
| group="main" sCount=1 dsCount=0 obj=0x42744770 self=0x58329e88
| sysTid=3700 nice=-20 sched=0/0 cgrp=apps handle=1471424616
| state=S schedstat=( 1663727513 2044643318 6806 ) utm=132 stm=34 core=1
at com.android.server.power.PowerManagerService$DisplayBlankerImpl.toString(PowerManagerService.java:~3449)
- waiting to lock <0x41a7e420> (a com.android.server.power.PowerManagerService$DisplayBlankerImpl) held by tid=24 (PowerManagerService)

值得注意的是，trace里面一般会包含时间，尽量分析跟anr时间相近的trace，避免受到其他干扰。tid=85线程在等待<0x41a7e420>的锁释放，而这个锁被tid=24占用了，所以就发送了死锁。那么这种情况下我们就需要找到发生死锁的source code，进行分析并修改。

其他分析思路

有时候我们 log 也分析了，traces 也分析了，还是很难分析出 ANR 的原因，那么我们可能就需要尝试从其他方面分析了：

从main log 里面找 anr 发生时间前 8s，看看 app 的 main thread 在做什么操作？是否有异常的地方，一般 process 的 pid 会等于主线程 id。
大范围搜寻 log，看是否 anr 发生之前，哪里有发生 crash？是否有可能引起 anr。
看情况抓取平台的一些辅助信息，包括但不局限于：
- memory info
- process status
- cpu info
- Binder info
- ftrace

减少发生 ANR 概率

将所有耗时操作，比如访问网络，Socket通信，查询大量 SQL 语句，复杂逻辑计算等都放在子线程中去，然后通过 handler.sendMessage、runonUIThread、AsyncTask 等方式更新 UI。无论如何都要确保用户界面作的流畅度。如果耗时操作需要让用户等待，那么可以在界面上显示度条。
使用 AsyncTask 处理耗时 IO 操作。在一些同步的操作主线程有可能被锁，需要等待其他线程释放相应锁才能继续执行，这样会有一定的 ANR 风险，对于这种情况有时也可以用异步线程来执行相应的逻辑。另外，要避免死锁的发生。
使用 Thread 或者 HandlerThread 时，调用 Process.setThreadPriority(Process.THREADPRIORITYBACKGROUND) 设置优先级，否则仍然会降低程序响应，因为默认 Thread 的优先级和主线程相同。
使用 Handler 处理工作线程结果，而不是使用 Thread.wait() 或者 Thread.sleep() 来阻塞主线程。
Activity 的 onCreate 和 onResume 回调中尽量避免耗时的代码
View 的 onOnTouchevent 和 onclick 中也要避免耗时的代码
BroadcastReceiver 中 onReceive 代码也要尽量减少耗时，建议使用 IntentService 处理。
各个组件的生命周期函数都不应该有太耗时的操作，即使对于后台 Service 或者 ContentProvider 来讲，应用在后台运行时候其 onCreate() 时候不会有用户输入引起事件无响应 ANR，但其执行时间过长也会引起 Service 的 ANR 和 ContentProvider 的ANR

参考文章

Android 系统稳定性 - ANR（一）

ANR问题分析指南

posted @ 2020-11-08 21:25 huansky 阅读(15141) 评论(0) 编辑收藏举报

刷新页面返回顶部

huansky