ANR 问题分析

砌墙君
4,451 阅读6分钟

ANR 问题分析

ANR(Application Not Responding) 应用程序无响应。一般是主线程阻塞太久或者是进程间通信时间太长导致。 如下图。

image.png

ANR问题主要分四种

  • Input Dispaching Timeout 输入时间分发超时

    input 事件分发超过5000ms 触摸事件，按键事件

    logcat日志关键字：Input event dispatching timed out

  • BroadcastQueue Timeout 广播队列超时

    前台广播 onReceiver 10s 内未执行完成

    后台广播 onReceiver 60s 内未执行完成

    logcat日志关键字：Timeout of broadcast BroadcastRecord

  • Service Timeout 前台服务超时

    前台服务onCreate，onStart，onBind等生命周期 在20s内未执行完成。

    后台服务onCreate，onStart，onBind等生命周期 在200s内未执行完成（较少）。

    logcat日志关键字：Timeout executing service

  • ContentProvider Timeout 内容提供者发布超时

    ContentProvider 的publish过程超过10s。

    logcat日志关键字：timeout publishing content providers

导致 ANR 的的原因

1 主线程阻塞，死循环。

2 多线程死锁导致主线程阻塞。

3 主线程被Binder对端block。

4 service binder的连接达到上线无法和和System Server通信

5 系统资源已耗尽（管道、CPU、IO）

...

实际上基本分为两类

  1. 进程自身导致。

    主线程的阻塞，死循环。

    其它线程的cpu 负载过高，主线程抢不到cpu时间片。

  2. 和进程间交互相关。

    其它进程 cpu 占用高。

    进程间 Binder 对端阻塞。

ANR 分析

1 系统日志分析

08-09 20:54:17.319630  1430 10045 E ActivityManager: ANR in com.yoosee (com.yoosee/com.jwkj.VasPlayBackListActivity)
08-09 20:54:17.319630  1430 10045 E ActivityManager: PID: 8645
08-09 20:54:17.319630  1430 10045 E ActivityManager: Reason: Input dispatching timed out (152056b com.yoosee/com.jwkj.VasPlayBackListActivity (server) is not responding. Waited 5000ms for MotionEvent)
08-09 20:54:17.319630  1430 10045 E ActivityManager: Parent: com.yoosee/com.jwkj.VasPlayBackListActivity
08-09 20:54:17.319630  1430 10045 E ActivityManager: Load: 30.31 / 29.12 / 29.36
08-09 20:54:17.319630  1430 10045 E ActivityManager: ----- Output from /proc/pressure/memory -----
08-09 20:54:17.319630  1430 10045 E ActivityManager: some avg10=0.19 avg60=0.31 avg300=0.14 total=1433082988
08-09 20:54:17.319630  1430 10045 E ActivityManager: full avg10=0.00 avg60=0.01 avg300=0.00 total=485600308
08-09 20:54:17.319630  1430 10045 E ActivityManager: ----- End output from /proc/pressure/memory -----
08-09 20:54:17.319630  1430 10045 E ActivityManager: 
08-09 20:54:17.319630  1430 10045 E ActivityManager: CPU usage from 0ms to 11302ms later (2021-08-09 20:54:05.995 to 2021-08-09 20:54:17.298) with 99% awake:
08-09 20:54:17.319630  1430 10045 E ActivityManager:   73% 3968/com.google.android.providers.media.module: 33% user + 39% kernel / faults: 3070 minor 1 major
08-09 20:54:17.319630  1430 10045 E ActivityManager:   61% 8645/com.yoosee: 45% user + 15% kernel / faults: 11566 minor
08-09 20:54:17.319630  1430 10045 E ActivityManager:   11% 
......
40% TOTAL: 21% user + 18% kernel + 0% iowait + 0.3% softirq

搜索ANR， 可以看到ActivityManager 会打印ANR相关的日志。

有ANR 发生的位置，发生ANR的进程和进程号。

以及 ANR 的原因是input分发超时了。

08-09 20:54:17.319630 1430 10045 E ActivityManager: ANR in com.yoosee (com.yoosee/com.jwkj.VasPlayBackListActivity) 08-09 20:54:17.319630 1430 10045 E ActivityManager: PID: 8645 08-09 20:54:17.319630 1430 10045 E ActivityManager: Reason: Input dispatching timed out (152056b com.yoosee/com.jwkj.VasPlayBackListActivity (server) is not responding. Waited 5000ms for MotionEvent)

同是可以看到cpu的使用率，可以判断是否是cpu占用过高，

1% 8645/com.yoosee: 45% user + 15% kernel / faults: 11566 minor 08-09 20:54:17.319630 1430 10045 E ActivityManager: 11% 40% TOTAL: 21% user + 18% kernel + 0% iowait + 0.3% softirq

com.yoosee的占用不高。不是cpu负载过高导致的。

2 看event log

日志中搜索关键字：am_anr，找到出现ANR的时间点、进程PID、ANR类型。

08-09 20:54:06.041712  1430 10045 I am_anr  : [0,8645,com.yoosee,950550084,Input dispatching timed out (152056b com.yoosee/com.jwkj.VasPlayBackListActivity (server) is not responding. Waited 5000ms for MotionEvent)]

也可以看到

时间点，进程名 和 pid 以及 ANR 的类型。

3 分析 trace 日志。

发生 ANR 时候生成的 trace 文件，一般在/data/anr/目录下。

trace 文件可以看到堆栈信息，线程信息，Binder 调用的信息。

`----- pid 8645 at 2021-08-09 20:54:16 -----`
`Cmd line: com.yoosee`
`ABI: 'arm'`
​
`"com.yoosee" sysTid=8645`
    `#00 pc 00311a5c  /system/framework/arm/boot-framework.oat (android.common.xxxxx.getIndex [DEDUPED]+84) (BuildId: d58ef8ba3f6b498696b93d06e350522609cfb4c6)`
    `#01 pc 00311bc3  /system/framework/arm/boot-framework.oat (android.common.xxxxx.getOrCreate+50) (BuildId: d58ef8ba3f6b498696b93d06e350522609cfb4c6)`
    `#02 pc 0034c837  /system/framework/arm/boot-framework.oat (android.graphics.xxxxx.isDarkMode+94) (BuildId: d58ef8ba3f6b498696b93d06e350522609cfb4c6)`
    `#03 pc 0034c243  /system/framework/arm/boot-framework.oat (android.graphics.xxxxx.changeArea+50) (BuildId: d58ef8ba3f6b498696b93d06e350522609cfb4c6)`
​

可以看到有java调用栈的信息，能精确定位到 anr 是卡在了哪里。

可以看到是在xxxxx.getIndex 方法中发生了 ANR 。

分析ANR 最重要是看anr 目录下的 trace 日志。所以查询补充了 trace 日志中的一些字段。

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核的序号。

\

avatar
文章
阅读
粉丝