有关ANR的那点事儿

1、简介

ANR全称：Application Not Responding，也就是应用程序无响应。

Android系统中，ActivityManagerService(简称AMS)和WindowManagerService(简称WMS)会检测App的响应时间，如果App在特定时间无法相应屏幕触摸或键盘输入时间，或者特定事件没有处理完毕，就会出现ANR。

以下四个条件都可以造成ANR发生：

InputDispatching Timeout：5秒内无法响应屏幕触摸事件或键盘输入事件 BroadcastQueue Timeout ：在执行前台广播（BroadcastReceiver）的onReceive()函数时10秒没有处理完成，后台为60秒。 Service Timeout ：前台服务20秒内，后台服务在200秒内没有执行完毕。（此外还有一种特殊情况10s（startForeground）内app端未及时binder回调serviceDoneExecuting告知AMS，MainHandler则会执行到delay的消息，并调用appNotResponding方法，产生ANR） ContentProvider Timeout ：ContentProvider的publish在10s内没进行完。

  一般的ANR有：主线程耗时操作；主线程被其它线程Block；系统级响应阻塞；系统或进程自身可用内存紧张；CPU资源被抢占

2、ANR的分析流程

1)流程

ANR问题分析流程：

1、获取ANRLog和trace，可以查看trace堆栈调用，查看main thread情况；

2、以inputdispatch ANR为例，首先check inputdispatch type,从anr后的reason可以进行下一步判定：

3、APP Related Issue check

CPU 负载，单进程CPU的负载并不是以100%为上限，而是有几个核，就有百分之几百，如4核上限为400%。

CPU usage from XX to XX ago 关键字表明了这是在 ANR 发生之前一段时间内的 CPU 统计.

Load 关键字表明了最近 1 分钟、5 分钟、15 分钟内的 CPU 负载，下表为CPU异常的一些打印：

CPU信息解析

在mainlog anr信息之后会紧接着打印cpu usage信息，根据当前的cpu占用率可以分析anr发生时是否出现cpu hunger而导致发生anr的进程没有机会获取到cpu进而出现anr

若cpu占用高则一方面需要继续往下进行trace文件的分析查找是否有异常阻塞，另一方面需要结合当前批次的其他anr,排查性能瓶颈,系统级耗时操作带来的影响(如qxdm log),并及时了解其他anr的进程cpu占用找到异常进程(如gms访问不到服务器时占用会异常的高）

通常情况下我们只需要关注total的数值,total数值高的情况下关注一下cpu占用高的进程

cpu usage信息字段及意义:

user： CPU在用户态的运行时

kernel：CPU在内核态运行的时间

idle： CPU空闲时间，不包括iowait时间

iowait： CPU等待I/O操作的时间

irq： CPU硬中断的时间

softirq: CPU软中断的时间

minor/major:表示页错误次数,如果ANR发生时发现CPU使用率中iowait占比很高，可以通过查看进程的major次数来推断是哪个进程在进行磁盘U/O操作

“+”，说明该进程或线程是在最后两次CPU使用率采样时间段内新建的;反之如果是“-”，说明该进程或线程在采样时间段内终止了

另外需要检测当前系统环境是否存在内存不足,可在main log中搜索lowmemorykiller关键字,如果出现lowmemorykiller杀死进程的情况则可判断系统当前存在内存不足

内存不足时需要排查是否有内存泄露,或者是性能瓶颈,同时也需要对trace文件进行分析.

4、Broadcast/Service ANR大都是APP Related Issue

2)分析思路

1. ANR现场分析(logcat)

anr发生时间

anr种类

anr发生时的前后文环境(是否有异常发生)

2. anr 发生时的系统环境

cpu使用情况

内存状况

3. trace文件分析

主线程stuck(io,db,耗时操作,等待锁)

子线程block,wait(等待锁,死锁)

其他进程block,wait(与anr相关的操作,相关的锁,cpu占用高,进程间通信)

 

关键的入手点：

重点文件：        Event log        Main log     anr_trace     bugreport     binderinfo

首先是根据Eventlog查看am_anr查看问题出现的具体时间点，再到main log中查看对应的ANR类型。

关键打印：

Input TimeOut                  am_anr          Application is not responding

Broadcast  Timeout          am_anr         Timeout of broadcast BroadcastRecord

Service  Timeout              am-anr          Timeout executing service

INPUT  Timeout

1）input 触发ANR的情况有：                               

情形	日志打印
无窗口, 有应用	Waiting because no window has focus but there is a focused application that may eventually add a window when it finishes starting up.
窗口暂停:	Waiting because the [targetType] window is paused.
窗口未连接:	Waiting because the [targetType] window’s input channel is not registered with the input dispatcher. The window may be in the process of being removed.
窗口连接已死亡	Waiting because the [targetType] window’s input connection is [Connection.Status]. The window may be in the process of being removed.
窗口连接已满	Waiting because the [targetType] window’s input channel is full. Outbound queue length: [outboundQueue长度]. Wait queue length: [waitQueue长度].
按键事件，输出队列或事件等待队列不为空：	Waiting to send key event because the [targetType] window has not finished processing all of the input events that were previously delivered to it. Outbound queue length: [outboundQueue长度]. Wait queue length: [waitQueue长度].
非按键事件，事件等待队列不为空且头事件分发超时500ms	Waiting to send non-key event because the [targetType] window has not finished processing certain input events that were delivered to it over 500ms ago. Wait queue length: [waitQueue长度]. Wait queue head age: [等待时长].

2）触发的log打印：   

1.  ALOGI("Application is not responding: %s. " "It has been %0.1fms since event, %0.1fms since wait started. Reason: %s", getApplicationWindowLabelLocked(applicationHandle, windowHandle).string(), dispatchLatency, waitDuration, reason);

2. Input event dispatching timed out xxx. Reason: + reason, 其中xxx取值:
    窗口类型: sending to windowState.mAttrs.getTitle()
    应用类型: sending to application appWindowToken.stringName
    其他类型: 则为空.
3. 当activity 不存在的时候：

1.)EventLog.writeEvent(EventLogTags.AM_ANR, userId, pid, processName, info.flags,
annotation); 这个log的输出在某些情况是不会输出的，用户定义了ANR的处理。还有就是另外几种情况,isShuttingDown ，isNotResponding ，isCrashing ，killedByAm，killed
2)生成 data/anr/文件，里面保存了一些pid的trace 信息以及cpu信息。
3)DropBoxManager也会输出一些anr的trace信息。
4).如果是前台进程还会有一个AppNotRespondingDialog
4. 当activity的进程存在的时候：就会先finish activiy ，然后结束进程，并且输出一个system.out 的log 输出，输出内容大概是：Input dispatching timed out +reason

Broadcast  Timeout

Brocadcast timeout 是指串行有序广播发送给receiver的时候，app没有来得及处理这个广播，或者app的receiver处理这个广播的时候超时了（前台广播10s，后台广播60s），没有及时回调finishReceiver通知fw。并行无序广播不计算timeout。

普通情况下的broadcast timeout比较好分析，一般只有3种情况：

1） 主线程很忙，没来得及处理

这种情况我们通过主线程log就可以判断，主线程log不停止，一直在打印，就说明主线程没有卡住，此时发生的anr大都是因为主线程忙导致的。

2） 主线程卡住，没来及处理

这种现象比较明显，主线程在某一时刻停止打印log，再结合trace，就可以判断hang住的点。

3） onReceive处理时间过长

这个case分两种：

a）onReceive处理时间长。

这种情况也比较好处理，看主线程trace就可以定论。

b）onReceive中call goAsync转移到其他线程处理，然后卡在其他线程。

这种情况比较复杂，goAsync只是把事情放到其他线程，避免block主线程，但是timeout计时依然不停止，要等工作线程处理完call finish以后才算处理完broadcast。不call goAsync直接起子线程处理广播事物会让系统误认为你以外处理完广播，从而降低进程优先级，导致进程被kill，继而导致广播不能完整处理完。对于事情不算特别复杂，能在60s（前台10s）之内肯定完成的工作，通过这种方式可以有更好的体验。但是对于超过60s（前台10s）的事务还是要起service来处理。

这类问题分析的时候，主线程显示不忙，trace显示主线程有没有hang，但是就是timeout，这时候就要去看那个工作线程的trace是不是block住了。

Service TimeOut

ActiveServices中有两个会触发注册超时检查的场景，注册之后通知APP去完成相关的操作，如果APP按照完成所有任务，则超时检查的任务会被取消。如果到了超时时间后仍然有未完成的任务，则就会发生ANR。

Service启动设置Handler超时消息

ContextImpl.startService -> ContextImpl.startServiceCommon -> AMS.startService -> ActiveServices.startServiceLocked -> ActiveServices.startServiceInnerLocked -> ActiveServices.bringUpServiceLocked -> ActiveServices.realStartServiceLocked -> ActiveServices.bumpServiceExecutingLocked -> ActiveServices.scheduleServiceTimeoutLocked

• AMS.MainHandler 设置超时消息ActivityManagerService.SERVICE_TIMEOUT_MSG

• 超时时间：前台SERVICE_TIMEOUT（20s）；后台SERVICE_BACKGROUND_TIMEOUT(200s)

总体流程图如下：

3)问题定位方法

1）打开system_app_anr@XXXX文件，查看ANR发生进程、进程号、主线程状态，是不是有明显的死锁或者明显binder调用阻塞；

2）如果是死锁，看业务代码即可；

3）如果是binder阻塞，查看binder调用链信息，查找对端进程及其对端进程调用stack，找到阻塞函数，如果system_app_anr@XXXX被截断，可以查看traces.txt文件；

4）如果是nativepollonce，可以查看BlockMonitor日志，是否主线程有比较耗时的操作；CPU占用率情况，iowait情况；最有效的是分析systrace日志；

5）如果system_app_anr@XXXX中没有发生anr的调用stack，一般是三种情况：

ANR进程处于D state，导致无法响应SIG 3信号，从而导致无法打印stack，可以通过sysrq信息确认；

ART处于死锁状态，由于ART本身bug导致无法处理SIG 3操作；

ANR进程获取不了足够的时间无法打印调用stack。

 

4)实例分析

https://blog.csdn.net/weixin_29144347/article/details/117555447

https://blog.csdn.net/Code1994/article/details/120509705

https://blog.csdn.net/xct841990555/article/details/127874020

（可以参考看看）

附录:

怎么寻找binder对端信息？

发生SWT时，backtrace经常会卡在binder client端等待binder server端返回：IPCThreadState:waitForResponse-->IPCThreadState:talkWithDriver,需要找到server端的pid才能进行下一步分析。

1）根据binder client thread的sysTid在SYS_BINDER_INFO/SWT_JBT_TRACES中查找binder通信对端，关键字“outgoing transaction"”:
SYS_BINDER_INFO/ SWT_JBT_TRACES中可以查看binder信息:
Outgoing: Current thread is performing binder request to other process
Incoming: Current thread is performing binder service for other process

2）在SYS_PROCESSES_AND_THREADS通过对端的sysTid查找process name

3） 如果对端是Monkey，比较特别，可以不用关注，除非是严重影响Monkey Test。

4）如果在SYS_BINDER_INFO中无法找到binder对端信息怎么办？
可以尝试在kernel_log中查找binder release的log (binder所在进程结束时会调用)

例如:kernel_log中
[543.692215].(6)[6750:kworker/6:1]binder: release 1035:1035 transaction 257798 out, still active
对应查找SYS_BINDER_INFO可以找到对端信息：
SYS_BINDER_INFO:
outgoing transaction 261951: 0000000000000000 from 670:670 to 1035:0 code 1 flags 10 pri0:120 r1 start
pending transaction 257798: 0000000000000000 from 1035:1035 to 670:0 code 5 flags 10 pri 0:118 r1 start
此处可以看到binder server端是670:0，表示没有空闲binder,需要查看对端情况，查看是否有卡住的情况。
如果binder server为0:0，表示binder server process已经挂掉，需要从log中查看是否有其它相关信息。

5）如果按照上述方法依然找不到对端，只能按照code逻辑关系排查。

一些异常日志可以关注：

IPCThreadState: binder thread pool (15/31 threads) starved for xxx ms 功能说明:当 system_server 等进程的线程池使用完, 无空闲线程时, 则 binder 通信都处于饥饿状态, 则饥饿状态超过一定阈值则输出信息; log 解析: system_server 进程的 线程池已满的持续长达 xxxx ms.

 

JavaBinder: !!! FAILED BINDER TRANSACTION !!! log 解析:binder 传输出错，有可能是传输的数据太大导致

 

Looper : Slow dispatch took 92974ms main h=android.os.Handler c = com.android.server.locksettings. -$$Lambda$LockSettingsService$ log 解析:LockSettingsService 卡顿，耗时 92974ms

 

[101:kswapd0]lowmemorykiller: Killing ‘earchbox:search’ (3881), adj 900, log 解析:lowmemorykiller都是从大kill到小，adj 越小说明系统 lowmemory 越严重。 从CPU usage里 Free memory until OOME 的值很小的时候，已经处于内存紧张状态。应用可能是占用了过多内存。 另外，除了trace文件中有内存信息，普通的eventlog日志中，也有内存信息（不一定打印） 04-02 22:00:08.195  1531  1544 I am_meminfo:[xxxxx,xxxxx,xxxxx,xxxxx,xxxxx] 以上四个值分别指的是：Cached，Free,Zram,Kernel,Native Cached+Free的内存代表着当前整个手机的可用内存，如果值很小，意味着处于内存紧张状态。一般低内存的判定阈值为：4G 内存手机以下阀值：350MB，以上阀值则为：450MB ps:如果ANR时间点前后，日志里有打印onTrimMemory，也可以作为内存紧张的一个参考判断。

 

Dropbox 中重点看 total,CPU 占用率、IOwait。对于 IOwait 来说，高于 5%其实就已经危险了，达到 10%就有很大几率产生 ANR 了，至于 IOwait 为什么会产生，基本上有三种情况：大文件读写（main-log 关键字： “inputstream”）内存整理（关键字：“kswapd0”、“lost ram”）系统 dump log（main-log 关键字：“dump”）。

 

swap分区的作用是当物理内存不足时，会将一部分硬盘当做虚拟内存来使用。kswapd0 占用过高是因为 物理内存不足，使用swap分区与内存换页操作交换数据，导致CPU占用过高。低内存时候，kswapd0会很高，同时也会影响到io此时，系统一般都会存在卡顿等现象，iowait也会存在异常。

 

线程状态为“Blocked”，一般我们在trace-log里边看到主线程存在held by thread XXX，可以根据XXX内容找到是哪个线程block了主线程,进一步确认哪个线程拿住了锁，如有死锁检查code逻辑进行解锁； 线程状态为“Waiting”，表示当前线程需要另外一个线程来notify()，需要根据callstack结合code来做分析，以找到是另外的某个线程拿住了锁。 如果很多线程在等同一把锁，可能产生资源竞争问题，导致某些线程可能拿不到锁。

 

线程状态为“Native”，且含有如下callstack： IPCThreadState::waitForResponse–>IPCThreadState::talkWithDriver， 当trace-log中出现talkWithDriver关键字时，一般都是卡在了对端导致产生ANR，从而查看binder-info内容，以此定位对端信息。从对端thread的callstack中确认卡住的接口，并请对端相关的owner帮忙解决。

 

proc xxx xxx为线程的id，定位binder-info线程时可以快速定位

 

SurfaceFlinger卡住 SF hang Time>40s (Service.sf.status值),sf hang, 直接在”SYS_ANDROID_LOG"搜索"I watchdog"，看是否有“surfaceflinger hang”关键字

 

线程状态为”Native”，确认callstack中有”Process.zygoteSendArgsAndGetResult”， 对于Zygote fork进程时卡住的问题，一般是由于底层memory问题引起的，请检查是否有memory不足或者memory leak的问题

 

Dump时间过长 1）前面有ANR发生： a. 前面有ANR发生，”ActivityManager” 线程正在做dump操作，通过如 下 callstack确认： appNotResponding, dumpStackTraces b. 从“SYS_ANDROID_LOG”中确认是dump哪一个进程花的时间过长 c. 搜索关键字”dumpStackTraces process”来确认ANR发生时所dump的进程 d. 通过dump的上一个进程与下一个进程来确认时间差是否大于60s，或者所有的 dump时间加起来远远超过60s e. ANR所引起的dump时间过长，需要看是否某个进程dump时间过长，并确认其原因 2）前面有fatal JE、NE、KE等Exception发生； 自动化测试脚本主动call “dumpsys”去dump系统信息： a. 通过callstack中确认是其他进程通过binder call发起AMS进行dump b. 自动化测试脚本一般是进程“adb” call进来的，该类SWT一般也不用关注，只会在eng/userdebug版本下，或者开启mtklog后才会发生 注意：这种dump所导致的SWT，一般来说是系统loading过重，或者需要dump的信息确实过多所引起。终端用户不会发生这类问题，建议不用过多关注。

 

JE (Java layer exception)	一般是在应用层和框架层发生的异常，通常是由Java代码，XML代码引起的。比如各种RuntimeException, ANR（Application Not Responding）、SWT（Software Watchdog Timeout）等
NE (Native layer exception)	发生在Linux用户空间的异常，通常是由C/C++代码和库文件引起的。比如内核发出的NE信号（SIGILL、 SIGABRT、 SIGBUS等）
KE (Kernel layer execption)	通常指内核故障或内核错误，由于在内核模式下出错，这类异常是非常严重的，往往会导致重启、死机或无法开机等
EE (External (Modem) exception)	从名字看就能猜到Modem这一部分是比较特殊的，独立的。Modem有自己的内存空间和代码，为手机通讯提供服务，一旦这一部分发生异常，需要MDlog，此log需用AEE-LogVie工具解析，解析是需要对应版本的数据文件