什么是ANR
ANR (“Application Not Responding”)——“应用没有响应”。
什么导致ANR
在Android中,应用程序是由Activity Manager和Window Manager系统服务监视的。当遇到下面任何一个情况中时,Android显示ANR:
- 主线程 (“事件处理线程” / “UI线程”) 在5秒内没有响应输入事件;
- BroadcastReceiver 没有在10秒内完成返回;
- Server没有在20秒内完成;
如何分析ANR问题
分析log文件
5009.8ms since event, 5009.5ms since waitstarted
04-0113:12:11.572 I/WindowManager( 220): Input event
dispatching timedout sending
tocom.android.email/com.android.email.activity.SplitScreenActivity
04-01 13:12:14.123 I/Process( 220): Sending signal. PID: 21404 SIG: 3**---发生ANR的时间和生成trace.txt的时间**
04-01 13:12:14.123 I/dalvikvm(21404):threadid=4: reacting to
signal 3
……
04-0113:12:15.872 E/ActivityManager( 220): ANR in
com.android.email(com.android.email/.activity.SplitScreenActivity)
04-0113:12:15.872 E/ActivityManager( 220):
Reason:keyDispatchingTimedOut
04-0113:12:15.872 E/ActivityManager( 220): Load: 8.68 / 8.37 / 8.53 **---5分钟,10分钟,15分钟内的平均负载分别为:8.68 , 8.37 , 8.53**
04-0113:12:15.872 E/ActivityManager( 220): CPUusage from 4361ms to 699ms ago **----CPU在ANR发生前的使用情况**
04-0113:12:15.872 E/ActivityManager( 220): 5.5%21404/com.android.email: 1.3% user + 4.1% kernel / faults:
10 minor
04-0113:12:15.872 E/ActivityManager( 220): 4.3%220/system_server: 2.7% user + 1.5% kernel / faults: 11
minor 2 major
04-0113:12:15.872 E/ActivityManager( 220): 0.9%52/spi_qsd.0: 0% user + 0.9% kernel
04-0113:12:15.872 E/ActivityManager( 220): 0.5%65/irq/170-cyttsp-: 0% user + 0.5% kernel
04-0113:12:15.872 E/ActivityManager( 220): 0.5%296/com.android.systemui: 0.5% user + 0% kernel
04-0113:12:15.872 E/ActivityManager( 220): 100%TOTAL: 4.8% user + 7.6% kernel + 87% iowait**--cpu使用情况**
04-0113:12:15.872 E/ActivityManager( 220): CPUusage from 3697ms to 4223ms later:-- ANR后CPU的使用量
04-0113:12:15.872 E/ActivityManager( 220): 25%21404/com.android.email: 25% user + 0% kernel / faults: 191 minor
04-0113:12:15.872 E/ActivityManager( 220): 16% 21603/__eas(par.hakan: 16% user + 0% kernel
04-0113:12:15.872 E/ActivityManager( 220): 7.2% 21406/GC: 7.2% user + 0% kernel
04-0113:12:15.872 E/ActivityManager( 220): 1.8% 21409/Compiler: 1.8% user + 0% kernel
04-0113:12:15.872 E/ActivityManager( 220): 5.5%220/system_server: 0% user + 5.5% kernel / faults: 1 minor
04-0113:12:15.872 E/ActivityManager( 220): 5.5% 263/InputDispatcher: 0% user + 5.5% kernel
04-0113:12:15.872 E/ActivityManager( 220): 32%TOTAL: 28% user + 3.7% kernel
从LOG可以看出ANR的类型,CPU的使用情况,如果CPU使用量接近100%,说明当前设备很忙,有可能是CPU饥饿导致了ANR
如果CPU使用量很少,说明主线程被BLOCK了
如果IOwait很高,说明ANR有可能是主线程在进行I/O操作造成的
分析trace文件
在service中出现了阻塞,阻塞的原因是多线程死锁导致。
"BT EventLoop" prio=5 tid=39 MONITOR
| group="main" sCount=1 dsCount=0 obj=0x40760918 self=0x5a0698
| sysTid=26547 nice=0 sched=0/0 cgrp=[no-cpu-subsys] handle=5900336
at android.server.BluetoothService.addRemoteDeviceProperties(BluetoothService.java:~1404)
- waiting to lock <0x405705e0> (a android.server.BluetoothService) held by threadid=9 (android.server.ServerThread)
at android.server.BluetoothEventLoop.addDevice(BluetoothEventLoop.java:143)
at android.server.BluetoothEventLoop.onDeviceFound(BluetoothEventLoop.java:174)
at dalvik.system.NativeStart.run(Native Method)
at dalvik.system.NativeStart.run(Native Method)
"Binder Thread #8" prio=5 tid=50 MONITOR
| group="main" sCount=1 dsCount=0 obj=0x40717e60 self=0x3e6660
| sysTid=506 nice=0 sched=0/0 cgrp=[no-cpu-subsys] handle=4088552
at android.server.BluetoothService.getBondState(BluetoothService.java:~1342)
- waiting to lock <0x405705e0> (a android.server.BluetoothService) held by threadid=9 (android.server.ServerThread)
at android.bluetooth.IBluetooth$Stub.onTransact(IBluetooth.java:237)
at android.os.Binder.execTransact(Binder.java:320)
at dalvik.system.NativeStart.run(Native Method)
"android.server.ServerThread" prio=5 tid=9 NATIVE
| group="main" sCount=1 dsCount=0 obj=0x4050fab8 self=0x2b7ef0
| sysTid=309 nice=-2 sched=0/0 cgrp=[no-cpu-subsys] handle=2850856
at android.server.BluetoothEventLoop.stopEventLoopNative(Native Method)
at android.server.BluetoothEventLoop.stop(BluetoothEventLoop.java:134)
at android.server.BluetoothService.finishDisable(BluetoothService.java:353)
at android.server.BluetoothService.access$200(BluetoothService.java:77)
at android.server.BluetoothService$1.handleMessage(BluetoothService.java:504)
at android.os.Handler.dispatchMessage(Handler.java:99)
at android.os.Looper.loop(Looper.java:130)
at com.android.server.ServerThread.run(SystemServer.java:563)
以上log可以看出,有多个线程被tid=9 阻塞,而线程tid =9 是要完成什么操作呢? 从stack trace可以看出是关闭蓝牙操作。 Tid 持有BluetoothService文件锁,最后是 stopEventLoopNative()本地调用。
其中两个线程tid=50和tid = 39, 都是要申请BluetoothService文件锁。 其中tid =39是处理设备查找到后的来自JNI层的回调操作: onDeviceFound()。通过分析BT JNI层的代码实现,可以发现此处发生了死锁。
备注:Thread状态
ThreadState (defined at “dalvik/vm/thread.h “)
THREAD_UNDEFINED = -1, /* makes enum compatible with int32_t */
THREAD_ZOMBIE = 0, /* TERMINATED */
THREAD_RUNNING = 1, /* RUNNABLE or running now */
THREAD_TIMED_WAIT = 2, /* TIMED_WAITING in Object.wait() */
THREAD_MONITOR = 3, /* BLOCKED on a monitor */
THREAD_WAIT = 4, /* WAITING in Object.wait() */
THREAD_INITIALIZING= 5, /* allocated, not yet running */
THREAD_STARTING = 6, /* started, not yet on thread list */
THREAD_NATIVE = 7, /* off in a JNI native method */
THREAD_VMWAIT = 8, /* waiting on a VM resource */
THREAD_SUSPENDED = 9, /* suspended, usually by GC or debugger */