前言
在懂得了ANR的发生原理和监控原理之后,是时候针对项目中的ANR进行分析了,在分析前要知道ANR的分析套路一般是怎么分析的
分析ANR问题需要哪些日志
- Trace日志:当ANR产生的时候,系统会dump此时的top进程中Thread的运行状态,将其保存在
trace
文件上 - AnrInfo日志:当ANR产生的时候,logcat会打印出当前AnrInfo信息,该信息可以通过
ActivityManagerService.getProcessesInErrorState()
方法获取 - Bugreport日志:当前Android设备上的错误报告,包含设备日志、堆栈轨迹和其他诊断信息,该信息可以通过
adb bugreport D:\
命令获取
ANR的分析思路
- 一、看Trace信息
- 死锁堆栈、业务堆栈、IPC Block堆栈、系统堆栈
- 二、看关键字
- Load、CPU、Slow Operation、Kswapd、Mmcqd、Kwork、Lowmemorykiller、onTrimMemory
- 三、看系统cpu负载分布
- 通过系统整体CPU负载
User、Sys、IOWait
占比,判断CPU资源紧张,还是IO资源紧张,进一步分析当前负载过高是发生在应用空间还是系统空间
- 通过系统整体CPU负载
- 四、看进程CPU
- 观察进程CPU占比
CPU usage from 37010ms to 0ms ago
和101% 23326/com.demo: 32% user + 68% kernel
- 观察进程CPU占比
- 五、看线程CPU:
- 对比各线程CPU占比,以及线程内部user和kernel占比,可以从目标进程内部分析各个线程的(utm,stm),进一步分析是哪个线程有问题了
- 六、看消息调度锁定细节
- 发生ANR时,没有一个消息是无辜的
Trace日志
----- pid 23326 at 2023-02-21 00:15:26 -----
Cmd line: com.demo
Build fingerprint: 'google/android_x86/x86:7.1.2/N2G48C/N975FXXU1ASGO:user/release-keys'
ABI: 'x86' //x86一般为模拟器
Build type: optimized
Zygote loaded classes=4380 post zygote classes=9911
Intern table: 48884 strong; 554 weak
JNI: CheckJNI is off; globals=1079 (plus 1467 weak)
Libraries: ...
Heap: 17% free, 43MB/52MB; 674957 objects //已分配堆内存大小52MB,其中已用43MB,剩下17%空余,共分配了674957个对象
Total time spent in GC: 6.414s //GC用过了多少时间
Mean GC size throughput: 244MB/s
Mean GC object throughput: 6.31642e+06 objects/s
Total number of allocations 41189203 //进程创建到现在一共创建了多少对象
Total bytes allocated 1GB //进程创建到现在一共申请了1GB内存
Total bytes freed 1GB //进程创建到现在一共释放了1GB内存
Free memory 8MB //不扩展堆堆情况下可用的内存
Free memory until GC 8MB //GC前的可用内存
Free memory until OOME 212MB //OOM之前的可用内存,这个值很小,说明内存紧张
Total memory 52MB //当前总内存(已用+可用)
Max memory 256MB //进程最多能申请的内存
Zygote space size 1552KB
Total mutator paused time: 177.563ms
Total time waiting for GC to complete: 89.366ms
Total GC count: 130 //GC次数
Total GC time: 6.414s //GC时长
Total blocking GC count: 1 //GC被block次数以及时长
Total blocking GC time: 100.948ms
suspend all histogram: Sum: 65.115ms 99% C.I. 5.440us-15646.719us Avg: 478.786us Max: 35628us
DALVIK THREADS (65): //当前进程共有65个线程"Signal Catcher" daemon prio=5 tid=3 Runnable| group="system" sCount=0 dsCount=0 obj=0x12c3a310 self=0xb6ed7e00| sysTid=23332 nice=0 cgrp=default sched=0/0 handle=0xc2ba6910| state=R schedstat=( 63328804 15730865 32 ) utm=3 stm=2 core=3 HZ=100| stack=0xc2aaa000-0xc2aac000 stackSize=1014KB| held mutexes= "mutator lock"(shared held)// Signal Catcher:线程名 daemon: 守护线程 prio:线程优先级 tid:线程内部id Runnable: 线程状态
// group: 线程所属的线程组 sCount:线程挂起次数 dsCount:用于调试的线程挂起次数 obj:当前线程关联的Java线程对象 self:当前线程地址
// sysTid:线程真正意义上的tid nice:调度优先级,值越小优先级越高 cgrp: 进程所属的进程调度组 sched: 调度策略 handle:函数处理地址
// state:线程状态 schedstat:CPU调度时间统计,依次表示cpu运行时间、RQ队列等待时间、cpu调度切换次数 utm: 用户态的cpu时间 stm:内核态的cpu时间 core:该线程的最后运行所在核 HZ:时钟频率
// stack:线程栈的地址空间 stackSize:栈的大小
// mutexes:所持有 mutex 类型,有独占锁(exclusive)和 共享锁(shared)两类
AnrInfo日志
ANR in com.demo (com.demo/com.demo.SplashActivity)
PID: 23326
Reason: Input dispatching timed out (Waiting because no window has focus but there is a focused application that may eventually add a window when it finishes starting up.)
//系统负载:表示不同时间段的系统整体负载, 依次表示ANR发生前 1分钟、前5分钟、前15分钟时间段的cpu负载
Load: 8.44 / 8.67 / 8.1
//进程cpu使用率:表示当前ANR发生前的进程cpu使用率
CPU usage from 37010ms to 0ms ago (2023-02-21 00:14:49.456 to 2023-02-21 00:15:26.466):101% 23326/com.demo: 32% user + 68% kernel / faults: 257 minor0.9% 1298/system_server: 0.5% user + 0.4% kernel / faults: 10086 minor 30 major0.1% 1387/com.android.systemui: 0% user + 0% kernel / faults: 3023 minor 4 major0.1% 1744/com.android.launcher3: 0% user + 0% kernel / faults: 124 minor 4 major0% 1105/surfaceflinger: 0% user + 0% kernel0% 1110/audioserver: 0% user + 0% kernel0% 7/rcu_sched: 0% user + 0% kernel0% 275/kworker/0:1: 0% user + 0% kernel0% 1669/android.ext.services: 0% user + 0% kernel / faults: 117 minor 2 major
//系统cpu使用率总汇
25% TOTAL: 8.3% user + 17% kernel + 0% iowait
CPU usage from 1434ms to 1936ms later (2023-02-21 00:15:27.900 to 2023-02-21 00:15:28.402):102% 23326/com.demo: 29% user + 73% kernel100% 23380/AsyncInit: 27% user + 73% kernel
24% TOTAL: 7% user + 17% kernel
- 先分析系统负载
Load
字段,8.44 / 8.67 / 8.1
说明系统当前的负载还算可以 - 再从cpu信息找到当前应用cpu使用率高达
101%
,从下面可以找到当前的线程卡在AsyncInit
方法上
Bugreport日志
Bugreport日志比较冗长,包含设备的各种信息,对于ANR来说,我们只要过滤ANR需要的关键字即可
1、搜索am_anr
通过当前关键字可以找到最终发送ANR的罪魁祸首
03-07 22:01:47.632 1000 1675 15617 I am_anr : [0,6267,com.demo,953695814,executing service com.demo/com.demo.hensen.MyService]
2、搜索ANR in
通过当前关键字可以找到最终发送ANR的罪魁祸首
E ActivityManager: ANR in com.demo.hensen.MyService
E ActivityManager: PID: 3036
E ActivityManager: Reason: executing service com.demo/com.demo.hensen.MyService