Android ANR问题总结

转载自:https://blog.csdn.net/jiangguohu1/article/details/52636470

一，什么是ANR？

        所谓ANR也就是Application not responsing，即应用程序无响应。在Android中，AMS和WMS会监测应用程序的响应时间，如果应用程序主线程在超时时间内对输入事件没有处理完毕或对特定的操作没有执行完毕，就会出现ANR。对于输入事件没有处理完毕的ANR，Android会弹出一个对话框，提示用户当前应用程序没有响应，用户可以选择继续等待或者关闭这个应用程序（也就是杀掉这个进程）。

二，ANR问题的产生

系统原因：由于kernel/Framework/Driver等存在问题，导致系统不稳定最终变现出ANR

应用原因：线程死锁、阻塞或性能低下。需避免将耗时操作放在主线程。

三，ANR问题的分类

InputDispatchingTimedOut

 应用程序主线程在5秒内没有完成用户的input事件（比如按键事件、屏幕触摸事件）

Service Timeout 

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

Broadcast Timeout

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

Content Provider Timeout

 应用程序在20秒内没有执行完成ContentProvider相关操作

四，ANR问题的分析流程

1，Find ANR time，PID，ANR type
2，Find JE/NE before ANR

3，Check trace.txt mapping process ID and time stamp
4，Check CPU usage
5，Find some more information about main thread through main log and event log

至于上面说的ANR的trace.txt文件，展讯项目一般在log的mic文件夹里的snapshot文件里，MTK项目则需要用GAT工具解析DB文件，其trace信息都在DB中。

分析trace.txt文件一般照着下面的步奏来：

五，ANR案例分析

问题描述：插入usb线，锁屏界面有微博消息，双击进入微博黑屏，一会弹出微博无响应，log已抓，出现时间点：11:17分左右

分析步骤：

1，Find ANR time，PID，ANR type

[plain]  view plain  copy

1. <strong>event.log</strong>  
2. 02-03 <strong>11:15:12.971</strong> 581 619 I <strong>am_anr</strong> : [0,2152,com.sina.weibo,8928836,Input dispatching timed out (Waiting because  
3. no window has focus but there is a focused application that may eventually add a window when it finishes starting up.)]  

[plain]  view plain  copy

1. <strong>main.log</strong>  
2. 02-03 11:15:12.991 581 619 I Process : Sending signal. <strong>PID: 2152</strong> SIG: 3  

[plain]  view plain  copy

1. <strong>system.log</strong>  
2. 02-03 11:15:20.708 581 619 E ActivityManager: ANR in com.sina.weibo (com.sina.weibo/.PageActivity)  
3. 02-03 11:15:20.708 581 619 E ActivityManager: <strong>PID: 2152</strong>  
4. 02-03 11:15:20.708 581 619 E ActivityManager: Reason: <strong>Input dispatching timed out</strong> (Waiting because no window has  
5. focus but there is a focused application that may eventually add a window when it finishes starting up.)  
6. 02-03 11:15:20.708 581 619 E ActivityManager: Load: 6.53 / 5.46 / 4.61  
7. 02-03 11:15:20.708 581 619 E ActivityManager: CPU usage from 2098ms to -7885ms ago:  
8. 02-03 11:15:20.708 581 619 E ActivityManager:<strong> 50% 62/kswapd0</strong>: 0% user + 50% kernel  
9. 02-03 11:15:20.708 581 619 E ActivityManager: 48% 581/system_server: 22% user + 25% kernel / faults: 19785 minor  
10. 279 major  
11. 02-03 11:15:20.708 581 619 E ActivityManager: 32% 2152/com.sina.weibo: 20% user + 11% kernel / faults: 28017  
12. minor 1509 major  

由此可见该问题属于： InputDispatchingTimedOut

2，Find JE/NE before ANR

没有异常

3，Check trace.txt mapping process ID and time stamp

[plain]  view plain  copy

1. <strong>snapshot_11-15-14.txt</strong>  
2. DALVIK THREADS (52):  
3. "main" prio=5 tid=1 Native  
4. | group="main" sCount=1 dsCount=0 obj=0x74c41f50 self=0xb4827800  
5. | sysTid=2152 nice=-6 cgrp=default sched=0/0 handle=0xb6fd4bec  
6. | state=S schedstat=( 0 0 0 ) utm=206 stm=145 core=3 HZ=100  
7. | stack=0xbe076000-0xbe078000 stackSize=8MB  
8. | held mutexes=  
9. native: #00 pc 000133cc /system/lib/libc.so (syscall+28)  
10. native: #01 pc 000a9a83 /system/lib/libart.so (art::ConditionVariable::Wait(art::Thread*)+82)  
11. native: #02 pc 001ad609 /system/lib/libart.so (art::JNI::IsInstanceOf(_JNIEnv*, _jobject*, _jclass*)+1024)  
12. native: #03 pc 00087be9 /system/lib/libandroid_runtime.so (???)  
13. native: #04 pc 000880a5 /system/lib/libandroid_runtime.so (android::ibinderForJavaObject(_JNIEnv*, _jobject*)+32)  
14. native: #05 pc 0008315d /system/lib/libandroid_runtime.so (???)  
15. native: #06 pc 0026495d /data/dalvik-cache/arm/system@framework@boot.oat  
16. (Java_android_os_Parcel_nativeWriteStrongBinder__JLandroid_os_IBinder_2+120)  
17. at android.os.Parcel.<strong>nativeWriteStrongBinder</strong>(Native method)  
18. at android.os.Parcel.writeStrongBinder(Parcel.java:559)  
19. at android.view.IWindowManager$Stub$Proxy.openSession(IWindowManager.java:1065)  
20. at android.view.WindowManagerGlobal.getWindowSession(WindowManagerGlobal.java:160)  
21. - locked <@addr=0x7145f718> (a java.lang.Class<android.view.WindowManagerGlobal>)  
22. at android.view.ViewRootImpl.<init>(ViewRootImpl.java:355)  
23. at android.view.WindowManagerGlobal.addView(WindowManagerGlobal.java:271)  
24. - locked <@addr=0x22db7d40> (a java.lang.Object)  
25. at android.view.WindowManagerImpl.addView(WindowManagerImpl.java:85)  
26. at android.app.ActivityThread.handleResumeActivity(ActivityThread.java:3113)  
27. at android.app.ActivityThread.handleLaunchActivity(ActivityThread.java:2418)  
28. at android.app.ActivityThread.access$800(ActivityThread.java:154)  

在上述中：线程的名字(“main”)，线程优先级(“prio”), 线程id(“tid”) 以及线程的类型(“Native”)。

线程所述的线程组 (“main”), 线程被正常挂起的次处(“sCount”)，线程因调试而挂起次数(“dsCount ”)，当前线程所关联的java线程对象(“obj ”)以及该
线程本身的地址(“self ”)。该线程在linux系统下的本地线程id (“sysTid ”)，线程的调度优先级(“nice ”)，调度策略(sched ) ，优先组属(cgrp=no-cpu-subsys)以及
处理函数地址(“handle”)

可见没有“held by thread”信息，没有发生block。接下啦查看CPU信息。

4，Check CPU usage

再去查看当时内存信息：可用内存MemFree + Cached: 12164 kB + 211060 kB
上述的IOWAIT接近但是还没有超过20%，也不算是很高，当时手机也不是处于低内存环境下。

5，Find some more information about main thread through main log and event log

查看启动PageActivity后和发生anr之前的相关log，发现接连启动了两个关于美图的进程。14715，14770。(这两个是美图的service请求启动的)

[plain]  view plain  copy

1. <strong>02-03 11:15:06.414 581 1170 I am_restart_activity: [0,308705919,76,com.sina.weibo/.PageActivity</strong>  
2. 02-03 11:15:06.424 581 1170 I am_focused_activity: [0,com.sina.weibo/.PageActivity]  
3. <strong>02-03 11:15:07.425 581 731 I am_proc_start:  
4. [0,14715,10096,com.mt.mtxx.mtxx:pushservice,service,com.mt.mtxx.mtxx/com.igexin.sdk.PushService]</strong>  
5. 02-03 11:15:07.485 581 916 I am_proc_bound: [0,14715,com.mt.mtxx.mtxx:pushservice]  
6. <strong>02-03 11:15:09.988 581 1148 I am_proc_start:  
7. [0,14770,10096,com.mt.mtxx.mtxx,service,com.mt.mtxx.mtxx/com.igexin.sdk.PushServiceUser]</strong>  
8. 02-03 11:15:10.088 581 672 I am_proc_bound: [0,14770,com.mt.mtxx.mtxx]  
9. 2-03 11:15:12.440 2152 2152 I am_on_performance: [0,com.sina.weibo.PageActivity, onCreate cost 5295ms]  
10. <strong>02-03 11:15:12.971 581 619 I am_anr :</strong> [0,2152,com.sina.weibo,8928836,Input dispatching timed out (Waiting  
11. because no window has focus but there is a focused application that may eventually add a window when it finishes starting  
12. up.)]  

这两个进程占用了大约96M的内存。

[plain]  view plain  copy

1. u0_a96 14715 253 1007376 49812 ffffffff b6e71f7c S com.mt.mtxx.mtxx:pushservice  
2. u0_a96 14770 253 1006276 47184 ffffffff b6e71f7c S com.mt.mtxx.mtxx  

这个是导致kswapd0 cpu占用率高的主要原因.

[plain]  view plain  copy

1. 02-03 11:15:12.961 581 619 D SprdRuntimeInfo: PID USER SYSTEM TOTAL NAME  
2. 02-03 11:15:12.961 581 619 D SprdRuntimeInfo: 62 0.00% 50.33% 50.33% kswapd0  
3. ...  
4. 02-03 11:15:12.961 581 619 D SprdRuntimeInfo: PID USER SYSTEM TOTAL NAME  
5. 02-03 11:15:12.961 581 619 D SprdRuntimeInfo: 62 0.00% 45.00% 45.00% kswapd0  

综上所述：新浪微博com.sina.weibo/.PageActivity这个界面执行onCreate方法时，美图(com.mt.mtxx)同时启动了两个进程com.mt.mtxx.mtxx:pushservice和com.mt.mtxx.mtxx，占用了较多内存(kswapd0占用cpu偏高)，使得系统繁忙。导致com.sina.weibo/.PageActivity执行onCreate方法耗时达到了5s之多，发生anr。

由于美图和新浪均没有源码，只能得出上面的那个结论。

ANR的问题不像别的问题那样，只要按着上面步奏来，基本上半数以上问题都能够解决。分析ANR问题是一个长期积累的过程。