android ANR 分析

最新推荐文章于 2024-09-06 08:00:00 发布

piao_xia

最新推荐文章于 2024-09-06 08:00:00 发布

阅读量232

点赞数

分类专栏： Android 文章标签： android ANR

Android 专栏收录该内容

2 篇文章 0 订阅

订阅专栏

什么是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 */