深层分析Android 产生ANR 的原因

当用户的输入事件(Input Event，如按键或触摸)在5秒内得不到响应 或者 BroadcastReceiver 在 10秒内未做完，就会引发 ANR。一般来说，引起 ANR 的原因：

• 主线程有耗时的计算操作。
• 主线程在等待获取某个资源(可能是死锁)。
• 主线程睡眠太久。

简单地说就是主线程卡住了，导致用户的输入事件处理不了。

分析 ANR 的原因

当发生 ANR 时，我们可以从两部分查看原因：

• 初步：Logcat 的 ANR 日志查看 CPU 使用率。如果 CPU 使用率很高，表明有耗时计算。
• 深入：查看 “/data/anr/traces.txt” 文件。

Logcat ANR Log

这块日志主要分为三部分。

第一部分：

512-670/system_process E/ActivityManager﹕ ANR in me.xiazdong.anrdemo (me.xiazdong.anrdemo/.MainActivity)

Reason: keyDispatchingTimedOut

从上面看出导致 ANR 的原因是 “keyDispatchingTimeOut”。

第二部分：

CPU usage from 18523ms to 0ms ago with 99% awake:

16% 753/com.android.systemui: 13% user + 3.2% kernel / faults: 124 minor

13% 175/surfaceflinger: 4.2% user + 9% kernel / faults: 3572 minor

6.4% 512/system_server: 4.7% user + 1.7% kernel / faults: 850 minor

3% 256/adbd: 0.2% user + 2.8% kernel / faults: 1033 minor

1.1% 252/mpdecision: 0.1% user + 1% kernel

0.9% 6652/kworker/0:2: 0% user + 0.9% kernel

0.8% 1896/cn.ledongli.ldl: 0.6% user + 0.1% kernel / faults: 7 minor

0.8% 27946/kworker/0:3: 0% user + 0.8% kernel

0.7% 4711/kworker/u:3: 0% user + 0.7% kernel

0.5% 3059/com.jianshu.haruki:pushservice: 0.4% user + 0.1% kernel / faults: 24 minor

0.5% 3607/com.jianshu.haruki: 0.3% user + 0.1% kernel / faults: 2 minor

0.4% 172/netd: 0.2% user + 0.2% kernel

0.4% 168/vold: 0.3% user + 0% kernel

0.3% 127/ueventd: 0.2% user + 0.1% kernel

0.3% 305/sensors.qcom: 0.1% user + 0.2% kernel

0.1% 4157/com.ttyongche:ixintui_service_v1: 0.1% user + 0% kernel / faults: 13 minor

0.1% 8844/com.eg.android.AlipayGphone:push: 0.1% user + 0% kernel / faults: 18 minor

0% 114/irq/294-atmel_m: 0% user + 0% kernel

0.1% 167/servicemanager: 0% user + 0% kernel

0.1% 726/MC_Thread: 0% user + 0.1% kernel

0.1% 1024/com.android.deskclock: 0.1% user + 0% kernel / faults: 7 minor

0.1% 9357/com.taobao.taobao: 0% user + 0% kernel / faults: 4 minor

0% 13958/me.xiazdong.anrdemo: 0% user + 0% kernel / faults: 5 minor

0% 119/mmcqd/0: 0% user + 0% kernel

0% 134/jbd2/mmcblk0p26: 0% user + 0% kernel

0% 728/RX_Thread: 0% user + 0% kernel

0% 748/wpa_supplicant: 0% user + 0% kernel

0% 870/com.android.settings: 0% user + 0% kernel

0% 903/com.baidu.input_mi: 0% user + 0% kernel / faults: 13 minor

0% 997/com.miui.whetstone: 0% user + 0% kernel

0% 1301/com.miui.providers.weather: 0% user + 0% kernel

0% 3011/com.ttyongche:pushservice: 0% user + 0% kernel

0% 3152/com.ttyongche: 0% user + 0% kernel / faults: 3 minor

这部分显示在 ANR 发生之前 CPU 使用状况。

第三部分：

CPU usage from 3154ms to 3704ms later:

14% 753/com.android.systemui: 8.7% user + 5.2% kernel

14% 753/ndroid.systemui: 10% user + 3.5% kernel

1.7% 11566/GL updater: 0% user + 1.7% kernel

12% 175/surfaceflinger: 5.4% user + 7.2% kernel / faults: 108 minor

5.4% 467/SurfaceFlinger: 3.6% user + 1.8% kernel

1.8% 475/GL updater: 1.8% user + 0% kernel

1.8% 479/SurfaceFlinger: 0% user + 1.8% kernel

1.8% 480/EventThread: 0% user + 1.8% kernel

1.8% 914/Binder_2: 0% user + 1.8% kernel

1.8% 12653/Binder_5: 0% user + 1.8% kernel

12% 512/system_server: 5.4% user + 7.2% kernel / faults: 9 minor

7.2% 670/InputDispatcher: 0% user + 7.2% kernel

1.8% 656/UEventObserver: 0% user + 1.8% kernel

1.8% 1019/Binder_B: 1.8% user + 0% kernel

1.8% 5056/Binder_10: 1.8% user + 0% kernel

0.8% 252/mpdecision: 0% user + 0.8% kernel

1.6% 286/mpdecision: 0% user + 1.6% kernel

1.8% 256/adbd: 0% user + 1.8% kernel / faults: 18 minor

1.8% 256/adbd: 0% user + 1.8% kernel

0.8% 305/sensors.qcom: 0.8% user + 0% kernel

0.8% 478/sensors.qcom: 0.8% user + 0% kernel

0.9% 3059/com.jianshu.haruki:pushservice: 0.9% user + 0% kernel / faults: 2 minor

0.9% 3218/Thread-5534: 0.9% user + 0% kernel

0.9% 3607/com.jianshu.haruki: 0.9% user + 0% kernel

0.9% 3648/Thread-5534: 0.9% user + 0% kernel

1.3% 27946/kworker/0:3: 0% user + 1.3% kernel

13% TOTAL: 6.8% user + 6.8% kernel

这部分主要输出 ANR 这段时间内 CPU 使用状况，如果 CPU 使用率特别高，可能就能表明主线程有耗时的计算操作。

traces.txt

在查看文件内容之前，我们需要了解线程的所有状态。

• THREAD_ZOMBIE: 线程已经终止了。
• THREAD_RUNNING: 线程是 Runnable 的或者正在运行的。
• THREAD_TIMED_WAIT: 线程调用 Object.wait(long millis) 时阻塞。
• THREAD_MONITOR: 线程在获取锁时阻塞。
• THREAD_WAIT: 线程调用 Object.wait() 时阻塞。
• THREAD_INITIALIZING: 线程还没准备好，不能被运行。
• THREAD_STARTING: 线程还没准备好，不能被运行。
• THREAD_NATIVE: 线程在执行 Native Method。
• THREAD_VMWAIT: 线程在等待 VM 的资源。
• THREAD_SUSPENDED: 线程已经被挂起(暂停)，在等待被恢复(resume)。最典型的状况是GC线程在工作，主线程被挂起。

在 traces.txt 文件的开头就是最近这次 ANR 的日志。

这里我们通过几个例子来看看如何分析日志。

1、在按钮的 onClick() 中调用 Thread.sleep()，日志如下：

DALVIK THREADS (17):

"main" prio=5 tid=1 Sleeping ## 表示 ANR 时主线程处于 Sleeping 状态

| group="main" sCount=1 dsCount=0 obj=0x73258000 self=0xb4827800

| sysTid=21428 nice=0 cgrp=default sched=0/0 handle=0xb6f82bec

| state=S schedstat=( 162539642 60048744 257 ) utm=12 stm=4 core=1 HZ=100

| stack=0xbe009000-0xbe00b000 stackSize=8MB

| held mutexes=

at java.lang.Thread.sleep!(Native method) ## 通过该堆栈可以看出ANR的原因

- sleeping on <0x02b70dd5> (a java.lang.Object)

at java.lang.Thread.sleep(Thread.java:1031)

- locked <0x02b70dd5> (a java.lang.Object)

at java.lang.Thread.sleep(Thread.java:985)

at me.xiazdong.anrdemo.MainActivity.clickHandler(MainActivity.java:20)

at java.lang.reflect.Method.invoke!(Native method)

at java.lang.reflect.Method.invoke(Method.java:372)

at android.view.View$1.onClick(View.java:4015)

2、主线程和子线程产生死锁，日志如下：

"main" prio=5 tid=1 MONITOR ## MONITOR 表示线程是 BLOCKED 状态，即被阻塞住了。

| group="main" sCount=1 dsCount=0 obj=0x417bd700 self=0x400310b0

| sysTid=13958 nice=0 sched=0/0 cgrp=apps handle=1074507568

| schedstat=( 0 0 0 ) utm=25 stm=6 core=0

at me.xiazdong.anrdemo.MainActivity.clickHandler(MainActivity.java:~46) ## 发生问题的地方是 clickHandler 方法

- waiting to lock <0x425a0530> (a java.lang.Object) held by tid=11 (Thread-3849) ## 主线程正在等待 Thread-3849 线程拥有的资源

at java.lang.reflect.Method.invokeNative(Native Method)

at java.lang.reflect.Method.invoke(Method.java:511)

at android.view.View$1.onClick(View.java:3671)

----------------------------

"Thread-3849" prio=5 tid=11 MONITOR

| group="main" sCount=1 dsCount=0 obj=0x425e6150 self=0x67f36008

| sysTid=13992 nice=0 sched=0/0 cgrp=apps handle=1716642824

| schedstat=( 0 0 0 ) utm=0 stm=0 core=0

at me.xiazdong.anrdemo.MainActivity$1.run(MainActivity.java:~31)

- waiting to lock <0x425a0520> (a java.lang.Object) held by tid=1 (main) ## Thread-3849 线程在等待主线程拥有的资源

閱讀更多 消逝的初心 的文章

關鍵字: 中央处理器 Android 第二