ANR 问题分析指南

引言

此文为ANR问题分析的通用指南，旨在为安卓稳定性组新人和其他希望了解ANR分析方法的APP研发人员提供初步的ANR问题分析步骤和方法，借此快速定位问题方是APP端还是哪个系统模块的问题，从而加快问题流转的效率，确保有效的信息在Owner间传递。

Owner在分析问题后转出或关闭之前必须把相应的分析步骤和证据添加在jira的comment上，包括且不限于耗时消息信息，对应的有效的堆栈信息，logcat中ANR时间，Binder 调用信息和binder 耗时信息等。

原理分享和Scout日志增强介绍参考：Scout 冻屏卡死检测与日志增强机制分享

ANR概述

ANR 全称 Applicatipon No Response，是Android 系统用来检测应用主线程（UI线程）超时故障，用来判断应用是否存在卡死或者卡顿响应慢的问题。如果应用位于前台，会通过弹窗操作，提供给用户杀死应用和等待的选择。

1.1 ANR类型

通常分为以下 4 类:

(1)Input ANR**---InputDispatchingTimedOut**

应用程序主线程在 5 秒内没有完成用户的 input 事件，目前部分小米机型是8秒超时

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

(2)Service ANR---ServiceTimeout

应用程序没有执行完成 service 的 bind/create/start/destroy/unbind 操作
前台服务 20 秒超时,后台服务 200 秒超时

logcat日志关键字：Timeout executing service

(3)Broadcast ANR---BroadcastTimeout

应用程序在规定时间内没有执行完成 onReceive 操作
前台广播 10 秒超时,后台广播 60 秒超时

logcat日志关键字：Timeout of broadcast BroadcastRecord

(4)ContentProvider ANR**---ContentProviderTimeou**

应用程序在 10 秒内没有执行完成 ContentProvider相关操作
logcat日志关键字：timeout publishing content providers

1.2 ANR常见的原因

主线程耗时操作，如复杂的layout，庞大的for循环，一般存在单条消息耗时或者多条消息整体耗时。
主线程消息队列存在大量的消息，一般是有消息泄露，大量消息需要执行出现整体耗时，导致对应组件消息执行delay。
主线程前面的消息执行耗时，导致后面的消息delay
主线程被子线程同步锁block，可能为子线程耗时操作或者发生死锁
主线程设置了同步屏障并且没有移除，导致后续消息无法处理
startForeground未在Service的onStartCommand中执行

ps:广播应用可以指定处理onReceiver的线程，对应线程阻塞也会导致广播ANR

主线程被Binder对端block，主线程在对另一个进程进行同步 binder 调用，而后者处理调用阻塞耗时或者Binder线程池满无法处理该Binder请求。
主线程i/o耗时
得不到系统资源，这种情况一般像内存泄漏，高度压力测试或者高温限制系统资源扥情况
通用分析步骤

根据以上ANR常见的原因，第1-6类原因导致的ANR一般都是应用自身的问题，需要应用Owner自己优化处理，而后面三类原因可能需要定位阻塞的对端进程或者服务是谁提供，流转给对应团队分析。

首先在接触到ANR问题时，我们先检查一下日志是否完整，通常抓的”284“日志比较完整，包括bugreport和/data/anr目录的日志，MQS 日志一般有微型bugreport 和 trace信息细节参考MQS日志抓取，然后可以按照以下步骤分析：

(1)确定ANR发生的类型和第一时间点

我们通常知道从system log中搜索“ANR in”这一关键字出现的log，从而确定ANR的类型和时间，但是这个log出现的时间点已经不是第一现场，因为在这之前会打印应用的调用栈信息，可能会delay几秒甚至十几秒，所以需要搜索event log中am_anr出现的log确定ANR时间点，进程pid 以及什么类型ANR，等待了多久，也可以根据不同类型的anr 查找更早的日志确认发生的第一时间

06-22 15:37:36.983 1000 1818 30935 I am_anr : [0,9832,com.android.incallui,550026821,Input dispatching timed out (com.android.incallui/com.android.incallui.InCallActivity, 98c4257 com.android.incallui/com.android.incallui.InCallActivity (server) is not responding. Waited 5001ms for (deviceId=5, source=0x00001002, displayId=0, action=DOWN, actionButton=0x00000000, flags=0x00000000, metaState=0x00000000, buttonState=0x00000000, classification=NONE, edgeFlags=0x00000000, xPrecision=1.0, yPrecision=1.0, xCursorPosition=nan, yCursorPosition=nan, pointers=[0: (206.0, 2045.0)]), policyFlags=0x62000000)]

Reason 显示为“Waiting because the focused window has not finished processing the input events that were previously delivered to it”这一类 ANR 的直接原因是在当前 Activity 下面,上一个 input 事件没有处理完成。属于 inputDispatchingTimeout 类型。
Reason 显示为“Waiting because no window has focus but there is a focused application that may eventually add a window when it finishes starting up” 。这一类 ANR 的直接原因就是窗口无法获得焦点从而发生 ANR。属于 inputDispatchingTimeout 类型。
Reason 显示为“Broadcast of Intent{…}”,是 BroadcastTimeout 类型的 ANR。
Reason 显示为“Executing service …”, 是 serviceTimeout 类型的 ANR。
Reason 显示为“ContentProvider not responding ”, 表示发生了执行 ContentProviderTimeout 的ANR。

(2)查看ANR进程trace信息

发生ANR的应用调用栈信息会在/data/anr目录下以时间来命名，如/data/anr/anr_2021-06-22-15-37-37-623

此文件头会指出ANR的应用进程名，pid和时间：

----- pid 9832 at 2021-06-22 15:37:37 -----

Cmd line: com.android.incallui

然后可以着重看应用主线程的调用栈信息，是否主线程在等锁，是否block在binder调用，是否在进行耗时操作。

“main” prio=5 tid=1 Native

| group=“main” sCount=1 dsCount=0 flags=1 obj=0x728e7d70 self=0xb400007933495c00

| sysTid=9832 nice=-10 cgrp=top-app sched=0/0 handle=0x79ba9534f8

| state=S schedstat=( 3110588485 1864750986 12705 ) utm=219 stm=91 core=5 HZ=100

具体可参考：Java Trace含义

在使能binder调用链信息的机型上，此文件中还会加上binder对端的进程调用栈信息，从而确定是应用自己的问题还是和别的进程有关，详见第三部分”打开日志增强功能的ANR分析“。

(3)查看CPU信息

在system log的”ANR in“ log中，会打印CPU在问题发生前后一个时间段的CPU统计情况，以便确定是否和CPU资源占用，IO wait等有关，CPU 占有率因为统计时间的滞后的问题有时候不是完全跟anr现场match上，所以这个信息只能作为一点参考，大多数情况并不是那么精准，所以借鉴这个信息的前提还是基于主线程消息处理的分析。CPU 的统计方法是一段时间内不同进程或线程在用户态和内核态分配的CPU时间片/统计总时间，如果当前8核都在，则占满是800%，同理如果2个被拔核，剩余6个核工作，占满则是600%。

类型	例子
ANR in	ANR in com.taobao.taobao (com.taobao.taobao/com.taobao.tao.welcome.Welcome)
PID	PID: 17938
Reason	Reason: Input dispatching timed out (ActivityRecord{9c104fc u0 com.taobao.taobao/com.taobao.tao.welcome.Welcome, ActivityRecord{9c104fc u0 com.taobao.taobao/com.taobao.tao.welcome.Welcome t17441} does not have a focused window)
Parent	Parent: com.taobao.taobao/com.taobao.tao.welcome.Welcome
Load	Load: 8.25 / 5.7 / 6.31
/proc/pressure/memory	----- Output from /proc/pressure/memory -----some avg10=0.64 avg60=0.51 avg300=0.46 total=2048041296full avg10=0.00 avg60=0.00 avg300=0.00 total=142542959----- End output from /proc/pressure/memory -----
CPU usage	CPU usage from 0ms to 17293ms later (2021-05-17 03:14:33.291 to 2021-05-17 03:14:50.584): 139% 17938/com.taobao.taobao: 102% user + 37% kernel / faults: 168571 minor 25 major 58% 1755/system_server: 35% user + 23% kernel / faults: 36127 minor 1 majorCPU usage from 364ms to 2245ms later (2021-05-17 03:14:33.655 to 2021-05-17 03:14:35.536): 177% 17938/com.taobao.taobao: 145% user + 32% kernel / faults: 7872 minor 2 major100% TOTAL: 68% user + 29% kernel + 0.1% iowait + 1.5% irq + 0.6% softirq

(4)检查是否和进程冻结相关

基于进程冻结的应用启动优化方案 Greezer Debug 方法总结

连续启动应用时，容易造成CPU资源的抢夺，导致应用启动变慢，所以性能同事引入进程冻结功能。

在启动应用时冻结后台其他进程，将 CPU 资源集中让给前台应用，从而提高启动应用的时间。

//冻结uid为10169的进程4911,3662,3592

07-27 20:37:34.435 1000 1655 7601 D GreezeManager: Freezing uid 10169: 4911 3662 3592

07-27 20:38:58.122 10169 3592 3592 W Looper : Slow Looper main: MotionEvent is 53983ms late (event_seq=11495, action=ACTION_DOWN)

07-27 20:38:58.131 10169 3592 3592 W Looper : Slow Looper main: KeyEvent is 4722ms late (event_seq=11501, code=KEYCODE_BACK, action=ACTION_DOWN)

07-27 20:40:04.442 10169 3592 3592 W Looper : Slow Looper main: MotionEvent is 62988ms late (event_seq=11507, action=ACTION_DOWN)

//进程3592在07-27 20:38:58.123解冻，此次被冻结时长83688ms

07-27 20:38:58.123 1000 1655 4818 D GreezeManager: THAW 10169 3592 com.sina.weibo 83688ms

也可以在 bugreport 中搜索 DUMP OF SERVICE greezer，会打印最近 4 小时内的进程冻结历史记录

06-12 10:39:21.851 1000 1691 12017 I am_anr : [0,15415,com.miui.misound,818462277,Input dispatching timed out (MiuiVolumeDialogImpl, 6ae5cf6 MiuiVolumeDialogImpl (server) is not responding. Waited 5003ms for MotionEvent(action=DOWN))]

DUMP OF SERVICE greezer:

#132 10:39:22.852 10149 15415 com.miui.misound 7326ms

fz: 10:39:15.526 game in foreground from 3 //开始冻结时间和原因

th: 10:39:22.852 receive signal in game //解冻时间和原因

打开日志增强功能的ANR分析

因为通用的分析步骤有时难以确定问题所在，所以安卓稳定性组增加了一系列的日志增强和卡顿监控措施来帮助分析ANR问题。主要有以下三类：

（1）binder调用链推导

之前经常会遇到在查看anr trace的过程中怀疑是binder通信耗时，但是却不知道binder调用对端是谁，所以在binder驱动层中实现对驱动的改造，为每个进程增加节点，并输出定制的Binder 传输记录信息，进程的其他Binder 状态，log例子如下：

binder 日志含义参考Binder 日志解读

06-22 15:16:10.130 1000 1818 9331 W ActivityManager: Binder Info:outgoing transaction: from 17131:17131 to 1818: 5358 context:binder code: 2 duration: 7.44 s

06-22 15:16:10.130 1000 1818 9331 D ActivityManager: Dump Trace: add java proc 1818

06-22 15:16:10.132 1000 1818 9331 W ActivityManager: Binder Info:outgoing transaction: from 1818: 5358 to 956: 956 context:hwbinder code: 3 duration: 7.44 s

06-22 15:16:10.132 1000 1818 9331 D ActivityManager: Dump Trace: add native proc 956

06-22 15:16:10.133 1000 1818 9331 W ActivityManager: Binder Info:outgoing transaction: from 1818: 2934 to 1107: 1107 context:binder code: 6 duration: 7.47 s

06-22 15:16:10.133 1000 1818 9331 D ActivityManager: Dump Trace: add native proc 1107

06-22 15:16:10.133 1000 1818 9331 W ActivityManager: Binder Info:outgoing transaction: from 1107: 2359 to 929: 2423 context:hwbinder code: 13 duration: 7.32 s

06-22 15:16:10.133 1000 1818 9331 D ActivityManager: Dump Trace: add native proc 929

相应的binder对端pid调用栈也会在/data/anr/anr_xxxx-xxx 输出。

（2）ANR阻塞消息和历史消息信息

以往ANR发生后，我们不知道是当前消息严重耗时，还是历史消息严重耗时，或者是业务异常密集执行导致。加上此功能后会打出当前正在阻塞的这条消息信息和最近20秒内处理的所有执行时长超过50ms的历史信息以及20秒内处理的消息数量，以便分析人员确认是当前消息耗时导致还是历史消息耗时累计导致。

06-22 15:16:10.133 10107 17131 29092 D ActivityThread: AnrScout get period history msg: (Current message: duration=7460ms seq=19329 late=17ms h=android.telecom.InCallService$1 w=5)

06-22 15:16:10.133 10107 17131 29092 D ActivityThread: AnrScout get period history msg:execute time>50ms (msgIndex=146seq=18962 plan=15:15:54.662 late=87ms wall=60ms running=0ms h=android.telecom.InCallService$1 w=5)

06-22 15:16:10.133 10107 17131 29092 D ActivityThread: AnrScout get period history msg:execute time>50ms (msgIndex=142seq=18958 plan=15:15:54.651 late=0ms wall=67ms running=0ms h=android.os.Handler c=android.telecom.Call$4)

06-22 15:16:10.133 10107 17131 29092 D ActivityThread: AnrScout get period history msg:In recent 20s, total historyMsgCount=512

每条信息字段的具体含义见下表：

阻塞消息信息	Current Blocking Msg: 当前处理的消息信息handler: 执行该消息的handlerplantime: 该消息计划执行时间latency: 该消息实际执行时间与计划时间差值，也就是消息被delay时长duration: 该消息处理的耗时runningtime: 该消息处理阶段被分配的CPU时间片时长，目前8450 新机已经失效runnabletime: 该消息处理阶段在cpu调度队列等待时长，目前8450 新机已经失效callback(if any): 如果消息是Runnable，则显示为callback	Current Blocking Msg:handler: android.view.ViewRootImpl $Vi e wR oo t H an d l er pl an t im e : 10 : 05 : 02.218 l a t e n cy : 1 m s d u r a t i o n : 4018 m sr u nnin g t im e : 3 m sr u nnab l e t im e : 20 m sc a ll ba c k (i f an y) : an d ro i d . v i e w . Vi e w$ PerformClick
消息队列历史消息信息	(anr发生时当前主线程正在处理的消息信息)AnrScout get period history msg: (Current message: duration=xxxms seq=xxx late=xms h=android.app.ActivityThread $H w = xxx) (an r 发生时前 20 s ，主线程处理的耗时超过 50 m s 的消息信息，其中 h = 代表消息的 t a r g e t ， c = 代表消息的 c a ll ba c k, w = 代表消息的 m s g . w ha t) * * A n r S co u t g e tp er i o d hi s t ory m s g : * * e x ec u t e t im e > xx m s (m s g I n d e x = xxx se q = xx pl an = xx : xx : xx . xxx l a t e = xxx m s w a ll = xxx m sr u nnin g = x m s h = co m . an d ro i d . d e v e l o p m e n t . A ppS co u tT es t A c t i v i t y$ 1 w=1)(anr发生时前20s，主线程执行的消息数量)AnrScout get period history msg:In recent 20s, total historyMsgCount=xxx	AnrScout get period history msg: (Current message: duration=5193ms seq=245 late=1ms h=android.app.ActivityThread $H w = 159) * * A n r S co u t g e tp er i o d hi s t ory m s g : * * e x ec u t e t im e > 50 m s (m s g I n d e x = 106 se q = 160 pl an = 16 : 38 : 15.952 l a t e = 2771 m s w a ll = 100 m sr u nnin g = 0 m s h = co m . an d ro i d . d e v e l o p m e n t . A ppS co u tT es t A c t i v i t y$ 1 w=1)AnrScout get period history msg:In recent 20s, total historyMsgCount=190

（3）Scout信息

对于打开Scout功能的机型（persist.sys.miui_scout_enable=true），如果发生了应用ANR，那么会有一个以pid和包名命名的ANR故障信息文件在/data/mqsas/scout/app/，比如

3158-com.xiaomi.market-APP_ANR-info-2021-06-30-15-51-50，

此文件首行会初步的进行问题定界，如”AppBug“或”SystemBug“，可根据这个快速进行问题归属的判断。然后会归纳出ANR的ActivityName，有无Binder Transaction信息等。

SystemBug

Exception: APP_ANR

Timestamp: 2021-06-30-15-51-50

packageName: com.xiaomi.market

processName: com.xiaomi.market

Pid： 3158

Uid: 10166

ANR Reason： executing service com.xiaomi.market/com.xiaomi.mipush.sdk.PushMessageHandler

Binder Tracsaction Info:

outgoing transaction: from 3158: 6938 to 1677:14107 context:binder code: 1 duration: 107.06 s

BackTrace:

bgAnr=true@@@type=service@@@29c1c62ab854a882594208786d5bff32@@@stack type:valid stack@@@traces:

at com.android.server.am.ActivityManagerService.broadcastIntentWithFeature(ActivityManagerService.java:17269)

waiting to lock <0x0260357e> (a com.android.server.am.ActivityManagerService) held by thread 178

3158-com.xiaomi.market-APP_ANR-history-2021-06-30-15-51-50文件则展示了应用卡顿的历史过程，并且在应用卡顿早期也抓取了调用栈信息，方便更准确的定位问题。

Quartz 4

Explorer

ANR问题指南

ANR 问题分析指南

打开日志增强功能的ANR分析

（1）binder调用链推导

（2）ANR阻塞消息和历史消息信息

Graph View