// ActivityManagerService.java // How long we allow a receiver to run before giving up on it. staticfinalintBROADCAST_FG_TIMEOUT=10 * 1000 * Build.HW_TIMEOUT_MULTIPLIER; staticfinalintBROADCAST_BG_TIMEOUT=60 * 1000 * Build.HW_TIMEOUT_MULTIPLIER;
// ContentResolver.java /** * How long we wait for an attached process to publish its content providers * before we decide it must be hung. * @hide */ publicstaticfinalintCONTENT_PROVIDER_PUBLISH_TIMEOUT_MILLIS= 10 * 1000 * Build.HW_TIMEOUT_MULTIPLIER;
注:以上超时的时间阈值,在一些特殊的情况下,也可以通过修改阈值来避免ANR。
3. ANR产生原因
ANR产生的原因,总的来说,通常有六种:
主线程 IO
多线程等锁
System_server watchdog
等待 Binder 对端返回数据
Binder 无空闲线程
系统资源紧张
3.1 主线程中有耗时/等待操作
android 应用程序都有一个主线程,这个主线程主要负责控制 UI 界面的显示、更新和控件交互(因此主线程通常又叫做UI线程),在 android 应用程序中,对于输入事件、broadcast 以及 service 的处理都是在这个主线程中。任何一个线程,简单点来说,其实都是一个 while 循环,在这个循环中,依次去做各种事,因此线程的工作流程显然是串行的,而非并行的。从另一个角度来说,这就意味着,在线程中,如果有一件事情没有完成,其它事情是决不可能被执行的。主线程也不例外,主线程要处理的各项事务(包括输入事件,广播,服务等)也必须按序一样一样来完成的。因此,如果主线程一直在做某件耗时的事情,或者在等待某些条件,就必然导致其它事务得不到及时处理,这就为 ANR 产生创造了条件。
03-01 17:34:02.641 5391 8174 W InputDispatcher: channel 'fb9318f PopupWindow:53fe386 (server)' ~ Consumer closed input channel or an error occurred. events=0x9 03-01 17:34:02.641 5391 8174 E InputDispatcher: channel 'fb9318f PopupWindow:53fe386 (server)' ~ Channel is unrecoverably broken and will be disposed! ... ... 03-01 17:34:10.387 5391 8174 I WindowManager: Input event dispatching timed out sending to PopupWindow:53fe386. Reason: Waiting because the focused window's input channel is not registered with the input dispatcher. The window may be in the process of being removed.
4. 如何分析ANR
ANR 分为前台 ANR(用户能感知到的,对用户体验影响大,需要弹框让用户决定退出还是等待)和后台 ANR(只抓取发生 ANR 进程的 trace,不会收集 CPU 信息,并且会在后台直接杀掉该无响应的进程,不会弹框提示用户);
前台 ANR 发生后,系统会马上去抓取现场信息用于调试分析,主要信息有:
am_anr 信息(Eventlog),这条 log 的时间最接近 ANR 发生的时间;
trace 信息,保存在 data/anr/ 目录下;
main log 中发生 ANR 的原因和 CPU 使用情况信息;
将 trace 文件和 CPU 使用情况保存到 data/system/dropbox 目录;
对用户感知的进程弹出 ANR 对话框,对用户不感知的发生 ANR 的进程直接杀掉;
分析步骤:
定位 ANR 发生的时间点;
查看 trace 信息;
分析是否有耗时的 message, binder 调用,锁的竞争,CPU 资源的抢占;
结合具体的业务场景的上下文来分析;
4.1 在log中搜索”am_anr”
1
01-29 15:12:47.938 1720 1798 I am_anr : [0,3108,com.miui.home,953794117,Input dispatching timed out (com.miui.home/com.miui.home.launcher.Launcher, 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: 5. Wait queue head age: 5799.1ms.)]
知道这个时间很重要,因为应用程序就是在这个时间段内,无法对外界的交互作出响应的。因此,我们应当重点查看这个时间段内主线程的所有 log(就是那些 pid 与 tid 相同,且都等于应用程序的进程 ID 的 log),从这些 log 我们也许可以看到在 ANR 期间,主线程在做些什么,这对于我们判断 ANR 的成因有一定的帮助。比如说,如果我们看到在这个时间段内,主线程打印了大量的与数据库相关的操作,那么就不难推测,很可能就是这些数据库操作,导致了阻塞;
4.2 在log中搜索”ANR in”
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15
01-29 15:12:47.953 3042 3164 I WtEventController: ANR com.miui.home 3108 01-29 15:12:52.810 1720 1798 E ActivityManager: ANR in com.miui.home (com.miui.home/.launcher.Launcher) 01-29 15:12:52.810 1720 1798 E ActivityManager: PID: 3108 01-29 15:12:52.810 1720 1798 E ActivityManager: Reason: Input dispatching timed out (com.miui.home/com.miui.home.launcher.Launcher, 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: 5. Wait queue head age: 5799.1ms.) 01-29 15:12:52.810 1720 1798 E ActivityManager: Load: 0.92 / 0.52 / 0.31 01-29 15:12:52.810 1720 1798 E ActivityManager: CPU usage from 37298ms to 0ms ago (2018-01-29 15:12:10.574 to 2018-01-29 15:12:47.872): 01-29 15:12:52.810 1720 1798 E ActivityManager: 13% 663/surfaceflinger: 6.3% user + 7.5% kernel / faults: 218 minor 2 major 01-29 15:12:52.810 1720 1798 E ActivityManager: 10% 1720/system_server: 6.4% user + 3.6% kernel / faults: 3751 minor 3 major 01-29 15:12:52.810 1720 1798 E ActivityManager: 8.9% 12029/com.tencent.mm: 7.2% user + 1.6% kernel / faults: 12889 minor 26 major 01-29 15:12:52.810 1720 1798 E ActivityManager: 6.2% 20598/ctrip.android.view:pushsdk.v1: 2.3% user + 3.8% kernel / faults: 12738 minor 1 major 01-29 15:12:52.810 1720 1798 E ActivityManager: 6.1% 29744/com.tencent.mm:tools: 4.3% user + 1.8% kernel / faults: 293 minor 01-29 15:12:52.810 1720 1798 E ActivityManager: 5.2% 3970/com.hxwj.wjjf: 4% user + 1.1% kernel / faults: 194 minor 01-29 15:12:52.810 1720 1798 E ActivityManager: 5.1% 7498/com.talk51.dasheng: 3.2% user + 1.8% kernel / faults: 568 minor 01-29 15:12:52.810 1720 1798 E ActivityManager: 4.7% 29530/com.tencent.mm:appbrand0: 3.4% user + 1.3% kernel / faults: 270 minor 01-29 15:12:52.810 1720 1798 E ActivityManager: 2.7% 22516/com.ss.android.ugc.live:push: 0% user + 2.7% kernel / faults: 9 minor
从上面这些信息,同样可以看到 ANR 的类型,进程名,进程 ID 等信息,而最重要的是还可以看到 ANR 发生之前与之后,各进程占用 CPU 的情况,以及 io 访问的情况,通过这些信息,我们可以作出一些判断:
如果 ANR 进程的 cpu 占用比别的进程都高得多,则显然应当关注该进程本身是否做了什么,是不是有大量耗时的操作;
如果是其它进程占用了很高的 CPU,比如说达到了百分之一百多,则有可能是 CPU 饥饿导致了 ANR;
at com.android.server.wm.WindowManagerService$H.handleMessage(WindowManagerService.java:8315) - waiting to lock <0x084ffe56> (a java.util.HashMap) held by thread 76 at android.os.Handler.dispatchMessage(Handler.java:102) at android.os.Looper.loop(Looper.java:148) ... ...
如何查找一个锁是被哪个线程锁住的?在 waiting to lock 的后面通常会有关键字 held by thread 76,根据这个线程序号,可以直接找到锁定的线程。也可以在 trace 文件中查找锁的数值关键字(如上面的<0x084ffe56> ),如果发现有 locked <0x084ffe56>,那么它就是在这个线程序中被锁定的,查找结果如下:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17
"Binder_A" prio=5 tid=76 Native | group="main" sCount=1 dsCount=0 obj=0x134490a0 self=0x55b18611f0 | sysTid=4276 nice=-3 cgrp=default sched=0/0 handle=0x7f7b6f6450 | state=S schedstat=( 155534146538 91307372331 509087 ) utm=8036 stm=7517 core=4 HZ=100 | stack=0x7f7b5fa000-0x7f7b5fc000 stackSize=1013KB | held mutexes= ... ... native: #02 pc 000000000002d584 /system/lib64/libbinder.so (_ZN7android14IPCThreadState14talkWithDriverEb+164) native: #03 pc 000000000002e050 /system/lib64/libbinder.so (_ZN7android14IPCThreadState15waitForResponseEPNS_6ParcelEPi+104) ... ... at com.android.server.wm.WindowStateAnimator.createSurfaceLocked(WindowStateAnimator.java:875) at com.android.server.wm.WindowManagerService.relayoutWindow(WindowManagerService.java:3264) - locked <0x084ffe56> (a java.util.HashMap) at com.android.server.wm.Session.relayout(Session.java:198) at android.view.IWindowSession$Stub.onTransact(IWindowSession.java:284) at com.android.server.wm.Session.onTransact(Session.java:130) at android.os.Binder.execTransact(Binder.java:453)