什么是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是谁,有两种方法:
- 搜索tid=35
- 搜索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)