（五十二） Android anr 分析步骤总结

前言：最近经手了比较多的anr问题，声明经手不是解决，只是从log上推断造成anr的原因，以此作为根据转交给对应的人来处理。

1. ANR简介

ANR全名Application Not Responding, 也就是"应用无响应". 当操作在一段时间内系统无法处理时, 系统层面会弹出ANR对话框.

通常在如下几种种情况下会弹出ANR对话框:

• 5s内无法响应用户输入事件(例如键盘输入, 触摸屏幕等).

• BroadcastReceiver的事件(onRecieve方法)在规定时间内没处理完(前台广播为10s，后台广播为60s)

• service 前台20s后台200s未执行完成  Timeout executing service（Android O多了个startForeground 5s限制）

造成以上情况的首要原因就是在主线程(UI线程)里面做了太多的阻塞耗时操作, 例如文件读写, 数据库读写, 网络查询等等.（或者调用Thread.join/LockSupport.park/wait/sleep造成的阻塞）

具体定义：

framework/base/services/core/java/com/android/server/am/ActivityManagerService.java:

// How long we allow a receiver to run before giving up on it.static final int BROADCAST_FG_TIMEOUT = 10*1000;static final int BROADCAST_BG_TIMEOUT = 60*1000;// How long we wait until we timeout on key dispatching.static final int KEY_DISPATCHING_TIMEOUT = 5*1000;

framework/base/services/core/java/com/android/server/am/ActiveServices.java

// How long we wait for a service to finish executing.static final int SERVICE_TIMEOUT = 20*1000;// How long we wait for a service to finish executing.static final int SERVICE_BACKGROUND_TIMEOUT = SERVICE_TIMEOUT * 10; // calling startForeground() before we ANR + stop it.static final int SERVICE_START_FOREGROUND_TIMEOUT = 5*1000;

2. ANR分析步骤

anr分析步骤我总结来看主要就如下5步。

2.1 events_log

查看event log确定anr时间点和发生anr的进程id

命令：grep "am_anr.*packageName" ./ -nri --include="events*"

比如：

06-22 23:15:36.257944 942 1021 I am_anr : [0,19721,com.android.chrome,-1463042491,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: 2. Wait queue head age: 5508.0ms.)]

从上面log可以看出是com.android.chrome 在6-22 23:15:36发生了anr，所处进程id为19721

2.2 sys_log

查看sys_log确定当时系统各项占用，虽然我一直对百分比占用很没谱

命令：grep "anr in packageName" ./ -nri --include="sys_log*"

然后vim到对应行

比如：

06-22 23:15:42.121724 942 1021 I AnrManager: dumpStackTraces end!06-22 23:15:42.159012 942 1021 I AnrManager: ANR in com.android.chrome (com.android.chrome/com.google.android.apps.chrome.Main), time=2400771406-22 23:15:42.159012 942 1021 I AnrManager: 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: 2. Wait queue head age: 5508.0ms.)06-22 23:15:42.159012 942 1021 I AnrManager: Load: 14.61 / 14.77 / 14.7106-22 23:15:42.159012 942 1021 I AnrManager: Android time :[2018-06-22 23:15:42.12] [24013.623]06-22 23:15:42.159012 942 1021 I AnrManager: CPU usage from 83364ms to 43ms ago (2018-06-22 23:14:12.849 to 2018-06-22 23:15:36.170):06-22 23:15:42.159012 942 1021 I AnrManager: 68% 942/system_server: 50% user + 17% kernel / faults: 267589 minor 3994 major06-22 23:15:42.159012 942 1021 I AnrManager: 21% 1715/com.android.systemui: 16% user + 5.5% kernel / faults: 133310 minor 4496 major

我们可以注意到sys_log时间点晚了不少

2.3 traces.txt

traces.txt主要是来确定下发生anr的时候的堆栈，如果打印出耗时操作的堆栈肯定最好了

发生anr后导出手机里/data/anr下的文件，文件名称一般是这样的“anr_2018-06-22-17-42-44-420”，之前我们通过events_log确定了anr发生时间，这时通过时间找对应文件。

比如上面举的chrome例子：anr_2018-06-22-23-15-36-796 这个文件所对应的时间是差不多的，打开瞅一下。

----- pid 19721 at 2018-06-22 23:15:36 -----
Cmd line: com.android.chrome

前两行 pid 19721对的上，时间时分秒对的上，包名com.android.chrome对的上。

"main" prio=5 tid=1 Waiting| group="main" sCount=1 dsCount=0 flags=1 obj=0x725815f0 self=0xeb15b000| sysTid=19721 nice=-4 cgrp=default sched=0/0 handle=0xef2134a4| state=S schedstat=( 1948839680 121430176 1126 ) utm=134 stm=60 core=7 HZ=100| stack=0xff29c000-0xff29e000 stackSize=8MB| held mutexes=at java.lang.Object.wait(Native method)- waiting on <0x064cfca3> (a java.lang.Object)at java.lang.Thread.parkFor$(Thread.java:2137)- locked <0x064cfca3> (a java.lang.Object)at sun.misc.Unsafe.park(Unsafe.java:358)at java.util.concurrent.locks.LockSupport.park(LockSupport.java:190)at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:868)at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1021)at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1328)at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:232)at org.chromium.components.signin.AccountManagerFacade.getGoogleAccounts(AccountManagerFacade.java:37)at org.chromium.components.signin.AccountManagerFacade.tryGetGoogleAccounts(AccountManagerFacade.java:47)at org.chromium.components.signin.AccountManagerFacade.tryGetGoogleAccountNames(AccountManagerFacade.java:30)at org.chromium.chrome.browser.ChromeTabbedActivity.finishNativeInitialization(ChromeTabbedActivity.java:158)at org.chromium.chrome.browser.init.ChromeBrowserInitializer$9.run(ChromeBrowserInitializer.java:3)at org.chromium.chrome.browser.init.ChainedTasks$1.run(ChainedTasks.java:7)at android.os.Handler.handleCallback(Handler.java:790)at android.os.Handler.dispatchMessage(Handler.java:99)at android.os.Looper.loop(Looper.java:168)at android.app.ActivityThread.main(ActivityThread.java:6555)at java.lang.reflect.Method.invoke(Native method)at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:438)at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:857)

从堆栈来看是由于chrome调用getGoogleAccounts继而调用到LockSupport.park-->Object.wait，导致UI线程一直在等待造成anr。（这里其实不严谨，没有直接log作证，万一人家刚wait没多久只是之前一个操作耗时长呢）

由于没有chrome代码，这个故障只好不了了之了，但从堆栈可以看到有可能是哪个模块没有及时调用LockSupport.unpark导致的anr，这样就到应用级别了，需要应用继续往下看。

2.4 main_log

main_log主要是针对应用的log打印的，但有时候追溯问题还是会回到sys_log，主要看是阻塞在应用层还是framework或者native 驱动都说不准。

anr主要是发生在应用的主线程即Ui线程中，那么main_log里搜索对应的 线程号=进程号的log看下。

比如上面的chrome搜索：grep " 19721 19721 " ./ -nr --include="main*"

时间点关注：6-22 23:15:30 - 23:15:36 左右的log，毕竟主要是这5s导致的anr

2.5 综合考虑

其实traces.txt中打印的堆栈有可能是主要原因，有可能是次要原因，也有可能只是个躺枪的，毕竟anr的时间段，就以点击事件anr 5s为例，5s点下去了各个方法都会有耗时，如果一个方法占用了1s，另外一个占用了3s多，最后的一个方法刚开始执行anr就把他堆栈打印出来了那不是很冤。

如果有条件当然是从各种log推断各个方法分别耗时多少，然后综合评判哪个方法可以优化，哪个方法由于外部原因不可避免的耗时延长这都是要看下的。

另外原因也分直接原因和根本原因，比如直接原因是主线程wait了，那根本原因看下是谁让他wait或者谁没及时notify呢。

3. 总结

anr的问题如果traces.txt堆栈打印的很明白，log里也有对应证据，那还是很好的，就怕anr 好几个方法都贡献点延迟，log没有，想调试的话anr一般是monkey中跑出来的，调试难度比较大，那真是欲仙欲死。

本地免log调试可以参考：（四十三）统计应用具体方法执行时长-Android Profiler CPU

原文出处