ANR系列（三）——ANR分析套路

前言

在懂得了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 usage from 37010ms to 0ms ago和101% 23326/com.demo: 32% user + 68% kernel
• 五、看线程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 minor
  0.9% 1298/system_server: 0.5% user + 0.4% kernel / faults: 10086 minor 30 major
  0.1% 1387/com.android.systemui: 0% user + 0% kernel / faults: 3023 minor 4 major
  0.1% 1744/com.android.launcher3: 0% user + 0% kernel / faults: 124 minor 4 major
  0% 1105/surfaceflinger: 0% user + 0% kernel
  0% 1110/audioserver: 0% user + 0% kernel
  0% 7/rcu_sched: 0% user + 0% kernel
  0% 275/kworker/0:1: 0% user + 0% kernel
  0% 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% kernel
    100% 23380/AsyncInit: 27% user + 73% kernel
24% TOTAL: 7% user + 17% kernel

1. 先分析系统负载Load字段，8.44 / 8.67 / 8.1说明系统当前的负载还算可以
2. 再从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