Android 性能优化系列：ANR 触发原理与分析

什么是 ANR？

ANR（Application Not Responding）是指应用程序未响应，Android 系统对于一些事件需要在一定时间范围内完成，如果超过预定时间未能得到有效响应或者响应时间过长，都会造成 ANR。

ANR 的产生需要满足三个条件：

• 主线程：只有 应用程序的主线程 响应超时才会产生 ANR

• 超时时间：产生 ANR 的上下文不同，超时时间也会不同，但只要在这个时间上限内没有响应就会 ANR

• 输入事件/特定操作：输入事件是指按键、触屏等设备输入事件，特定操作是指 BroadcastReceiver 和 Service 的生命周期中的各个函数，产生 ANR 的上下文不同，导致 ANR 的原因也会不同

为了降低因网络访问导致的 ANR，在 Android 4.0 之后强制规定访问网络必须在子线程处理，如果在主线程访问网络将会抛出 NetworkOnMainThreadException。

只要是耗时操作都可能会阻塞主线程，耗时操作要求放在子线程。

ANR 发生场景

不同的场景产生 ANR 的方式也不同，在这里详细讲讲各种情况产生的场景。

ANR 事件	超时时间	相应日志描述
点击事件（按键和触摸事件）	5s 内没被处理	Input event dispatching timed out
Service	前台 Service 20s，后台 Service 200s 未完成启动	Timeout executing service
BroadcastReceiver	前台广播 10s，后台广播 60s，onReceive() 在规定时间内没处理完	Timeout of broadcast Broadcast Record
ContentProvider	publish 在 10s 内没处理完	Timeout publishing content providers

需要注意的是，前台广播的 ANR 时间虽然是 10s 内 onReceive() 没有执行完就提示，这是在没有点击触摸事件导致 ANR 的前提下才是 10s，否则会先触发点击事件的 ANR，onReceive() 有可能执行不到 10s 就发生 ANR，所以不要在 onReceive() 处理耗时操作。

在实际项目中，大多数的 ANR 都是点击触摸事件超时导致，会超时的原因也主要由以下三个原因导致：

• 数据导致的 ANR：频繁 GC 导致线程暂停，处理事件时间被拉长

• 线程阻塞或死锁导致的 ANR

• Binder 导致的 ANR：Binder 通信数据量过大

所以，我们想要得到为什么会出现 ANR，就必须对于原理了解清楚，且知道有多少情况会导致出现事件被拉长的问题。

系统对 ANR 的捕捉原理

在网上有很多分析 ANR 的文章都都将 ANR 触发过程理解为装炸弹和拆炸弹的过程，但说到本质上，系统内部对于 ANR 的触发流程其实也很简单，ANR 也是建立在主线程 Looper 机制上的，简单理解就是 先发送一个延时消息，然后在特定位置移除这个消息，如果消息没有被移除则证明整个流程出现问题，执行 ANR 处理。

触发 ANR 生成日志时，在不同的系统版本会有所不同，上图中是通过 ANRHelper 类处理 ANR 日志收集，在其他较低系统版本上是 AppErrors 类处理 ANR 日志收集。

如何分析 ANR

traces.txt 信息概览

当发生 ANR 时系统会在 /data/anr/ 目录额外生成一份 traces.txt 日志，方便我们可以了解到发生 ANR 时的基本信息和堆栈信息。

traces.txt 日志信息如下（以主线程为例）：

// main 代表的主线程
// Native 是线程状态
// 下面的是堆栈信息
"main" prio=5 tid=1 Native
  | group="main" sCount=1 dsCount=0 obj=0x73cff4c0 self=0xafa84400
  | sysTid=5790 nice=0 cgrp=top-app sched=1073741825/1 handle=0xb2717534
  | state=S schedstat=( 3240607247 80660807 2053 ) utm=283 stm=41 core=1 HZ=100
  | stack=0xbe7c1000-0xbe7c3000 stackSize=8MB
  | held mutexes=
  kernel: (couldn't read /proc/self/task/5790/stack)
  native: #00 pc 00048968  /system/lib/libc.so (__ioctl+8)
  native: #01 pc 0001b0cf  /system/lib/libc.so (ioctl+38)
  native: #02 pc 0003cd25  /system/lib/libbinder.so (_ZN7android14IPCThreadState14talkWithDriverEb+168)
  native: #03 pc 0003d737  /system/lib/libbinder.so (_ZN7android14IPCThreadState15waitForResponseEPNS_6ParcelEPi+238)
  native: #04 pc 0003662d  /system/lib/libbinder.so (_ZN7android8BpBinder8transactEjRKNS_6ParcelEPS1_j+36)
  native: #05 pc 000999cf  /system/lib/libandroid_runtime.so (???)
  native: #06 pc 00607b09  /system/framework/arm/boot-framework.oat (Java_android_os_BinderProxy_transactNative__ILandroid_os_Parcel_2Landroid_os_Parcel_2I+140)
  at android.os.BinderProxy.transactNative(Native method)
  at android.os.BinderProxy.transact(Binder.java:930)
  at android.view.IWindowSession$Stub$Proxy.remove(IWindowSession.java:924)
  at android.view.ViewRootImpl.dispatchDetachedFromWindow(ViewRootImpl.java:3306)
  at android.view.ViewRootImpl.doDie(ViewRootImpl.java:5961)
  - locked <0x0ed5befa> (a android.view.ViewRootImpl)
  at android.view.ViewRootImpl.die(ViewRootImpl.java:5938)
  at android.view.WindowManagerGlobal.removeViewLocked(WindowManagerGlobal.java:459)
  at android.view.WindowManagerGlobal.removeView(WindowManagerGlobal.java:397)
  - locked <0x05ba7d9d> (a java.lang.Object)
  at android.view.WindowManagerImpl.removeViewImmediate(WindowManagerImpl.java:126)
  at d.h.b.q.n.a$c.removeViewImmediate(SourceFile:1)
  at android.widget.Toast$TN.handleHide(Toast.java:496)
  at android.widget.Toast$TN$2.handleMessage(Toast.java:346)
  at android.os.Handler.dispatchMessage(Handler.java:102)
  at android.os.Looper.loop(Looper.java:154)
  at android.app.ActivityThread.main(ActivityThread.java:6193)
  at java.lang.reflect.Method.invoke!(Native method)
  at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:886)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:776)

关键信息	描述
main	main 标识是主线程。在 traces.txt 中如果是线程会命名为 “thread-x” 的格式，x 表示线程 id，逐步递增
prio	线程优先级，默认是 5
tid	tid 不是线程的 id，是线程唯一标识 id
group	线程组名称
sCount	该线程被挂起的次数
dsCount	线程被调试器挂起的次数
obj	对象地址
self	该线程 native 的地址
sysTid	线程号（主线程的线程号和进程号相同）
nice	线程的调度优先级
sched	分别标志了线程的调度策略和优先级
cgrp	调度归属组
handle	线程处理函数的地址
state	调度状态
schedstat	从 /proc/[pid]/task/[tid]/schedstat 读出，三个值分别表示线程在 cpu 上执行的时间、线程的等待时间和线程执行的时间片长度，不支持这项信息的三个值都是 0
utm	线程用户态下使用的时间值（单位是 jiffies）
stm	内核态下的调度时间值
core	最后执行这个线程的 cpu 核的序号

线程状态	说明	描述
UNDEFINED = -1
ZOMBIE = 0	TERMINATED	线程已经终止
RUNNING = 1	RUNNABLE or running now	正常运行
TIMED_WAIT = 2	TIMED_WAITING Object.wait()	等待，一般是调用 Object.wait(2000)
MONITOR = 3	BLOCKED on a monitor	synchronized
WAIT = 4	WAITING in Object.wait()	调用 Object.wait() 或 LockSupport.park() 等待
INITIALIZING = 5	allocated, not yet running	已经初始化线程，但是还没有进行 start
STARTING = 6	started, not yet on thread list	已经 start 但是没有 run
NATIVE = 7	off in a JNI native method	native 线程出问题，有三种常见情况： 1、项目自己有 JNI 开发线程 2、有 IO 操作（IO 的本质是调用 Linux 内核的函数） 3、AQS 锁住了
VMWAIT = 8	waiting on a VM resource	没有时间片
SUSPENDED = 9	suspended，usually by GC or debugger	被 GC 挂起的（该情况发生的可能性不高）
Blocked		死锁（查看 CPU usage 会发现几乎都是 0%，这也是死锁的体现）

其中线程状态和堆栈信息是我们最关心的，它能够帮助我们快速定位到具体位置（堆栈信息有我们应用的函数调用的话）。

日志分析思路

日志分析思路主要可以分为四个步骤：

• ANR 日志准备（traces.txt + mainlog）

• 在 traces.txt 找到 ANR 信息（发生 ANR 时间节点、主线程状态、事故点、ANR 类型）

• 在 mainlog 日志分析发生 ANR 时的 CPU 状态

• 在 traces.txt 分析发生 ANR 时的 GC 情况（分析内存）

ANR 日志准备（traces.txt + mainlog）

在发生 ANR 的时候，系统会收集 ANR 相关的信息提供给开发者：

• 发生 ANR 时会收集 trace 信息能找到各个线程的执行情况和 GC 信息，trace 文件保存在 /data/anr/traces.txt

• 在 mainlog 日志中有 ANR 相关的信息和发生 ANR 时的 CPU 使用情况

简单说就是我们至少需要两份文件：/data/anr/traces.txt 和 mainlog 日志。如果有 eventlog 能更快的定位到 ANR 的类型，当然 traces.txt 和 mainlog 也能分析得到。

traces.txt 文件通过命令 adb pull /data/anr/ 获取。

mainlog 日志需要在程序运行时就时刻记录 adb logcat -v time -b main > mainlog.log。

在 traces.txt 找到 ANR 信息（发生 ANR 时间节点、主线程状态、事故点、ANR 类型）

当我们拿到 traces.txt 文件时，主要找四个信息：发生 ANR 时的时间节点、主线程状态（在文件中搜索 main）、ANR 类型、事故点（堆栈信息中找到我们应用中的函数）。

分析发生 ANR 时进程中各个线程的堆栈，一般有几种情况：

• 主线程状态是 Runnable 或 Native，堆栈信息中有我们应用中的函数，则很有可能就是执行该函数时候发生了超时

• 主线程状态是 Block，非常明显的线程被锁，这时候可以看是被哪个线程锁了，可以考虑优化代码，如果是死锁问题，就更需要及时解决了

• 由于抓 trace 的时刻很有可能耗时操作已经执行完了（ANR -> 耗时操作执行完毕 -> 系统抓 trace），这时候的 trace 就没有什么用了（在堆栈信息找不到我们应用的函数调用）

/data/anr/traces.txt

// 发生 ANR 时的时间节点
----- pid 5790 at 2022-05-23 10:21:32 -----

// 主线程状态
"main" prio=5 tid=1 Waiting

// 事故点
// 不一定能找到我们应用的调用函数，因为抓 trace 的时候耗时操作可能已经执行完了，例如下面的堆栈
at android.os.BinderProxy.transactNative(Native method)
at android.os.BinderProxy.transact(Binder.java:930)
at android.view.IWindowSession$Stub$Proxy.remove(IWindowSession.java:924)
at android.view.ViewRootImpl.dispatchDetachedFromWindow(ViewRootImpl.java:3306)
at android.view.ViewRootImpl.doDie(ViewRootImpl.java:5961)
- locked <0x0ed5befa> (a android.view.ViewRootImpl)
at android.view.ViewRootImpl.die(ViewRootImpl.java:5938)
at android.view.WindowManagerGlobal.removeViewLocked(WindowManagerGlobal.java:459)
at android.view.WindowManagerGlobal.removeView(WindowManagerGlobal.java:397)
- locked <0x05ba7d9d> (a java.lang.Object)
at android.view.WindowManagerImpl.removeViewImmediate(WindowManagerImpl.java:126)
at d.h.b.q.n.a$c.removeViewImmediate(SourceFile:1)
at android.widget.Toast$TN.handleHide(Toast.java:496)
at android.widget.Toast$TN$2.handleMessage(Toast.java:346)
at android.os.Handler.dispatchMessage(Handler.java:102)
at android.os.Looper.loop(Looper.java:154)
at android.app.ActivityThread.main(ActivityThread.java:6193)
at java.lang.reflect.Method.invoke!(Native method)
at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:886)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:776)

因为从上面的堆栈中其实不能分析到 ANR 类型，所以可以再借助 eventlog 或 mainlog 日志找到，可以在 mainlog 日志 搜索关键词 ANR in：

mainlog.log（对应的 adb logcat -v time -b main > mainlog.log）

05-23 10:21:38.029  2003  2016 E ActivityManager: ANR in com.example.demo (com.example.demo/.ui.login.LoginActivity)
05-23 10:21:38.029  2003  2016 E ActivityManager: PID: 5790
05-23 10:21:38.029  2003  2016 E ActivityManager: PSS: 42718 kB
05-23 10:21:38.029  2003  2016 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.)
05-23 10:21:38.029  2003  2016 E ActivityManager: Load: 16.16 / 10.88 / 4.95

在 eventlog 日志 搜索关键词 am_anr：

05-23 10:20:29.166  2003  2016 I am_anr  : [0,3392,com.example.demo,955792964,Input dispatching timed out (Waiting because no window has focus but there is a focused application that may eventually add a window when it finishes starting up.)]

在 mainlog 日志分析发生 ANR 时的 CPU 状态

在 mainlog 日志中根据 ANR 时间节点并 搜索关键词 CPU usage 查看发生 ANR 前后 CPU 的使用情况，从 CPU usage 信息中大概可以分析：

• 如果某些进程的 CPU 占用百分比较高，几乎占用了所有 CPU 资源，而发生 ANR 的进程（一般说的是我们的 app 进程）CPU 占用为 0% 或非常低，则认为 CPU 资源被占用，app 进程没有被分配足够的资源，从而发生了 ANR。这种情况多数可以认为是系统状态的问题，并不是由应用造成的（简单讲就是其他进程 CPU 使用率非常高自己低，就是系统资源分配不足导致）

• 如果发生 ANR 的进程（一般说的是我们的 app 进程）CPU 占用较高，如到了 80% 或 90% 以上，则可以怀疑应用内一些代码不合理消耗掉了 CPU 资源，如出现了死循环或者后台有许多线程执行任务等等原因，这就要结合 traces.txt 和 ANR 前后的 mainlog 日志进一步分析（简单理解就是 IO 非常频繁，要么死循环了，要么上锁了）

• 如果 CPU 总用量不高，该进程和其他进程的占用过高，这有一定概率是由于某些主线程的操作就是耗时过长，或者是由于主进程被锁造成的

mainlog.log

05-23 10:21:38.029  2003  2016 E ActivityManager: CPU usage from 2068ms to -8489ms ago (2022-05-23 10:21:27.434 to 2022-05-23 10:21:37.991):
05-23 10:21:38.029  2003  2016 E ActivityManager:   30% 2003/system_server: 16% user + 14% kernel / faults: 7835 minor 541 major
05-23 10:21:38.029  2003  2016 E ActivityManager:   13% 5790/com.example.demo: 9.2% user + 3.9% kernel / faults: 11775 minor 141 major
05-23 10:21:38.029  2003  2016 E ActivityManager:   5.4% 247/mmcqd/0: 0% user + 5.4% kernel
05-23 10:21:38.029  2003  2016 E ActivityManager:   5.4% 2591/com.xtc.i3launcher: 4.3% user + 1% kernel / faults: 4186 minor 276 major
05-23 10:21:38.029  2003  2016 E ActivityManager:   3.3% 36/kworker/u8:3: 0% user + 3.3% kernel
05-23 10:21:38.029  2003  2016 E ActivityManager:   2.9% 410/audioserver: 1.7% user + 1.2% kernel / faults: 79 minor 3 major
05-23 10:21:38.029  2003  2016 E ActivityManager:   2.8% 5754/com.netease.xtc.cloudmusic: 2.8% user + 0% kernel / faults: 1954 minor 315 major
05-23 10:21:38.029  2003  2016 E ActivityManager:   2.3% 2457/com.android.phone: 1.6% user + 0.7% kernel / faults: 2226 minor 513 major
05-23 10:21:38.029  2003  2016 E ActivityManager:   2.2% 35/kworker/u8:2: 0% user + 2.2% kernel
05-23 10:21:38.029  2003  2016 E ActivityManager:   2.2% 356/surfaceflinger: 0.9% user + 1.3% kernel / faults: 464 minor
05-23 10:21:38.029  2003  2016 E ActivityManager:   2.1% 110/kswapd0: 0% user + 2.1% kernel
05-23 10:21:38.029  2003  2016 E ActivityManager:   2% 448/kworker/u8:8: 0% user + 2% kernel
05-23 10:21:38.029  2003  2016 E ActivityManager:   1.9% 444/kworker/u8:7: 0% user + 1.9% kernel
05-23 10:21:38.029  2003  2016 E ActivityManager:   1.9% 4683/kworker/u8:9: 0% user + 1.9% kernel
05-23 10:21:38.029  2003  2016 E ActivityManager:   1.4% 4782/com.android.commands.monkey: 0.5% user + 0.8% kernel / faults: 1598 minor 3 major
05-23 10:21:38.029  2003  2016 E ActivityManager:   1.1% 299/logd: 0.5% user + 0.5% kernel / faults: 200 minor 115 major
05-23 10:21:38.029  2003  2016 E ActivityManager:   1.1% 3499/super_log: 0.2% user + 0.8% kernel / faults: 69 minor 1 major
05-23 10:21:38.029  2003  2016 E ActivityManager:   0.9% 7/rcu_preempt: 0% user + 0.9% kernel
05-23 10:21:38.029  2003  2016 E ActivityManager:   0.8% 2795/com.android.dialer: 0.7% user + 0% kernel / faults: 1270 minor 221 major
05-23 10:21:38.029  2003  2016 E ActivityManager:   0.4% 4696/mdss_fb0: 0% user + 0.4% kernel
05-23 10:21:38.029  2003  2016 E ActivityManager:   0.3% 12/ksoftirqd/1: 0% user + 0.3% kernel
05-23 10:21:38.029  2003  2016 E ActivityManager:   0.3% 20/ksoftirqd/3: 0% user + 0.3% kernel
05-23 10:21:38.029  2003  2016 E ActivityManager:   0.3% 258/core_ctl/0: 0% user + 0.3% kernel
05-23 10:21:38.029  2003  2016 E ActivityManager:   0.3% 2178/VosRXThread: 0% user + 0.3% kernel
05-23 10:21:38.029  2003  2016 E ActivityManager:   0.3% 2183/sdcard: 0% user + 0.3% kernel / faults: 42 minor 3 major
05-23 10:21:38.029  2003  2016 E ActivityManager:   0.2% 3/ksoftirqd/0: 0% user + 0.2% kernel
05-23 10:21:38.029  2003  2016 E ActivityManager:   0.2% 290/jbd2/mmcblk0p43: 0% user + 0.2% kernel
05-23 10:21:38.029  2003  2016 E ActivityManager:   0.1% 15/migration/2: 0% user + 0.1% kernel
05-23 10:21:38.029  2003  2016 E ActivityManager:   0.1% 16/ksoftirqd/2: 0% user + 0.1% kernel
05-23 10:21:38.029  2003  2016 E ActivityManager:   0.1% 19/migration/3: 0% user + 0.1% kernel
05-23 10:21:38.029  2003  2016 E ActivityManager:   0.1% 269/kworker/0:4: 0% user + 0.1% kernel
05-23 10:21:38.029  2003  2016 E ActivityManager:   0.1% 355/servicemanager: 0% user + 0% kernel / faults: 68 minor
05-23 10:21:38.029  2003  2016 E ActivityManager:   0% 1//init: 0% user + 0% kernel / faults: 6 minor 4 major
05-23 10:21:38.029  2003  2016 E ActivityManager:   0% 5/kworker/0:0H: 0% user + 0% kernel
05-23 10:21:38.029  2003  2016 E ActivityManager:   0% 8/rcu_sched: 0% user + 0% kernel
05-23 10:21:38.029  2003  2016 E ActivityManager:   0% 10/migration/0: 0% user + 0% kernel
05-23 10:21:38.029  2003  2016 E ActivityManager:   0% 11/migration/1: 0% user + 0% kernel
05-23 10:21:38.029  2003  2016 E ActivityManager:   0% 14/kworker/1:0H: 0% user + 0% kernel
05-23 10:21:38.029  2003  2016 E ActivityManager:   0% 135/mdp3_ppp: 0% user + 0% kernel
05-23 10:21:38.029  2003  2016 E ActivityManager:   0% 223/irq/114-5-0024: 0% user + 0% kernel
05-23 10:21:38.029  2003  2016 E ActivityManager:   0% 271/kworker/0:1H: 0% user + 0% kernel
05-23 10:21:38.029  2003  2016 E ActivityManager:   0% 276/kworker/3:3: 0% user + 0% kernel
05-23 10:21:38.029  2003  2016 E ActivityManager:   0% 309/debuggerd: 0% user + 0% kernel / faults: 237 minor 27 major
05-23 10:21:38.029  2003  2016 E ActivityManager:   0% 415/media.extractor: 0% user + 0% kernel / faults: 117 minor 66 major
05-23 10:21:38.029  2003  2016 E ActivityManager:   0% 419/netd: 0% user + 0% kernel / faults: 134 minor 2 major
05-23 10:21:38.029  2003  2016 E ActivityManager:   0% 2177/VosTXThread: 0% user + 0% kernel
05-23 10:21:38.029  2003  2016 E ActivityManager:   0% 2713/com.xtc.i3launcher:push: 0% user + 0% kernel / faults: 955 minor 58 major
05-23 10:21:38.029  2003  2016 E ActivityManager:   0% 2767/perffeedbackd: 0% user + 0% kernel / faults: 77 minor
05-23 10:21:38.029  2003  2016 E ActivityManager:   0% 4546/kworker/1:3: 0% user + 0% kernel
05-23 10:21:38.029  2003  2016 E ActivityManager: 84% TOTAL: 14% user + 17% kernel + 51% iowait + 0.6% softirq

发生死锁时的 CPU 状态如下：

在 traces.txt 分析发生 ANR 时的 GC 情况（分析内存）

当上面分析了 CPU 状态后发现是非 CPU 问题时，就需要从内存 GC 分析，因为 GC 会触发 STW（Stop The World）导致线程执行时间被拉长。

// 这里只截取了一部分 GC 信息
// 如果还有其他信息，还需要分析如 GC 回收率等，下面的 GC 信息是正常的，这里仅用于展示
Total time waiting for GC to complete: 64.298ms
Total GC count: 30
Total GC time: 4.961s
Total blocking GC count: 1
Total blocking GC time: 149.286ms

小结

其实 ANR 问题主要就是两类问题：

• CPU 问题

• GC 问题

所以定位 ANR 总的来说就是：

• 判定是否为 CPU 问题：常见的是在主线程事件发生

• 如果非 CPU 问题，再去定位 GC 问题

• GC 问题直接去看 traces.txt 上面的 GC 信息

  • 常规 GC 导致的问题，就是有频繁的对象创建

  • 常规少量数据不会出现有这个问题，但是数据量异常将会引发连锁反应，ANR 是结果的体现，具体体现是卡顿和内存泄漏

ANR 案例分析

ANR 案例分析一

具备的日志文件：eventlog、traces.txt、mainlog。

1、查看 eventlog 日志搜索关键词 “am_anr“，找到出现 ANR 的时间节点、进程 pid、ANR 类型

07-20 15:36:36.472 1000 1520 1597 I am_anr :[0, 1480,com.xxxx.mobile,952680005,Input dispatching timed out(AppWindowToken{da8f666 token=Token{5501f51 ActivityRecord{15c5c78 u0 com.xxxx.mobile/.ui.MainActivity t3862}}}, Waiting because no window has focus but there is a focused application that may eventually add a window when it finishes starting up.)]

从上面的 log 可以看出，应用 com.xxxx.mobile 在 07-20 15:36:36.472 发生了一次 KeyDispatchTimeout 类型的 ANR，它的进程号是 1480。把关键信息梳理一下：

• ANR 时间节点：07-20 15:36:36.472

• 进程 pid：1480

• 进程名：com.xxxx.mobile

• ANR 类型：KeyDispatchTimeout

2、查看 mainlog 日志分析发生 ANR 之前的做了什么事情

我们已经知道了发生 KeyDispatchTimeout 的 ANR 是因为 input 事件在 5s 内没有处理完成。那么在时间 07-20 15:36:36.472 的前 5s 也就是 15:36:30~15:36:31 时间段左右程序到底做了什么事情？既然已经知道 pid，从 mainlog 再搜索下 pid=1480 的日志找到该进程所运行的轨迹：

07-20 15:36:29.749 10102 1480 1737 D mobile-Application:[Thread:17329] receive an intent from server, action=com.ttt.push.RECEIVE_MESSAGE
07-20 15:36:30.136 10102 1480 1737 D mobile-Application:receiving an empty message, drop
07-20 15:36:35.791 10102 1480 1766 I Adreno :QUALCOMM build			:9c9b012, I92eb381bc9
07-20 15:36:35.791 10102 1480 1766 I Adreno :Build Date			:12/31/17
07-20 15:36:35.791 10102 1480 1766 I Adreno :OpenGL ES Shader Compiler Version: EV031.22.00.01
07-20 15:36:35.791 10102 1480 1766 I Adreno :Local Branch		 :
07-20 15:36:35.791 10102 1480 1766 I Adreno :Remote Branch			:refs/tags/AU_LINUX_ANDROID_LA.UM.6.4.R1.08.00.00.309.049
07-20 15:36:35.791 10102 1480 1766 I Adreno :Remote Branch			:NONE
07-20 15:36:35.791 10102 1480 1766 I Adreno :Reconstruct Branch		 :NOTHING
07-20 15:36:35.826 10102 1480 1766 I vndksupport: sphal namespace is not configured for this process. Loading /vendor/lib64/hw/gralloc.msm8998.so from the current namespace instead.
07-20 15:36:36.682 10102 1480 W ViewRootImpl[MainActivity]: Cancelling event due to no window focus: KeyEvent { action=ACTION_UP, keyCode=KEYCODE_PERIOD, scanCode=0, metaState=0, flags=0x28, repeatCount=0, eventTime=16099429, downTime=16099429, deviceId=-1, source=0x101 }

从上面我们知道，在时间 07-20 15:36:29.749 程序收到了一个 action 消息：

07-20 15:36:29.749 10102 1480 1737 D mobile-Application:[Thread:17329] receive an intent from server, action=com.ttt.push.RECEIVE_MESSAGE

应用 com.xxxx.mobile 收到了一个推送消息 com.ttt.push.RECEIVE_MESSAGE 导致了阻塞。

我们再串联一下目前所获取到的信息：在时间 07-20 15:36:29.749 应用 com.xxxx.mobile 收到了一个推送消息 action=com.ttt.push.RECEIVE_MESSAGE 发生阻塞，5s 后发生了 KeyDispachTimeout 的 ANR。

3、查看 mainlog 日志分析 CPU 状态

虽然知道了从什么时候开始 ANR 的，但是具体原因还没有找到，是不是当时 CPU 很紧张、各路 app 在抢占资源？所以从 mainlog 继续分析 CPU 信息。搜索关键词 ANR in：

07-20 15:36:58.711 1000 1520 1597 E ActivityManager: ANR in com.xxxx.mobile(com.xxxx.mobile/.ui.MainActivity)
07-20 15:36:58.711 1000 1520 1597 E ActivityManager: PID: 1480
07-20 15:36:58.711 1000 1520 1597 E ActivityManager: Reason: Input dispatching timed out(AppWindowToken{da8f666 token=Token{5501f51 ActivityRecord{15c5c78 u0 com.xxxx.mobile/.ui.MainActivity t3862}}}, Waiting because no window has focus but there is a focused application that may eventually add a window when it finishes starting up.)
07-20 15:36:58.711 1000 1520 1597 E ActivityManager: Load: 0.0 / 0.0 / 0.0
07-20 15:36:58.711 1000 1520 1597 E ActivityManager: CPU usage from 20ms to 20286ms later(2018-07-20 15:36:36.120 to 2018-07-20 15:36:56.426)
07-20 15:36:58.711 1000 1520 1597 E ActivityManager:  42% 6774/pressure: 41% user + 1.4% kernal / faults: 168 minor
07-20 15:36:58.711 1000 1520 1597 E ActivityManager:  34% 142/kswapd0: 0% user + 34% kernal
07-20 15:36:58.711 1000 1520 1597 E ActivityManager:  31% 1520/system_server: 13% user + 18% kernal / faults: 58724 minor 1585 major
07-20 15:36:58.711 1000 1520 1597 E ActivityManager:  13% 29901/com.ss.android.article.news: 7.7% user + 6% kernal / faults: 48999 minor 1540 major
07-20 15:36:58.711 1000 1520 1597 E ActivityManager:  11% 1480/com.xxxx.mobile: 5.2% user + 6.3% kernal / faults: 76401 minor 2422 major
07-20 15:36:58.711 1000 1520 1597 E ActivityManager:  8.2% 21000/kworker/u16:12: 0% user + 8.2% kernal
07-20 15:36:58.711 1000 1520 1597 E ActivityManager:  0.8% 724/mtd: 0% user + 0.8% kernal / faults: 1561 minor 9 major
07-20 15:36:58.711 1000 1520 1597 E ActivityManager:  8% 29704/kworker/u16:8: 0% user + 8% kernal
07-20 15:36:58.711 1000 1520 1597 E ActivityManager:  7.9% 24391/kworker/u16:18: 0% user + 7.9% kernal
07-20 15:36:58.711 1000 1520 1597 E ActivityManager:  7.1% 30656/kworker/u16:14: 0% user + 7.1% kernal
07-20 15:36:58.711 1000 1520 1597 E ActivityManager:  7.1% 9998/kworker/u16:4: 0% user + 7.1% kernal

上面的日志将 CPU 状态写的很清楚，这里再将需要分析的列出来：

// 进程名
07-20 15:36:58.711 1000 1520 1597 E ActivityManager: ANR in com.xxxx.mobile(com.xxxx.mobile/.ui.MainActivity) 
// 进程 pid
07-20 15:36:58.711 1000 1520 1597 E ActivityManager: PID: 1480 

// Load 表明是 1min/5min/15min CPU 的负载
07-20 15:36:58.711 1000 1520 1597 E ActivityManager: Load: 0.0 / 0.0 / 0.0

// com.xxxx.mobile 的 CPU 使用率是 11%，用户态使用率 5.2%，内核态使用率 6.3%
07-20 15:36:58.711 1000 1520 1597 E ActivityManager:  11% 1480/com.xxxx.mobile: 5.2% user + 6.3% kernal / faults: 76401 minor 2422 major

com.xxxx.mobile 占用了 11% 的 CPU，其实这并不算多，现在的手机基本都是多核 CPU，假如你的 CPU 是 4 核，那么上限是 400%，以此类推。

4、查看 traces.txt 日志分析具体发生 ANR 的位置

当 app 不响应、响应慢了或者 WatchDog 的监视没有得到回应时，系统会 dump 出一个 traces.txt 文件存放在 /data/anr/traces.txt，通过 traces.txt 文件，我们可以拿到线程名、堆栈信息、线程当前状态、binder call 等信息。通过命令 adb pull /data/anr/ 获取。

Cmd line:com.xxxx.mobile

"main" prio=5 tid=1 Runnable
 | group="main" sCount=0 dsCount=0 obj=0x73bcc7d0 self=0x7f20814c00
 | sysTid=20176 nice=-10 cgrp=default sched=0/0 handle=0x7f251349b0
 | state=R schedstat=( 0 0 0 ) utm=12 stm=3 core=5 HZ=100
 | stack=0x7fdb75e000-0x7fdb760000 stackSize=8MB
 | held mutexes="mutator lock"(shared held)
 at ttt.push.InterceptorProxy.addMiuiApplication(InterceptorProxy.java:77)
 at ttt.push.InterceptorProxy.create(InterceptorProxy.java:59)
 at android.app.Activity.onCreate(Activity.java:1041)
 at miui.app.Activity.onCreate(SourceFile:47)
 at com.xxxx.mobile.ui.b.onCreate(SourceFile:172)
 at com.xxxx.mobile.ui.MainActivity.onCreate(SourceFile:68)
 at android.app.Activity.performCreate(Activity.java:7050)
 at android.app.Instrumentation.callActivityOnCreate(Instrumentation.java:1214)
 at android.app.ActivityThread.performLaunchActivity(ActivityThread.java:2807)
 at android.app.ActivityThread.handleLaunchActivity(ActivityThread.java:2929)
 at android.app.ActivityThread.-wrap11(ActivityThread.java:-1)
 at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1618)
 at android.os.Handler.dispatchMessage(Handler.java:105)
 at android.os.Looper.loop(Looper.java:171)
 at android.app.ActivityThread.main(ActivityThread.java:6699)
 at java.lang.reflect.Method.invoke(Native method)
 at com.android.internal.os.Zygote$MethodAndArgsCaller.run(Zygote.java:246)
 at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:783)

从堆栈信息中能够看到有我们应用的代码：

at ttt.push.InterceptorProxy.addMiuiApplication(InterceptorProxy.java:77)

找到了具体代码的位置并修复。

ANR 案例分析二

1、查看 traces.txt 日志找到发生 ANR 的时间节点、主线程状态、ANR 类型、事故点

根据上面的信息梳理下信息：

• ANR 时间节点：2022-04-02 11:20:17

• 主线程状态：Runnable

• ANR 类型：堆栈信息是 dispatchTouchEvent，大致判断是事件导致

• 事故点：com.jideos.module_main.view.DragScrollBar.moveListView()

2、查看 mainlog 日志分析 CPU 状态

搜索关键词 ANR in：

CPU 状态该进程总共占 27%，其中用户态占用 22%，内核态占用 4.6%（内核态能说明是否是 IO 过多）。

如果 CPU 占用 40% 左右就要考虑 CPU 消耗过高了。

根据上面的分析，CPU 状态整体是正常的，排除掉 IO、死锁导致的问题。

3、查看 traces.txt 日志分析 GC（是否是内存问题）

• 320 个 GC 循环中的平均主 GC 回收字节率 0.0731004

• 323 个主要 GC 上的平均主要 GC 复制活动字节比 0.862705

• 年轻代并发复制总时间 20.267s，平均时间 84.802ms

• 239 个周期的平均次要 GC 回收字节率 0.169567（按次算）

• 峰值区域分配 464（116MB）/ 2048（512MB），将近满值

• 总 GC 次数 559 次（也就是 559 次 STW）

• 总 GC 时间 83.285s

• 总 GC 阻塞次数 279 次

• 总 GC 阻塞时间 52.749s

根据上面的信息其实基本可以判定 GC 是不正常的，对象的回收率不高，而且 GC 次数过多，GC 时间很长，应用程序在非常频繁的 GC，内存不足才会频繁的 GC，所以可以断定是有大对象创建或内存泄漏了导致的内存不足，频繁 GC 触发 STW（Stop The World）拉长了线程执行时间导致 ANR。

4、结合项目代码和分析到的原因定位修复 ANR

难定位的 ANR 问题整理

• 主线程被其他线程 lock 导致死锁
  
• 主线程做耗时操作，比如数据库读写
  
• binder 数据量过大
  
• binder 通信失败
  

ANR 解决方案

• 将所有耗时操作如访问网络、socket 通信、查询大量 SQL 语句、复杂逻辑计算等都放在子线程中，然后通过 handler.sendMessage、runOnUIThread 等方式更新 UI。无论如何都要确保用户界面的流畅度，如果耗时操作需要让用户等待，可以在界面上显示进度条

• 将 IO 操作放在异步线程。在一些同步的操作主线程有可能被锁，需要等待其他线程释放响应锁才能继续执行，这样会有一定的 ANR 风险，对于这种情况有时也可以用异步线程来执行相应的逻辑，另外，要避免死锁的发生

• 使用 Thread 或 HandlerThread 时，调用 Process.setThreadPriority（Process.THREAD_PRIORITY_BACKGROUND）设置优先级，否则仍然会降低程序响应，因为默认 Thread 优先级和主线程相同

• 使用 Handler 处理工作线程结果，而不是使用 Thread.wait() 或 Thread.sleep() 来阻塞主线程

• Activity 的 onCreate() 和 onResume() 回调中避免耗时代码

• BroadcastReceiver 中 onReceive() 代码也要尽量减少耗时，建议使用 IntentService 处理

• 各个组件的生命周期函数都不应该有太耗时的操作，即使对于后台 Service 或 ContentProvider 来讲，虽然应用在后台运行时生命周期函数不会有用户输入引起无响应的 ANR，但其执行时间过长也会引起 Service 或 ContentProvider 的 ANR

以上的常规解决方案实际上只有一个核心，就是降低线程阻塞时间，将耗时操作放到子线程处理。

ANR 监控方案

FileObserver

FileObserver 可以做到指定文件目录的监控功能，我们可以使用它实现监控 /data/anr 目录，当该目录有变动时即说明发生了 ANR。

public class ANRFileObserver extends FileObserver {
    private static final String TAG = "ANRFileObserver";

    public ANRFileObserver(String path) {
        super(path);
    }

    @Override
    public void onEvent(int event, @Nullable String path) {
        switch (event) {
            case FileObserver.ACCESS: // 文件被访问
                Log.i(TAG, "ACCESS = " + path);
                break;
            case FileObserver.ATTRIB: // 文件属性被修改，如 chmod、chown、touch 等
                Log.i(TAG, "ATTRIB = " + path);
                break;
            case FileObserver.CLOSE_NOWRITE: // 不可写文件被 close
                Log.i(TAG, "CLOSE_NOWRITE = " + path);
                break;
            case FileObserver.CREATE: // 创建新文件
                Log.i(TAG, "CREATE = " + path);
                break;
            case FileObserver.DELETE: // 文件被删除
                Log.i(TAG, "DELETE = " + path);
                break;
            case FileObserver.DELETE_SELF: // 自删除，即一个可执行文件在执行时删除自己
                Log.i(TAG, "DELETE_SELF = " + path);
                break;
            case FileObserver.MODIFY: // 文件被修改
                Log.i(TAG, "MODIFY = " + path);
                break;
            case FileObserver.MOVE_SELF: // 自移动，即一个可执行文件在执行时移动自己
                Log.i(TAG, "MOVE_SELF = " + path);
                break;
            case FileObserver.MOVED_FROM: // 文件被移走
                Log.i(TAG, "MOVED_FROM = " + path);
                break;
            case FileObserver.MOVED_TO: // 文件被移动过来
                Log.i(TAG, "MOVED_TO = " + path);
                break;
            case FileObserver.OPEN: // 文件被打开
                Log.i(TAG, "OPEN = " + path);
                break;
            default:
                Log.i(TAG, "event = " + event + ", path = " + path);
                break;
        }
    }
}

ANRFileObserver fileObserver = new ANRFileObserver("/data/anr");
fileObserver.startWatching();

但是该监控方案也有弊端导致适配性不是很好：

• /data/anr/ 目录可能会因为厂商定制化没有权限无法访问

• 应用被杀死时可能无法及时的监控

ANR WatchDog

Android 基于 Looper 的方案写了一个 WatchDog 监控，同样的也是通过 Handler post 消息检测时间，相关流程如下：

我们也可以参考 WatchDog 的源码和原理自定义一个监控 ANR 的 WatchDog，事件 ANR 是 5s 无响应，那就设定每 5s 从 Looper 插一条消息，如果 5s 后还没执行完成就说明出现了 ANR。具体代码如下：

public class ANRWatchDog extends Thread {
    private static final String TAG = "ANRWatchDog";
    private static final int TIMEOUT = 5000;

    private static ANRWatchDog sWatchDog;

    private final Handler mMainHandler = new Handler(Looper.getMainLooper());

    private final ANRChecker mAnrChecker = new ANRChecker();

    private ANRListener mAnrListener;

    private ANRWatchDog() {
        super("ANR-WatchDog-Thread");
    }

    public static ANRWatchDog getInstance() {
        if (sWatchDog == null) {
            sWatchDog = new ANRWatchDog();
        }
        return sWatchDog;
    }

    @Override
    public void run() {
        // 设置为后台线程
        Process.setThreadPriority(Process.THREAD_PRIORITY_BACKGROUND);
        while (true) {
            synchronized (this) {
                // 开始计时，往主线程 Looper 插一条消息
                mAnrChecker.schedule();
                // 每 5s 循环一次
                long waitTime = TIMEOUT;
                long start = SystemClock.uptimeMillis();
                while (waitTime > 0) { // 避免提前唤醒，保证 5s 检测一次
                    try {
                        wait(waitTime);
                    } catch (InterruptedException e) {
                        Log.w(TAG, e.toString());
                    }
                    waitTime = TIMEOUT - (SystemClock.uptimeMillis() - start);
                }
                // 没有超时 5s，继续循环
                if (!mAnrChecker.isBlocked()) {
                    continue;
                }
            }

            // 响应超过 5s 认为已经发生了 ANR，将堆栈信息打印出来
            String stackTrace = getStackTraceInfo();
            if (mAnrListener != null) {
                mAnrListener.onAnrHappened(stackTrace);
            }
            mAnrListener = null;
            break;
        }
    }

    private String getStackTraceInfo() {
        StringBuilder sb = new StringBuilder();
        for (StackTraceElement element : Looper.getMainLooper().getThread().getStackTrace()) {
            sb.append(element.toString()).append("\r\n");
        }
        return sb.toString();
    }

    private class ANRChecker implements Runnable {
        private boolean completed;
        private long startTime;
        private long executeTime = SystemClock.uptimeMillis();

        @Override
        public void run() {
            synchronized (ANRWatchDog.this) {
                completed = true; // 执行完修改标志位
                executeTime = SystemClock.uptimeMillis();
            }
        }

        void schedule() {
            completed = false;
            startTime = SystemClock.uptimeMillis();
            mMainHandler.postAtFrontOfQueue(this); // 往主线程 Looper 插入一条消息
        }

        // 如果标志位是 false 或响应时间超过 5s
        boolean isBlocked() {
            return !completed || executeTime - startTime >= TIMEOUT;
        }
    }

    public ANRWatchDog setANRListener(ANRListener listener) {
        mAnrListener = listener;
        return this;
    }

    public interface ANRListener {
        void onAnrHappened(String stackTrack);
    }
}

public class MainActivity extends AppCompatActivity {

    @Override
    protected void onCreate(@Nullable Bundle savedInstanceState) {
        super.onCreate(savedInstanceState);
        setContentView(R.layout.activity_main);

        ANRWatchDog.getInstance().setANRListener(new ANRWatchDog.ANRListener() {
            @Override
            public void onAnrHappened(String stackTrack) {
                Log.i("ANRWatchDog", "stack = " + stackTrack);
            }
        }).start();

        findViewById(R.id.btn).setOnClickListener(new View.OnClickListener() {
            @Override
            public void onClick(View v) {
                try {
                	// 模拟 anr
                    Thread.sleep(1000000);
                } catch (InterruptedException e) {
                    e.printStackTrace();
                }
            }
        });
    }
}

总结

ANR 定位分析总结如下：

• 在 traces.txt 找到发生 ANR 时间节点、主线程的状态、ANR 类型和事故点

• 在 mainlog 日志查看 CPU 状态

• 根据以上步骤收集的信息大致判断问题原因

  • 是 CPU 问题还是 非 CPU 问题

  • 如果是非 CPU 问题，那么看 GC 处理信息

• 在 traces.txt 分析 CG 信息

• 结合项目代码和以上步骤分析到的原因，定位到问题修复 ANR

其实 ANR 发生的原因本质上只有三个：

• 线程挂起

• CPU 不给资源

• GC 触发 STW 导致线程执行时间被拉长