1. 序
解决ANR一直是Android 开发者需要掌握的重要技巧,一般从三个方面着手。
- 开发阶段:通过工具检查各个方法的耗时,卡顿情况,发现一处修改一处。
- 线上阶段:这个阶段主要依靠监控工具发现ANR并上报,比如matrix。
- 分析阶段:如果线上用户发生ANR,并且你获取了一份日志,这就涉及了本文要分享的内容——
ANR日志分析技巧
2、ANR产生机制
ANR——应用无响应,Activity是5秒,BroadCastReceiver是10秒,Service是20秒。
这句话说的很笼统,要想深入分析定位ANR,需要知道更多知识点,一般来说,ANR按产生机制,分为4类:
1. 输入事件超时(5 s)——InputEvent Timeout
1 | |
2. 广播类型超时(前台15s,后台60s)——BroadcastReceiver Timeout
1 | |
3. 服务超时(前台20s,后台200s)——Service Timeout
1 | |
4.ContentProvider 类型
1 | |
plus:Activity生命周期超时会不会ANR?——经测试并不会
1 | |
三、导致ANR的原因
很多开发者认为,那就是耗时操作导致ANR,全部是app应用层的问题。实际上,线上环境大部分ANR由系统原因导致。
1. 应用层导致ANR(耗时操作)
1 | |
2. 系统导致ANR
1 | |
四、分析日志
发生ANR的时候,系统会产生一份anr日志文件(手机的/data/anr 目录下,文件名称可能各厂商不一样,业内大多称呼为trace文件),内含如下几项重要信息。
1. CPU负载
1 | |
如上所示:
- 第一行:1、5、15 分钟内正在使用和等待使用CPU 的活动进程的平均数
- 第二行:表明负载信息抓取在ANR发生之后的0~1987ms。同时也指明了ANR的时间点:2020-03-10 08:31:55.169
- 中间部分:各个进程占用的CPU的详细情况
- 最后一行:各个进程合计占用的CPU信息。
名词解释:
1 | |
注意:
- iowait占比很高,意味着有很大可能,是io耗时导致ANR,具体进一步查看有没有进程faults major比较多。
- 单进程CPU的负载并不是以100%为上限,而是有几个核,就有百分之几百,如4核上限为400%。
2. 内存信息
1 | |
从含义可以得出结论:Free memory until OOME 的值很小的时候,已经处于内存紧张状态。应用可能是占用了过多内存。
另外,除了trace文件中有内存信息,普通的eventlog日志中,也有内存信息(不一定打印)
1 | |
以上四个值分别指的是Cached,Free,Zram,Kernel,Native
Cached+Free的内存代表着当前整个手机的可用内存,如果值很小,意味着处于内存紧张状态。一般低内存的判定阈值为:4G 内存手机以下阀值:350MB,以上阀值则为:450MB
plus:如果ANR时间点前后,日志里有打印onTrimMemory,也可以作为内存紧张的一个参考判断
3. 堆栈信息
堆栈信息是最重要的一个信息,展示了ANR发生的进程当前所有线程的状态。
1 | |
如上日志所示,本文截图了两个线程信息,一个是主线程main,它的状态是native。另一个是OkHttp ConnectionPool,它的状态是TimeWaiting.
众所周知,教科书上说线程状态有5种:新建、就绪、执行、阻塞、死亡
而Java中的线程状态有6种,这6种状态都定义在:java.lang.Thread.State中
| 状态 | 解释 |
|---|---|
| NEW | 线程刚被创建,但是并未启动。还没调用start方法。 |
| RUNNABLE | 线程可以在java虚拟机中运行的状态,可能正在运行自己代码,也可能没有,这取决于操作系统处理器。 |
| BLOCKED | 当一个线程试图获取一个对象锁,而该对象锁被其他的线程持有,则该线程进入Blocked状态;当该线程持有锁时,该线程将变成Runnable状态。 |
| WATING | 一个线程在等待另一个线程执行一个(唤醒)动作时,该线程进入Waiting状态。进入这个状态后是不能自动唤醒的,必须等待另一个线程调用notify或者notifyAll方法才能够 |
| TIMED_WAITING | 同waiting状态,有超时参数,超时后自动唤醒,比如Thread.Sleep(1000) |
| TERMINATED | 线程已经执行完毕 |
问题来了,上述main线程的native是什么状态,哪来的?
其实这个trace文件中的状态是是CPP代码中定义的状态,下面是一张对应关系表
| java thread 状态 | cpp thread状态 | 说明 |
|---|---|---|
| TERMINATED | ZOMBIE | 线程死亡,终止运行 |
| RUNNABLE | RUNNING/RUNNABLE | 线程可运行或正在运行 |
| TIMED_WAITING | TIMED_WAIT | 执行了带有超时参数的wait、sleep或join函数 |
| BLOCKED | MONITOR | 线程阻塞,等待获取对象锁 |
| WAITING | WAIT | 执行了无超时参数的wait函数 |
| NEW | INITIALIZING | 新建,正在初始化,为其分配资源 |
| NEW | STARTING | 新建,正在启动 |
| RUNNABLE | NATIVE | 正在执行JNI本地函数 |
| WAITING | VMWAIT | 正在等待VM资源 |
| RUNNABLE | SUSPENDED | 线程暂停,通常是由于GC或debug被暂停 |
| UNKNOWN | 未知状态 |
由此可知,main函数的native状态是正在执行JNI函数。
堆栈信息是我们分析ANR的第一个重要的信息,一般来说:
- main线程处于 BLOCK、WAITING、TIMEWAITING状态,那基本上是函数阻塞导致ANR
- 如果main线程无异常,则应该排查CPU负载和内存环境
五、典型案例分析
1. 主线程无卡顿,处于正常状态堆栈
1 | |
上述主线程堆栈就是一个很正常的空闲堆栈,表明主线程正在等待新的消息。如果ANR日志里主线程是这样一个状态,那可能有两个原因:
- 该ANR是CPU抢占或内存紧张等其他因素引起
- 这份ANR日志抓取的时候,主线程已经恢复正常
2.主线程执行了耗时操作
1 | |
上述日志表明,主线程正处于执行状态,看堆栈信息可知不是处于空闲状态,发生ANR是因为一处click监听函数里执行了耗时操作。
3. 主线程被锁阻塞
1 | |
这是一个典型的主线程被锁阻塞的例子,
1 | |
其中等待的锁是<0x01aed1da>,这个锁的持有者是线程 3。
进一步搜索 “tid=3” 找到线程3, 发现它正在TimeWating。
那么ANR的原因找到了:线程3持有了一把锁,并且自身长时间不释放,主线程等待这把锁发生超时。
在线上环境中,常见因锁而ANR的场景是SharePreference写入。
4. CPU被其他应用抢占
1 | |
如上日志,第二行是钉钉的进程,占据CPU高达543%,抢占了大部分CPU资源,因而导致发生ANR
5. 内存紧张导致ANR
如果有一份日志,CPU和堆栈都很正常(不贴出来了),仍旧发生ANR,考虑是内存紧张
从CPU第一行信息可以发现,ANR的时间点是2020-10-31 22:38:58.468
1 | |
接着去系统日志里搜索am_meminfo, 这个没有搜索到。
再次搜索onTrimMemory,果然发现了很多条记录
1 | |
可以看出,在发生ANR的时间点前后,内存都处于紧张状态,level等级是80,查看Android API 文档
1 | |
可知80这个等级是很严重的,应用马上就要被杀死,被杀死的这个应用从名字可以看出来是桌面,连桌面都快要被杀死,那普通应用能好到哪里去呢?
一般来说,发生内存紧张,会导致多个应用发生ANR,所以在日志中如果发现有多个应用一起ANR了,可以初步判定,此ANR与你的应用无关。
6. 系统服务超时导致ANR
系统服务超时一般会包含BinderProxy.transactNative关键字,请看如下日志(敏感包名已脱密):
1 | |
从堆栈可以看出获取网络信息发生了ANR:getActiveNetworkInfo
前文有讲过:系统的服务都是Binder机制(16个线程),服务能力也是有限的,有可能系统服务长时间不响应导致ANR。
如果其他应用占用了所有Binder线程,那么当前应用只能等待,可进一步搜索:blockUntilThreadAvailable关键字
1 | |
如果有发现某个线程的堆栈,包含此字样,可进一步看其堆栈,确定是调用了什么系统服务。
此类ANR也是属于系统环境的问题,如果某类型机器上频繁发生此问题,应用层可以考虑规避策略。