Android ANR日志分析进行曲

定义
ANR(Application Not Responding)?应用程序无响应。如果你应用程序在UI线程被阻塞太长时间，就会出现ANR，通常出现ANR，系统会弹出一个提示提示框，让用户知道，该程序正在被阻塞，是否继续等待还是关闭。

ANR出现的原因
1:主线程频繁进行耗时的IO操作：如数据库读写（UI线程等待其它线程释放某个锁，导致UI线程无法处理用户输入）；
2:多线程操作的死锁，主线程被block；
3:主线程被Binder 对端block；
4:System Server中WatchDog出现ANR；
5:service binder的连接达到上线无法和SystemServer通信
6:系统资源已耗尽（管道、CPU、IO）

ANR类型
出现ANR的一般有以下几种类型：
1:KeyDispatchTimeout（常见）
input事件在5S内没有处理完成发生了ANR。
logcat日志关键字：Input event dispatching timed out
2:BroadcastTimeout
前台Broadcast：onReceiver在10S内没有处理完成发生ANR。
后台Broadcast：onReceiver在60s内没有处理完成发生ANR。
logcat日志关键字：Timeout of broadcast BroadcastRecord
3:ServiceTimeout
前台Service：onCreate，onStart，onBind等生命周期在20s内没有处理完成发生ANR。
后台Service：onCreate，onStart，onBind等生命周期在200s内没有处理完成发生ANR
logcat日志关键字：Timeout executing service
4：ContentProviderTimeout
ContentProvider 在10S内没有处理完成发生ANR。 logcat日志关键字：timeout publishing content providers

ANR分析过程
1.查看events_log
在android stuido Terminal面板，输出events日志信息，命令如下：
adb logcat -b events

面板信息如下：

图片2.png

其次Terminal面板找到关键字：am_anr，找到出现ANR的时间点、进程PID、ANR类型。

图片3.png

从上面的log我们可以看出：应用com.example.myapplication在09-25 23:04:27.355时间，发生了一次KeyDispatchTimeout类型的ANR，它的进程号是3724. 把关键的信息整理一下：
ANR时间：09-25 23:04:27.355
进程pid：3879
进程名：com.example.myapplication
ANR类型：KeyDispatchTimeout

通过上面关键信息，我们了解到，发生KeyDispatchTimeout的ANR是因为input事件在5秒内没有处理完成。那么在这个时间09-25 23:04:27.355的前5秒，也就是（23:04:22 ~23:04:23）时间段左右程序到底做了什么事情？我们已经知道pid了，再搜索一下pid = 3879的日志.这些日志表示该进程所运行的轨迹，关键的日志如下：

图片4.png

仔细看一下就会发现：

图片5.png

23:04:19时间点做了界面跳转，之后将近8秒后，就出现ANR了，那么，我们知道怎么开始的，但是具体原因还是没有找到。
那么接下来，是不是当时CPU很紧张、各路APP再抢占资源？我们再看看CPU的信息,。搜索关键字关键字：ANR IN

2021-09-26 07:04:28.043 1597-1611/system_process E/ActivityManager: ANR in com.example.myapplication (com.example.myapplication/.activities.ANRTestActivity)
    PID: 3879
    Reason: Input dispatching timed out (Waiting to send non-key event because the touched window has not finished processing certain input events that were delivered to it over 500.0ms ago.  Wait queue length:  Wait queue head age: 5706.6ms.)
    Load: 0.23 / 0.09 / 0.07
    CPU usage from 507882ms to 0ms ago (2021-09-25 14:56:16.323 to 2021-09-25 23:04:27.351):
      0.9% 1597/system_server: 0.1% user + 0.7% kernel / faults: 26762 minor 1 major
      0.2% 1800/com.android.settings: 0% user + 0.2% kernel / faults: 8985 minor 8 major
      0.6% 1303/surfaceflinger: 0% user + 0.6% kernel / faults: 18 minor
      0.1% 2094/com.google.android.apps.nexuslauncher: 0% user + 0.1% kernel / faults: 1130 minor 2 major
      0% 1692/com.android.systemui: 0% user + 0% kernel / faults: 381 minor
      0% 1320/audioserver: 0% user + 0% kernel / faults: 38 minor
      0% 2214/com.google.android.googlequicksearchbox:search: 0% user + 0% kernel / faults: 4059 minor
      0% 2000/com.google.android.gms.persistent: 0% user + 0% kernel / faults: 947 minor
      0% 1779/com.android.phone: 0% user + 0% kernel / faults: 110 minor
      0% 2274/com.google.android.gms: 0% user + 0% kernel / faults: 542 minor 20 major
      0% 1307/adbd: 0% user + 0% kernel / faults: 2411 minor
      0% 1252/logd: 0% user + 0% kernel / faults: 40 minor
      0% 1329/netd: 0% user + 0% kernel / faults: 153 minor
      0% 4/kworker/0:0: 0% user + 0% kernel
      0% 2108/com.android.printspooler: 0% user + 0% kernel / faults: 878 minor
      0% 2141/com.google.process.gapps: 0% user + 0% kernel / faults: 448 minor
      0% 2873/com.google.android.gms.unstable: 0% user + 0% kernel / faults: 156 minor
      0% 1250/jbd2/vdc-8: 0% user + 0% kernel
      0% 3/ksoftirqd/0: 0% user + 0% kernel
      0% 8/rcu_preempt: 0% user + 0% kernel
      0% 1241/kworker/0:1H: 0% user + 0% kernel
      0% 1302/servicemanager: 0% user + 0% kernel
      0% 1319/zygote: 0% user + 0% kernel / faults: 560 minor
      0% 1330/rild: 0% user + 0% kernel
      0% 6/kworker/u8:0: 0% user + 0% kernel
      0% 679/kworker/1:1: 0% user + 0% kernel
      0% 680/kworker/2:1: 0% user + 0% kernel
      0% 681/kworker/3:1: 0% user + 0% kernel
      0% 1299/healthd: 0% user + 0% kernel
      0% 1301/lmkd: 0% user + 0% kernel
      0% 1331/fingerprintd: 0% user + 0% kernel
     +0% 3879/com.example.myapplication: 0% user + 0% kernel
     +0% 3926/com.android.calendar: 0% user + 0% kernel
     +0% 3939/com.android.providers.calendar: 0% user + 0% kernel
     +0% 3960/com.android.deskclock: 0% user + 0% kernel
     +0% 4019/logcat: 0% user + 0% kernel
    0.3% TOTAL: 0% user + 0.3% kernel + 0% iowait + 0% softirq
    CPU usage from 183ms to 689ms later (2021-09-25 23:04:27.534 to 2021-09-25 23:04:28.040):
0% TOTAL: 0% user + 0% kernel

图片6.png

从上面可以看出，各路进程CPU占用基本低于1%，显然不是CPU负载的原因了。那么到底是什么原因呢？这时就要看我们的终极大杀器——traces.txt。

2.traces.txt日志分析
我们需要把traces.txt导出来，操作命令如下图：

图片8.png

通过traces文件,我们可以拿到线程名、堆栈信息、线程当前状态、binder call等信息。通过adb命令拿到该文件：adb pull /data/anr/traces.txt

图片9.png

接下来，我们需要把traces.txt导入AS，如下：

图片10.png

traces.txt里面的一些字段，看看它到底能给我们提供什么信息.
main：main标识是主线程，如果是线程，那么命名成“Thread-X”的格式,x表示线程id,逐步递增。
prio：线程优先级,默认是5
tid：tid不是线程的id，是线程唯一标识ID
group：是线程组名称
sCount：该线程被挂起的次数
dsCount：是线程被调试器挂起的次数
obj：对象地址
self：该线程Native的地址
sysTid：是线程号(主线程的线程号和进程号相同)
nice：是线程的调度优先级
sched：分别标志了线程的调度策略和优先级
cgrp：调度归属组
handle：线程处理函数的地址。
state：是调度状态
schedstat：从/proc/[pid]/task/[tid]/schedstat读出，三个值分别表示线程在cpu上执行的时间、线程的等待时间和线程执行的时间片长度，不支持这项信息的三个值都是0；
utm：是线程用户态下使用的时间值(单位是jiffies）
stm：是内核态下的调度时间值
core：是最后执行这个线程的cpu核的序号。

Java的堆栈信息是我们最关心的，它能够定位到具体位置。从上面的traces,我们可以判断com.example.myapplication.activities.ANRTestActivity$1.onClick(ANRTestActivity.java:25)点击之后导致了com.example.myapplication发生了ANR。在第25行代码，如下：

图片11.png

从上面源码可以看出，点击事件里面的方法休眠了15秒，导致Input不能及时处理引发ANR。

总结一下这分析流程：首先我们搜索am_anr，找到出现ANR的时间点、进程PID、ANR类型、然后再找搜索PID，找前5秒左右的日志。过滤ANR IN 查看CPU信息，接着查看traces.txt，找到java的堆栈信息定位代码位置，最后查看源码，分析与解决问题。这个过程基本能找到发生ANR的来龙去脉。

小伙伴如果有兴趣的话，欢迎来阅读Android ListView性能优化案例这篇文章，搜索并关注公众号“Android技术迷”关注后即可阅读此文章，感谢关注。