ANR实例

什么是ANR？

以下四个条件都可以造成ANR发生：

InputDispatching Timeout：5秒内无法响应屏幕触摸事件或键盘输入事件

BroadcastQueue Timeout ：在执行前台广播（BroadcastReceiver）的onReceive()函数时10秒没有处理完成，后台为60秒。

Service Timeout ：前台服务20秒内，后台服务在200秒内没有执行完毕。

ContentProvider Timeout ：ContentProvider的publish在10s内没进行完。

常见的原因

    A.耗时操作，如复杂的layout，庞大的for循环，IO等。
	B.被Binder 对端block
	C.被子线程同步锁block
    D.Binder被占满导致主线程无法和SystemServer通信
	E.得不到系统资源（CPU/RAM/IO）
	其中ABCD比较好分析，而E比较困难。

1. 主线程耗时Blocked

07-17 03:27:58.860 13407 13499 I am_anr  : [0,19914,com.example.myapplication,550026822,Input dispatching timed out (Waiting to send non-key event because the touched window has not finished processing certain input events that were delivered to it over 500.0ms ago.  Wait queue length: 25.  Wait queue head age: 5552.3ms.)]

07-17 03:28:03.421 13407 13499 E ActivityManager: ANR in com.example.myapplication (com.example.myapplication/.MainActivity)
07-17 03:28:03.421 13407 13499 E ActivityManager: PID: 19914
07-17 03:28:03.421 13407 13499 E ActivityManager: Reason: Input dispatching timed out (Waiting to send non-key event because the touched window has not finished processing certain input events that were delivered to it over 500.0ms ago.  Wait queue length: 25.  Wait queue head age: 5552.3ms.)
07-17 03:28:03.421 13407 13499 E ActivityManager: Parent: com.example.myapplication/.MainActivity
07-17 03:28:03.421 13407 13499 E ActivityManager: Load: 6.17 / 5.78 / 5.21
07-17 03:28:03.421 13407 13499 E ActivityManager: CPU usage from 8084ms to 0ms ago (2020-07-17 03:27:50.711 to 2020-07-17 03:27:58.795):
07-17 03:28:03.421 13407 13499 E ActivityManager:   99% 19914/com.example.myapplication: 99% user + 0.1% kernel
07-17 03:28:03.421 13407 13499 E ActivityManager:   5.9% 13407/system_server: 3.8% user + 2.1% kernel / faults: 753 minor
07-17 03:28:03.421 13407 13499 E ActivityManager:   5.1% 294/irq/480-synapti: 0% user + 5.1% kernel
07-17 03:28:03.421 13407 13499 E ActivityManager:   3.3% 499/surfaceflinger: 1.6% user + 1.7% kernel
...
07-17 03:28:03.421 13407 13499 E ActivityManager: 53% TOTAL: 42% user + 9.6% kernel + 1.8% irq

----- pid 19914 at 2020-07-17 03:27:59 -----
Cmd line: com.example.myapplication

"main" prio=5 tid=1 Runnable
  | group="main" sCount=0 dsCount=0 flags=0 obj=0x71eccd98 self=0x7d670c2c00
  | sysTid=19914 nice=-10 cgrp=default sched=0/0 handle=0x7d6861aed0
  | state=R schedstat=( 9759243732 45112461 462 ) utm=969 stm=5 core=3 HZ=100
  | stack=0x7fd7004000-0x7fd7006000 stackSize=8192KB
  | held mutexes= "mutator lock"(shared held)
  at com.example.myapplication.MainActivity.startxxx(MainActivity.java:65)
  at java.lang.reflect.Method.invoke(Native method)
  at android.support.v7.app.AppCompatViewInflater$DeclaredOnClickListener.onClick(AppCompatViewInflater.java:385)
  at android.view.View.performClick(View.java:7140)
  at android.view.View.performClickInternal(View.java:7117)
  at android.view.View.access$3500(View.java:801)
  at android.view.View$PerformClick.run(View.java:27351)
  at android.os.Handler.handleCallback(Handler.java:883)
  at android.os.Handler.dispatchMessage(Handler.java:100)
  at android.os.Looper.loop(Looper.java:214)
  at android.app.ActivityThread.main(ActivityThread.java:7356)
  at java.lang.reflect.Method.invoke(Native method)
  at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:492)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:930)

public void startxxx(View v) {
    Log.d(TAG, "click");
    while (true) {

        int i = 1;
        i++;
}

2. Binder耗时Blocked

@event log
07-15 23:40:52.342   968  1273 I am_anr  : [0,3066,com.example.serviceclient,818462277,Input dispatching timed out (Waiting to send non-key event because the touched window has not finished processing certain input events that were delivered to it over 500.0ms ago.  Wait queue length: 37.  Wait queue head age: 5510.9ms.)]

@main log
07-15 23:40:57.485   968  1273 E ActivityManager: ANR in com.example.serviceclient (com.example.serviceclient/.MainActivity)
07-15 23:40:57.485   968  1273 E ActivityManager: PID: 3066
07-15 23:40:57.485   968  1273 E ActivityManager: Reason: Input dispatching timed out (Waiting to send non-key event because the touched window has not finished processing certain input events that were delivered to it over 500.0ms ago.  Wait queue length: 37.  Wait queue head age: 5510.9ms.)
07-15 23:40:57.485   968  1273 E ActivityManager: Parent: com.example.serviceclient/.MainActivity
07-15 23:40:57.485   968  1273 E ActivityManager: Load: 5.6 / 2.88 / 1.15
07-15 23:40:57.485   968  1273 E ActivityManager: CPU usage from 0ms to 5073ms later (2020-07-15 23:40:52.288 to 2020-07-15 23:40:57.361):
07-15 23:40:57.485   968  1273 E ActivityManager:   95% 3022/com.chinatsp.tdmsservice.TDmsBootService: 94% user + 0.7% kernel / faults: 2551 minor
07-15 23:40:57.485   968  1273 E ActivityManager:   22% 968/system_server: 13% user + 9.5% kernel / faults: 5716 minor
07-15 23:40:57.485   968  1273 E ActivityManager:   8.9% 1402/com.android.systemui: 6.2% user + 2.7% kernel / faults: 3557 minor
07-15 23:40:57.485   968  1273 E ActivityManager:   0.2% 827/media.codec: 0.2% user + 0% kernel / faults: 6806 minor
...
07-15 23:40:57.485   968  1273 E ActivityManager: 47% TOTAL: 36% user + 9% kernel + 0.2% iowait + 1% irq + 0.2% softirq

----- pid 3066 at 2020-07-15 23:40:53 -----
Cmd line: com.example.serviceclient


"main" prio=5 tid=1 Native
  | group="main" sCount=1 dsCount=0 flags=1 obj=0x71d9cd98 self=0x7d881b3c00
  | sysTid=3066 nice=-10 cgrp=default sched=0/0 handle=0x7d8987ced0
  | state=S schedstat=( 98988292 30063746 251 ) utm=6 stm=2 core=1 HZ=100
  | stack=0x7fe41f1000-0x7fe41f3000 stackSize=8192KB
  | held mutexes=
  kernel: (couldn't read /proc/self/task/3066/stack)
  native: #00 pc 00000000000cee94  /apex/com.android.runtime/lib64/bionic/libc.so (__ioctl+4)
  native: #01 pc 000000000008a974  /apex/com.android.runtime/lib64/bionic/libc.so (ioctl+132)
  native: #02 pc 0000000000058448  /system/lib64/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+260)
  native: #03 pc 0000000000059320  /system/lib64/libbinder.so (android::IPCThreadState::waitForResponse(android::Parcel*, int*)+60)
  native: #04 pc 00000000000590bc  /system/lib64/libbinder.so (android::IPCThreadState::transact(int, unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+180)
  native: #05 pc 000000000004df54  /system/lib64/libbinder.so (android::BpBinder::transact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+72)
  native: #06 pc 0000000000149778  /system/lib64/libandroid_runtime.so (android_os_BinderProxy_transact(_JNIEnv*, _jobject*, int, _jobject*, _jobject*, int)+152)
  at android.os.BinderProxy.transactNative(Native method)
  at android.os.BinderProxy.transact(BinderProxy.java:510)
  at com.chinatsp.tdmsservice.aidl.ITDmsComm$Stub$Proxy.enableDmsMonitor(ITDmsComm.java:120)
  at com.chinatsp.tdmsservice.TDmsManager.enableDmsMonitor(TDmsManager.java:106)
  at com.example.serviceclient.MainActivity$3.onClick(MainActivity.java:86)
  at android.view.View.performClick(View.java:7140)
  at android.view.View.performClickInternal(View.java:7117)
  at android.view.View.access$3500(View.java:801)
  at android.view.View$PerformClick.run(View.java:27351)
  at android.os.Handler.handleCallback(Handler.java:883)
  at android.os.Handler.dispatchMessage(Handler.java:100)
  at android.os.Looper.loop(Looper.java:214)
  at android.app.ActivityThread.main(ActivityThread.java:7356)
  at java.lang.reflect.Method.invoke(Native method)
  at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:492)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:930)

@cat /sys/kernel/debug/binder/transactions

@binderinfo.txt
outgoing transaction 71582: 0000000000000000 from 3066:3066 to 3022:3039 code 1 flags 10 pri 0:110 r1

----- pid 3022 at 2020-07-15 23:40:56 -----
Cmd line: com.chinatsp.tdmsservice.TDmsBootService

"Binder:3022_1" prio=5 tid=13 Runnable
  | group="main" sCount=0 dsCount=0 flags=0 obj=0x12d40478 self=0x7cf2c33800
  | sysTid=3039 nice=-10 cgrp=default sched=0/0 handle=0x7cf8231d50
  | state=R schedstat=( 12764606291 558828596 6091 ) utm=1274 stm=1 core=0 HZ=100
  | stack=0x7cf813b000-0x7cf813d000 stackSize=991KB
  | held mutexes= "mutator lock"(shared held)
  at com.chinatsp.tdmsservice.TDmsServiceImpl.enableDmsMonitor(TDmsServiceImpl.java:36)
  at com.chinatsp.tdmsservice.aidl.ITDmsComm$Stub.onTransact(ITDmsComm.java:57)
  at android.os.Binder.execTransactInternal(Binder.java:1021)
  at android.os.Binder.execTransact(Binder.java:994)

public void enableDmsMonitor(int surfaceHash, Surface surface) throws RemoteException {
    Log.d(TAG, "enableDmsMonitor surfaceHash:" + surfaceHash + "surface:" + surface);

    while (true) {
        int i = 100;
        i++;
    }

}

3. 被子线程同步锁block

"Binder_4" prio=5 tid=56 Blocked
  | group="main" sCount=1 dsCount=0 obj=0x1321a0a0 self=0xad31e200
  | sysTid=2491 nice=0 cgrp=default sched=0/0 handle=0x9fd00930
  | state=S schedstat=( 0 0 0 ) utm=46441 stm=46582 core=1 HZ=100
  | stack=0x9fc04000-0x9fc06000 stackSize=1014KB
  | held mutexes=
  at com.android.server.net.NetworkPolicyManagerService.getNetworkPolicies(NetworkPolicyManagerService.java:1696)
  - waiting to lock <0x07439315> (a java.lang.Object) held by thread 35
  at android.net.INetworkPolicyManager$Stub.onTransact(INetworkPolicyManager.java:145)
  at android.os.Binder.execTransact(Binder.java:453

被Tid=35的人拿住了一把锁（0x07439315），那么继续看tid=35是谁，有两种方法：

1. 搜索tid=35
2. 搜索0x07439315，找到 - locked <0x07439315> (a java.lang.Object)

"NetworkPolicy" prio=5 tid=35 TimedWaiting
  | group="main" sCount=1 dsCount=0 obj=0x12d98940 self=0x9f91f700
  | sysTid=2415 nice=0 cgrp=default sched=0/0 handle=0xa0f33930
  | state=S schedstat=( 0 0 0 ) utm=7681 stm=7783 core=0 HZ=100
  | stack=0xa0e31000-0xa0e33000 stackSize=1038KB
  | held mutexes=
  at java.lang.Object.wait!(Native method)
  - waiting on <0x02580c1b> (a java.lang.Object)
  at java.lang.Thread.parkFor$(Thread.java:1220)
  - locked <0x02580c1b> (a java.lang.Object)
  at sun.misc.Unsafe.park(Unsafe.java:299)
  at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:198)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2053)
  at java.util.concurrent.ArrayBlockingQueue.poll(ArrayBlockingQueue.java:372)
  at com.android.server.NativeDaemonConnector$ResponseQueue.remove(NativeDaemonConnector.java:634)
  at com.android.server.NativeDaemonConnector.executeForList(NativeDaemonConnector.java:426)
  at com.android.server.NativeDaemonConnector.execute(NativeDaemonConnector.java:345)
  at com.android.server.NativeDaemonConnector.execute(NativeDaemonConnector.java:340)
  at com.android.server.NetworkManagementService.setInterfaceQuota(NetworkManagementService.java:1712)
  - locked <0x0b0f91b8> (a java.lang.Object)
  at com.android.server.net.NetworkPolicyManagerService.setInterfaceQuota(NetworkPolicyManagerService.java:2421)
  at com.android.server.net.NetworkPolicyManagerService.updateNetworkRulesLocked(NetworkPolicyManagerService.java:1232)
  at com.android.server.net.NetworkPolicyManagerService$14.onReceive(NetworkPolicyManagerService.java:1060)
  - locked <0x07439315> (a java.lang.Object)
  at android.app.LoadedApk$ReceiverDispatcher$Args.run(LoadedApk.java:881)
  at android.os.Handler.handleCallback(Handler.java:739)
  at android.os.Handler.dispatchMessage(Handler.java:95)
  at android.os.Looper.loop(Looper.java:148)
  at android.os.HandlerThread.run(HandlerThread.java:61)

4. Binder线程耗尽

//假如System_server中Block在此log表示，system_server 32binder沾满，没有可用binder
at android.os.Binder.blockUntilThreadAvailable(Native method)