一.系统服务导致的ANR
1. 一个apk 调用系统服务,
//这是一个apk 调用了系统服务
buttton2.setOnClickListener(new View.OnClickListener() {
@Override
public void onClick(View v) {
mPcm.testOne("one"); // 调用系统服务
}
});
//系统服务中的函数,做了延迟,模拟 ANR
public void testOne(String key) {
Slog.d(TAG,"phg__ testOne key " + key);
try {
Thread.sleep(20000); // 延迟 20s
} catch (Exception e){
Slog.d(TAG,"phg__ testOne err ");
}
Slog.d(TAG,"phg__ testOne ");
}
2. 当我们点击apk的 button时,会调用了系统 testOne函数,由于系统函数做了20s的延迟,所以会发生 ANR ,这时 logcat 会打印如下错误
08-04 17:13:12.453 1178 8163 I ActivityManager: Done dumping
08-04 17:13:12.453 1178 8163 I AnrManager: dumpStackTraces end!
08-04 17:13:12.455 1178 8163 I AnrManager: ANR in com.coolos.testtwo (com.coolos.testtwo/.MainActivity), time=5282428
//ANR 原因
08-04 17:13:12.455 1178 8163 I AnrManager: Reason: Input dispatching timed out (ef785ad com.coolos.testtwo/com.coolos.testtwo.MainActivity (server) is not responding. Waited 5001ms for FocusEvent(hasFocus=false))
08-04 17:13:12.455 1178 8163 I AnrManager: Load: 28.83 / 28.99 / 29.13
08-04 17:13:12.455 1178 8163 I AnrManager: Android time :[2021-08-04 17:13:12.45] [5286.003]
08-04 17:13:12.455 1178 8163 I AnrManager: CPU usage from 52010ms to 0ms ago (2021-08-04 17:12:16.868 to 2021-08-04 17:13:08.879):
08-04 17:13:12.455 1178 8163 I AnrManager: 9.6% 1178/system_server: 5.4% user + 4.1% kernel / faults: 29901 minor 12 major
08-04 17:13:12.455 1178 8163 I AnrManager: 7.2% 388/logd: 1.4% user + 5.7% kernel / faults: 31 minor
08-04 17:13:12.455 1178 8163 I AnrManager: 0% 498/android.hardware.audio.service.mediatek: 0% user + 0% kernel / faults: 380 minor
08-04 17:13:12.455 1178 8163 I AnrManager: 2.6% 564/surfaceflinger: 1.4% user + 1.2% kernel / faults: 235 minor
08-04 17:13:12.455 1178 8163 I AnrManager: 2.3% 1949/com.android.launcher3: 1.5% user + 0.8% kernel / faults: 9566 minor 17 major
08-04 17:13:12.455 1178 8163 I AnrManager: 2.1% 1486/com.android.systemui: 1.3% user + 0.8% kernel / faults: 6981 minor 6 major
08-04 17:13:12.455 1178 8163 I AnrManager: 2% 817/vendor.mediatek.hardware.pq@2.2-service: 1% user + 0.9% kernel
08-04 17:13:12.455 1178 8163 I AnrManager: 1.9% 506/android.hardware.graphics.composer@2.1-service: 0.7% user + 1.2% kernel / faults: 1169 minor
08-04 17:13:12.455 1178 8163 I AnrManager: 1.7% 7168/adbd: 0.4% user + 1.2% kernel / faults: 1595 minor
08-04 17:13:12.455 1178 8163 I AnrManager: 0% 1459/usap64: 0% user + 0% kernel / faults: 14354 minor 81 major
08-04 17:13:12.455 1178 8163 I AnrManager: 1.1% 725/guardserver: 0.1% user + 1% kernel
08-04 17:13:12.455 1178 8163 I AnrManager: 1.1% 545/audioserver: 0.5% user + 0.6% kernel / faults: 70 minor
08-04 17:13:12.455 1178 8163 I AnrManager: 0.5% 8/rcu_preempt: 0% user + 0.5% kernel
//这里是综括,因为我们的是睡眠函数,所以CPU 使用率不高,也没有iowait,所以这里都正常
08-04 17:13:12.455 1178 8163 I AnrManager: 6.1% TOTAL: 3% user + 3% kernel + 0% iowait + 0% softirq
// 这里显示 1453:1453 apk 进程 到 系统进程 1178:2648
08-04 17:13:12.460 1178 8163 I AnrManager: outgoing transaction from 1459:1459 to 1178:1923 start 5267.882075 android time 2021-08-04 17:12:54.332 spent time 14625 ms
3. 我们再来看ANR 文件
// 找到 main 中有 testOne 字符串的 main
"main" prio=5 tid=1 Native
| group="main" sCount=1 dsCount=0 flags=1 obj=0x71c8a338 self=0xb4000071c2096c00
| sysTid=1459 nice=-10 cgrp=default sched=0/0 handle=0x724959e4f8
| state=S schedstat=( 471451233 9273919 175 ) utm=39 stm=7 core=6 HZ=100
| stack=0x7fe813e000-0x7fe8140000 stackSize=8192KB
| held mutexes=
native: #00 pc 00000000000d7544 /apex/com.android.runtime/lib64/bionic/libc.so (__ioctl+4)
native: #01 pc 0000000000093c38 /apex/com.android.runtime/lib64/bionic/libc.so (ioctl+160)
native: #02 pc 0000000000051c6c /system/lib64/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+300)
native: #03 pc 0000000000052c7c /system/lib64/libbinder.so (android::IPCThreadState::waitForResponse(android::Parcel*, int*)+60)
native: #04 pc 00000000000529e4 /system/lib64/libbinder.so (android::IPCThreadState::transact(int, unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+188)
native: #05 pc 000000000004b0b0 /system/lib64/libbinder.so (android::BpBinder::transact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+152)
native: #06 pc 00000000001254e0 /system/lib64/libandroid_runtime.so (android_os_BinderProxy_transact(_JNIEnv*, _jobject*, int, _jobject*, _jobject*, int)+152)
// 一旦出现 transactNative ,就要看 服务端了
at android.os.BinderProxy.transactNative(Native method)
at android.os.BinderProxy.transact(BinderProxy.java:540)
at android.yulong.querylist.IQueryList$Stub$Proxy.testOne(IQueryList.java:335)
at com.coolpad.app.sdk.PhgCoolpadManager.testOne(PhgCoolpadManager.java:30)
at com.coolos.testtwo.MainActivity$1.onClick(MainActivity.java:41)
at android.view.View.performClick(View.java:7456)
at android.view.View.performClickInternal(View.java:7429)
at android.view.View.access$3600(View.java:814)
at android.view.View$PerformClick.run(View.java:28526)
at android.os.Handler.handleCallback(Handler.java:938)
at android.os.Handler.dispatchMessage(Handler.java:99)
at android.os.Looper.loop(Looper.java:244)
at android.app.ActivityThread.main(ActivityThread.java:7806)
at java.lang.reflect.Method.invoke(Native method)
at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:612)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:997)
// 从logcat 中可以看到 是1923 服务端线程
这个sysTid=1923 就是线程号
这里表示是 Sleeping
"Binder:1178_8" prio=5 tid=119 Sleeping
| group="main" sCount=1 dsCount=0 flags=1 obj=0x14900d30 self=0xb40000713467d800
| sysTid=1923 nice=-10 cgrp=default sched=0/0 handle=0x70e45fdcc0
| state=S schedstat=( 5204780710 1516256968 8915 ) utm=327 stm=192 core=2 HZ=100
| stack=0x70e4506000-0x70e4508000 stackSize=995KB
| held mutexes=
at java.lang.Thread.sleep(Native method)
- sleeping on <0x0fc0565a> (a java.lang.Object)
at java.lang.Thread.sleep(Thread.java:442)
- locked <0x0fc0565a> (a java.lang.Object)
at java.lang.Thread.sleep(Thread.java:358)
at com.yulong.querylist.QueryListImpl.testOne(QueryListImpl.java:337)
at android.yulong.querylist.IQueryList$Stub.onTransact(IQueryList.java:184)
at android.os.Binder.execTransactInternal(Binder.java:1154)
at android.os.Binder.execTransact(Binder.java:1123)
二. apk自己导致的ANR
1. 直接在 apk button 的 onClick函数中设置了延迟函数,模拟ANR
buttton4.setOnClickListener(new View.OnClickListener() {
@Override
public void onClick(View v) {
try {
Thread.sleep(20000); // 延迟20s ,模拟ANR
} catch (Exception e){
}
}
});
2. 点击button, 会出现ANR,logcat 抓取的log如下
08-04 17:30:13.813 1178 8375 E ActivityManager: com.coolos.testtwo,Input dispatching timed out (ced7f6a com.coolos.testtwo/com.coolos.testtwo.MainActivity (server) is not responding. Waited 5002ms for FocusEvent(hasFocus=false))
08-04 17:30:13.815 1178 8375 E Junk : {"eventTag":"ActivityManager","eventId":"0010021","eventMsg":"com.coolos.testtwo,Input dispatching timed out (ced7f6a com.coolos.testtwo\/com.coolos.testtwo.MainActivity (server) is not responding. Waited 5002ms for FocusEvent(hasFocus=false))","reserve2":"9e11c060c18d4e1e","eventTimestamp":"20210804173013","eventPkg":"com.coolos.testtwo"}
08-04 17:30:13.816 1178 8375 I AnrManager: startAnrDump
08-04 17:30:13.816 1178 8375 I AnrManager: isANRFlowSkipped() AnrFlow = 0
08-04 17:30:13.817 1178 8375 I AnrManager: enableTraceLog: false
08-04 17:30:13.828 1178 8376 I AnrManager: /sys/kernel/debug/binder/timeout_log isn't exist
08-04 17:30:13.865 1178 1693 I AnrManager: informMessageDump pid= 1462
08-04 17:30:13.871 1178 8375 I AnrManager: Android time :[2021-08-04 17:30:13.86] [6307.419]
08-04 17:30:13.871 1178 8375 I AnrManager: CPU usage from 1024938ms to 48ms ago (2021-08-04 17:13:08.931 to 2021-08-04 17:30:13.821):
08-04 17:30:13.871 1178 8375 I AnrManager: 1.7% 388/logd: 0.7% user + 1% kernel / faults: 40 minor
08-04 17:30:13.871 1178 8375 I AnrManager: 1.6% 297/kmemleak: 0% user + 1.6% kernel
08-04 17:30:13.871 1178 8375 I AnrManager: 1.2% 1178/system_server: 0.5% user + 0.6% kernel / faults: 36782 minor 382 major
08-04 17:30:13.871 1178 8375 I AnrManager: 0.4% 498/android.hardware.audio.service.mediatek: 0.4% user + 0% kernel / faults: 510 minor
08-04 17:30:13.871 1178 8375 I AnrManager: 0.3% 1486/com.android.systemui: 0.1% user + 0.1% kernel / faults: 22480 minor 152 major
08-04 17:30:13.871 1178 8375 I AnrManager: 0.2% 564/surfaceflinger: 0.1% user + 0.1% kernel / faults: 1406 minor
08-04 17:30:13.871 1178 8375 I AnrManager: 0.2% 7168/adbd: 0% user + 0.1% kernel / faults: 640 minor
// 负载不高
08-04 17:30:13.871 1178 8375 I AnrManager: 0.9% TOTAL: 0.3% user + 0.6% kernel + 0% iowait + 0% softirq
// 没有 outgoing transaction log
2. ANR 文件
"main" prio=5 tid=1 Sleeping
| group="main" sCount=1 dsCount=0 flags=1 obj=0x71c8a338 self=0xb4000071c2096c00
| sysTid=1462 nice=0 cgrp=default sched=0/0 handle=0x724959e4f8
| state=S schedstat=( 448196613 10582922 171 ) utm=37 stm=7 core=7 HZ=100
| stack=0x7fe813e000-0x7fe8140000 stackSize=8192KB
| held mutexes=
at java.lang.Thread.sleep(Native method)
- sleeping on <0x09704768> (a java.lang.Object) // 这里直接显示 anr 原因了
at java.lang.Thread.sleep(Thread.java:442)
- locked <0x09704768> (a java.lang.Object)
at java.lang.Thread.sleep(Thread.java:358)
at com.coolos.testtwo.MainActivity$4.onClick(MainActivity.java:64)
at android.view.View.performClick(View.java:7456)
at android.view.View.performClickInternal(View.java:7429)
at android.view.View.access$3600(View.java:814)
at android.view.View$PerformClick.run(View.java:28526)
at android.os.Handler.handleCallback(Handler.java:938)
at android.os.Handler.dispatchMessage(Handler.java:99)
at android.os.Looper.loop(Looper.java:244)
at android.app.ActivityThread.main(ActivityThread.java:7806)
at java.lang.reflect.Method.invoke(Native method)
at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:612)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:997)
一般发生ANR时,我们会向前 推 5s 来查找具体原因