手记

(五十二) 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

原文出处

0人推荐
随时随地看视频
慕课网APP