盒子
盒子
文章目录
  1. 前言
  2. 引发 ANR 的原因
  3. 分析 ANR 的原因
    1. Logcat ANR Log
    2. traces.txt
  4. 参考文献

如何分析 ANR 的原因

2015.09.11 xiazdong  热度 ℃

前言

这个问题是面试的时候被问到的，问题原话：”怎么查看 ANR Log?”。

我们写程序其实并不仅仅是避免 ANR，而是要让应用体验”如丝般顺滑”。

引发 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
0% 6088/com.tencent.mm: 0% user + 0% kernel / faults: 12 minor
0% 10189/android.process.media: 0% user + 0% kernel / faults: 4 minor
0% 10582/kworker/u:0: 0% user + 0% kernel
0% 13795/com.android.packageinstaller: 0% user + 0% kernel
0% 27537/kworker/u:2: 0% user + 0% kernel
0% 31641/logcat: 0% user + 0% kernel
123% TOTAL: 67% user + 55% kernel + 0.9% iowait

这部分显示在 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 线程在等待主线程拥有的资源

参考文献

支持一下
扫一扫，支持xiazdong