一.系统服务导致的ANR
1. 一个apk 调用系统服务,
//这是一个apk 调用了系统服务
(new () {
@Override
public void onClick(View v) {
("one"); // 调用系统服务
}
});
//系统服务中的函数,做了延迟,模拟 ANR
public void testOne(String key) {
(TAG,"phg__ testOne key " + key);
try {
(20000); // 延迟 20s
} catch (Exception e){
(TAG,"phg__ testOne err ");
}
(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 (/.MainActivity), time=5282428
//ANR 原因
08-04 17:13:12.455 1178 8163 I AnrManager: Reason: Input dispatching timed out (ef785ad / (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/: 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/.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/: 1.3% user + 0.8% kernel / faults: 6981 minor 6 major
08-04 17:13:12.455 1178 8163 I AnrManager: 2% 817/@2.2-service: 1% user + 0.9% kernel
08-04 17:13:12.455 1178 8163 I AnrManager: 1.9% 506/@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//lib64/bionic/ (__ioctl+4)
native: #01 pc 0000000000093c38 /apex//lib64/bionic/ (ioctl+160)
native: #02 pc 0000000000051c6c /system/lib64/ (android::IPCThreadState::talkWithDriver(bool)+300)
native: #03 pc 0000000000052c7c /system/lib64/ (android::IPCThreadState::waitForResponse(android::Parcel*, int*)+60)
native: #04 pc 00000000000529e4 /system/lib64/ (android::IPCThreadState::transact(int, unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+188)
native: #05 pc 000000000004b0b0 /system/lib64/ (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 (Native method)
at (:540)
at $Stub$(:335)
at (:30)
at $(:41)
at (:7456)
at (:7429)
at $3600(:814)
at $(:28526)
at (:938)
at (:99)
at (:244)
at (:7806)
at (Native method)
at $(:612)
at (: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 (Native method)
- sleeping on <0x0fc0565a> (a )
at (:442)
- locked <0x0fc0565a> (a )
at (:358)
at (:337)
at $(:184)
at (:1154)
at (:1123)
二. apk自己导致的ANR
1. 直接在 apk button 的 onClick函数中设置了延迟函数,模拟ANR
(new () {
@Override
public void onClick(View v) {
try {
(20000); // 延迟20s ,模拟ANR
} catch (Exception e){
}
}
});
2. 点击button, 会出现ANR,logcat 抓取的log如下
08-04 17:30:13.813 1178 8375 E ActivityManager: ,Input dispatching timed out (ced7f6a / (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":",Input dispatching timed out (ced7f6a \/ (server) is not responding. Waited 5002ms for FocusEvent(hasFocus=false))","reserve2":"9e11c060c18d4e1e","eventTimestamp":"20210804173013","eventPkg":""}
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/: 0.4% user + 0% kernel / faults: 510 minor
08-04 17:30:13.871 1178 8375 I AnrManager: 0.3% 1486/: 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 (Native method)
- sleeping on <0x09704768> (a ) // 这里直接显示 anr 原因了
at (:442)
- locked <0x09704768> (a )
at (:358)
at $(:64)
at (:7456)
at (:7429)
at $3600(:814)
at $(:28526)
at (:938)
at (:99)
at (:244)
at (:7806)
at (Native method)
at $(:612)
at (:997)
一般发生ANR时,我们会向前 推 5s 来查找具体原因