ANR 模拟分析

时间:2025-01-25 10:49:18

一.系统服务导致的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 来查找具体原因