android ANR异常分析技巧总结

前言
ANR异常是android开发中比较常见的异常之一，最近为了看ANR异常，差了不少资料，现在做一个总结。
本文将从以下几个角度来总结ANR异常分析：

1.ANR类型
2.ANR产生的原因
3.ANR日志来源
4.分析ANR问题的套路
1. ANR类型
ANR类型按报错类型主要有Input（输入事件）、Broadcast（广播）、Service（服务）， 对应产生ANR的时间分别为：

类型    前台应用    后台应用
Input    5s    5s
Broadcast    10s    6s
Service    20s    200s
上面的只是原生数据，各个厂商可能会对数据进行修改。并且前台应用和后台应用判断是否ANR的时间是不一样的。其中Input时间会直接弹出ANR弹框， 另外的异常如果用户不操作， 只会打印日志，不会弹弹框。

2. ANR产生的原因
产生ANR的原因本质都是：主线程未在规定时间内完成代码的执行， 具体的原因有：

1.耗时操作， 如复杂的Layout，庞大的for循环， IO操作等
2.被Binder 对端block
3.被子线程同步锁block
4.Binder被占满导致主线程无法和System_server进程通信
5.得不到系统资源（CPU/RAM/IO）
第1点比较好理解， 就是在主线程耗时操作太多；

第2点指当前进程的主线程与其他进程进行Binder通信时， 由于Binder通信会让主线程挂起，等待对端的返回， 结果对端由于某些原因一直未返回， 导致当前进程的主线程无法往下执行而超市，产生ANR；

第3点是指主线程与其他线程公用锁但是一直未得到锁， 导致超时，产生ANR；

第4点是指主线程和System_server进程进行Binder通信，由于其他线程或者其他进程与System_server进程之间有太多Binder通信，将Binder池占满，导致主线程的Binder通信一直无法处理，超时产生ANR；

第5点是由于系统资源紧张，CPU占用率过高，负载过大，IO操作太多， 导致主线程无法得到CPU时间片等系统资源去执行，而产生ANR.

其中前四点比较好分析， 通过日志可以找到线索并解决， 而第五种定位比较困难， 因为第五种ANR情况更复杂， 甚至不是软件的问题。

3. ANR日志来源
如果是第三方数据上报，或者测试人员测试时抓取了日志， 我们可以直接查看日志， 但是如果使我们自己发现或者复现了问题，可以用以下方式获取日志：

3.1 traces.txt
ANR优先查看此日志， AMS在ANR发生的时候，dump相关进程（ANR的进程、systemserver、mediaserver，surfaceFinger等）的当前栈到traces.txt。需要注意的是，traces.txt是抓取的是超时后（如input超时就是5s后）的snapshot，并不一定能够真实的反应出block的点。也存在抓到主线程没有block，在idle的情况。

获取traces.txt的方式：adb pull /data/anr/traces.txt

3.2 applogcat-log
我们的logcat信息会打印在此处， 里面有较多的堆栈信息，按照日期，取出里面最新的日志。
获取applogcat-log方式：adb pull /data/log/android_logs

3.3 dropbox
里面会记录不同的错误信息日志， 日志命名格式为 AA_BB@CC.txt, 其中AA表示进程名，BB表示异常类型， CC为时间戳，如 system_server_anr@13457689.txt, 就表示一个ANR异常的日志文件， 找到自己对应的时间及进程的日志信息即可。此日志可作为一个线索。

获取方式：adb pull /data/system/dropbox

4. 分析ANR问题的套路
4.1 在主线程进行耗时操作
这个一般比较好排查，（这个正式APP现在一般也不会有吧。。。）， 如果看代码看不出， 可以看一下日志， 打开traces.txt文件， 看到的第一行是这样：

----- pid 13250 at 2018-01-01 23:56:09 -----
1
这个表示进程 13250 的日志就从这里开始了， 一般traces.txt文件的第一个进程就是发生ANR所在进程， 然后继续往下看， 找到主线程的日志， 举个栗子：

"main" prio=5 tid=1 Native
  | group="main" sCount=1 dsCount=0 obj=0x7425caf8 self=0xb4827800
  | sysTid=671 nice=0 cgrp=default sched=0/0 handle=0xb6febbec
  | state=S schedstat=( 0 0 0 ) utm=1853 stm=50 core=2 HZ=100
  | stack=0xbe7bd000-0xbe7bf000 stackSize=8MB
  | held mutexes=
  kernel: (couldn't read /proc/self/task/671/stack)
  native: #00 pc 000133cc  /system/lib/libc.so (syscall+28)
  native: #01 pc 000a9a83  /system/lib/libart.so (art::ConditionVariable::Wait(art::Thread*)+82)
  native: #02 pc 001b16f1  /system/lib/libart.so (art::JNI::NewString(_JNIEnv*, unsigned short const*, int)+640)
  native: #03 pc 00075887  /system/lib/libandroid_runtime.so (???)
  native: #04 pc 008570ab  /data/dalvik-cache/arm/system@framework@boot.oat (Java_android_database_CursorWindow_nativeGetString__JII+110)
  at android.database.CursorWindow.nativeGetString(Native method)
  at android.database.CursorWindow.getString(CursorWindow.java:438)
  at android.database.AbstractWindowedCursor.getString(AbstractWindowedCursor.java:51)
  at android.database.CursorWrapper.getString(CursorWrapper.java:114)
  at com.android.settings.ApnSettings.fillList(ApnSettings.java:259)
  at com.android.settings.ApnSettings.onResume(ApnSettings.java:208)
  at android.app.Fragment.performResume(Fragment.java:2096)
  at android.app.FragmentManagerImpl.moveToState(FragmentManager.java:928)
  at android.app.FragmentManagerImpl.moveToState(FragmentManager.java:1067)
  at android.app.FragmentManagerImpl.moveToState(FragmentManager.java:1049)
  at android.app.FragmentManagerImpl.dispatchResume(FragmentManager.java:1879)
  at android.app.Activity.performResume(Activity.java:6113)
  at android.app.ActivityThread.performResumeActivity(ActivityThread.java:3015)
  at android.app.ActivityThread.handleResumeActivity(ActivityThread.java:3061)
  at android.app.ActivityThread.handleLaunchActivity(ActivityThread.java:2415)
  at android.app.ActivityThread.access$800(ActivityThread.java:151)
  at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1313)
  at android.os.Handler.dispatchMessage(Handler.java:102)
  at android.os.Looper.loop(Looper.java:135)
  at android.app.ActivityThread.main(ActivityThread.java:5345)
  at java.lang.reflect.Method.invoke!(Native method)
  at java.lang.reflect.Method.invoke(Method.java:372)
  at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:947)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:742)

这一段日志中， 看到第一行的"main"就知道这就是主线程， main是线程名。然后从ApnSettings.java中可以看到fillList这个可能的耗时操作主线程处理的地方有OnResume和OnReceive，因为调用栈到这里就结束了。
且代码中存在使用HandlerThread异步处理这个操作的地方，可以借鉴下将OnResume和OnReceive这两处都放到HandlerThread中去做。

4.2 被Binder 对端block
 "main" prio=5 tid=1 Native
  | group="main" sCount=1 dsCount=0 obj=0x73ee6470 self=0xb4d76500
  | sysTid=22831 nice=0 cgrp=default sched=0/0 handle=0xb6f4bc00
  | state=S schedstat=( 0 0 0 ) utm=22 stm=22 core=0 HZ=100
  | stack=0xbe283000-0xbe285000 stackSize=8MB
  | held mutexes=
  native: #00 pc 000410ac  /system/lib/libc.so (__ioctl+8)
  native: #01 pc 000477e5  /system/lib/libc.so (ioctl+14)
  native: #02 pc 0001e7c5  /system/lib/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+132)
  native: #03 pc 0001ee17  /system/lib/libbinder.so (android::IPCThreadState::waitForResponse(android::Parcel*, int*)+38)
  native: #04 pc 0001efcd  /system/lib/libbinder.so (android::IPCThreadState::transact(int, unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+124)
  native: #05 pc 00019fb7  /system/lib/libbinder.so (android::BpBinder::transact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+30)
  native: #06 pc 00086de9  /system/lib/libandroid_runtime.so (???)
  native: #07 pc 00d94629  /data/dalvik-cache/arm/system@framework@boot.oat (Java_android_os_BinderProxy_transactNative__ILandroid_os_Parcel_2Landroid_os_Parcel_2I+140)
  at android.os.BinderProxy.transactNative(Native method)
  at android.os.BinderProxy.transact(Binder.java:503)
  at android.net.INetworkPolicyManager$Stub$Proxy.getNetworkPolicies(INetworkPolicyManager.java:410)
  at android.net.NetworkPolicyManager.getNetworkPolicies(NetworkPolicyManager.java:174)
  at com.android.settings.net.NetworkPolicyEditor.read(NetworkPolicyEditor.java:57)
  at com.android.settings.DataUsageSummary.onCreate(DataUsageSummary.java:361)
  at android.app.Fragment.performCreate(Fragment.java:2202)
  at android.app.FragmentManagerImpl.moveToState(FragmentManager.java:942)
  at android.app.FragmentManagerImpl.moveToState(FragmentManager.java:1148)
  at android.app.BackStackRecord.run(BackStackRecord.java:793)
  at android.app.FragmentManagerImpl.execPendingActions(FragmentManager.java:1535)
  at android.app.FragmentManagerImpl.executePendingTransactions(FragmentManager.java:562)
  at com.android.settings.SettingsActivity.switchToFragment(SettingsActivity.java:1084)
  at com.android.settings.SettingsActivity.onCreate(SettingsActivity.java:657)
  at android.app.Activity.performCreate(Activity.java:6251)
  at android.app.Instrumentation.callActivityOnCreate(Instrumentation.java:1110)
  at android.app.ActivityThread.performLaunchActivity(ActivityThread.java:2370)
  at android.app.ActivityThread.handleLaunchActivity(ActivityThread.java:2477)
  at android.app.ActivityThread.-wrap11(ActivityThread.java:-1)
  at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1345)
  at android.os.Handler.dispatchMessage(Handler.java:102)
  at android.os.Looper.loop(Looper.java:148)
  at android.app.ActivityThread.main(ActivityThread.java:5438)
  at java.lang.reflect.Method.invoke!(Native method)
  at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:762)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:652)

主从日志中看到调用了NetworkPolicyManager.getNetworkPolicies，然后就进行了Binder通信， 然后调用栈就终止在这里了，推断是对端block了， Binder通信的两端方法名是一致的， 所以可以再当前日志搜索getNetworkPolicies，找到对端：

"Binder_4" prio=5 tid=56 Blocked
  | group="main" sCount=1 dsCount=0 obj=0x1321a0a0 self=0xad31e200
  | sysTid=2491 nice=0 cgrp=default sched=0/0 handle=0x9fd00930
  | state=S schedstat=( 0 0 0 ) utm=46441 stm=46582 core=1 HZ=100
  | stack=0x9fc04000-0x9fc06000 stackSize=1014KB
  | held mutexes=
  at com.android.server.net.NetworkPolicyManagerService.getNetworkPolicies(NetworkPolicyManagerService.java:1696)
  - waiting to lock <0x07439315> (a java.lang.Object) held by thread 35
  at android.net.INetworkPolicyManager$Stub.onTransact(INetworkPolicyManager.java:145)
  at android.os.Binder.execTransact(Binder.java:453

被Tid=35的人拿住了一把锁（0x07439315），那么继续看tid=35是谁，有两种方法：

搜索tid=35
搜索0x07439315，找到 - locked <0x07439315> (a java.lang.Object)
"NetworkPolicy" prio=5 tid=35 TimedWaiting
  | group="main" sCount=1 dsCount=0 obj=0x12d98940 self=0x9f91f700
  | sysTid=2415 nice=0 cgrp=default sched=0/0 handle=0xa0f33930
  | state=S schedstat=( 0 0 0 ) utm=7681 stm=7783 core=0 HZ=100
  | stack=0xa0e31000-0xa0e33000 stackSize=1038KB
  | held mutexes=
  at java.lang.Object.wait!(Native method)
  - waiting on <0x02580c1b> (a java.lang.Object)
  at java.lang.Thread.parkFor$(Thread.java:1220)
  - locked <0x02580c1b> (a java.lang.Object)
  at sun.misc.Unsafe.park(Unsafe.java:299)
  at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:198)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2053)
  at java.util.concurrent.ArrayBlockingQueue.poll(ArrayBlockingQueue.java:372)
  at com.android.server.NativeDaemonConnector$ResponseQueue.remove(NativeDaemonConnector.java:634)
  at com.android.server.NativeDaemonConnector.executeForList(NativeDaemonConnector.java:426)
  at com.android.server.NativeDaemonConnector.execute(NativeDaemonConnector.java:345)
  at com.android.server.NativeDaemonConnector.execute(NativeDaemonConnector.java:340)
  at com.android.server.NetworkManagementService.setInterfaceQuota(NetworkManagementService.java:1712)
  - locked <0x0b0f91b8> (a java.lang.Object)
  at com.android.server.net.NetworkPolicyManagerService.setInterfaceQuota(NetworkPolicyManagerService.java:2421)
  at com.android.server.net.NetworkPolicyManagerService.updateNetworkRulesLocked(NetworkPolicyManagerService.java:1232)
  at com.android.server.net.NetworkPolicyManagerService$14.onReceive(NetworkPolicyManagerService.java:1060)
  - locked <0x07439315> (a java.lang.Object)
  at android.app.LoadedApk$ReceiverDispatcher$Args.run(LoadedApk.java:881)
  at android.os.Handler.handleCallback(Handler.java:739)
  at android.os.Handler.dispatchMessage(Handler.java:95)
  at android.os.Looper.loop(Looper.java:148)
  at android.os.HandlerThread.run(HandlerThread.java:61)

可以看到，NetworkPolicy在通过NativeDaemonConnector和netd通信（setInterfaceQuota）
我们结合log来看下在发生ANR的前后的打印：

06-19 15:29:00.997  1235  1270 I am_anr  : [0,22831,com.android.settings,818429509,Input dispatching timed out (Waiting because no window has focus but there is a focused application that may eventually add a window when it finishes starting up.)]
  06-19 15:29:05.683  1235  2415 E NetdConnector: NDC Command {55445 bandwidth setiquota seth_w0 9223372036854775807} took too long (4755ms
  06-19 15:29:05.723  1235  2491 I dvm_lock_sample: [system_server,1,Binder_4,4919,NetworkPolicyManagerService.java,1696,-,1056,100]

从eventslog中还可以发现，setting出现了两次连续的ANR，而上下文中都有类似上面的dvm_lock_sample NetworkPolicyManagerService相关的告警。
因此虽然15:28的这次ANR并没有打出有用的栈，但是我们还是可以猜测出这两次ANR的原因都是netd的command耗时太久导致的（在主线程的调用路径上存在必然的block）
那么，在netd可能无法修改的情况下（至少应用层是无法修改的），我们只能将可能存在block的操作放到非UI线程中去做。

4.3 主线程被子线程同步锁block 导致ANR
这种问题和上面降到的Binder对端block的例子有一部分步骤相似， 只要在主线程的日志中看到这么一句：

 waiting to lock <0x07439315> (a java.lang.Object) held by thread 35
1
说明主线程正在等锁， held by thread 35 标识同步锁被线程号 35 所持有， 我们可以搜索这个线程号或者0x07439315， 去看看这个线程在做什么，找到问题原因。

4.4 系统资源紧张导致ANR
04-01 13:12:11.572 I/InputDispatcher( 220): Application is not responding:Window{2b263310com.Android.email/com.android.email.activity.SplitScreenActivitypaused=false}.  5009.8ms since event, 5009.5ms since waitstarted
04-0113:12:11.572 I/WindowManager( 220): Input event dispatching timedout sending tocom.android.email/com.android.email.activity.SplitScreenActivity
04-01 13:12:14.123 I/Process(  220): Sending signal. PID: 21404 SIG: 3
04-01 13:12:14.123 I/dalvikvm(21404):threadid=4: reacting to signal 3 
……
04-0113:12:15.872 E/ActivityManager(  220): ANR in com.android.email(com.android.email/.activity.SplitScreenActivity)
04-0113:12:15.872 E/ActivityManager(  220): Reason:keyDispatchingTimedOut
04-0113:12:15.872 E/ActivityManager(  220): Load: 8.68 / 8.37 / 8.53
04-0113:12:15.872 E/ActivityManager(  220): CPUusage from 4361ms to 699ms ago ----CPU在ANR发生前的使用情况

04-0113:12:15.872 E/ActivityManager(  220):   5.5%21404/com.android.email: 1.3% user + 4.1% kernel / faults: 10 minor
04-0113:12:15.872 E/ActivityManager(  220):   4.3%220/system_server: 2.7% user + 1.5% kernel / faults: 11 minor 2 major
04-0113:12:15.872 E/ActivityManager(  220):   0.9%52/spi_qsd.0: 0% user + 0.9% kernel
04-0113:12:15.872 E/ActivityManager(  220):   0.5%65/irq/170-cyttsp-: 0% user + 0.5% kernel
04-0113:12:15.872 E/ActivityManager(  220):   0.5%296/com.android.systemui: 0.5% user + 0% kernel
04-0113:12:15.872 E/ActivityManager(  220): 100%TOTAL: 4.8% user + 7.6% kernel + 87% iowait
04-0113:12:15.872 E/ActivityManager(  220): CPUusage from 3697ms to 4223ms later:-- ANR后CPU的使用量======later是标志
04-0113:12:15.872 E/ActivityManager(  220):   25%21404/com.android.email: 25% user + 0% kernel / faults: 191 minor
04-0113:12:15.872 E/ActivityManager(  220):    16% 21603/__eas(par.hakan: 16% user + 0% kernel
04-0113:12:15.872 E/ActivityManager(  220):    7.2% 21406/GC: 7.2% user + 0% kernel
04-0113:12:15.872 E/ActivityManager(  220):    1.8% 21409/Compiler: 1.8% user + 0% kernel
04-0113:12:15.872 E/ActivityManager(  220):   5.5%220/system_server: 0% user + 5.5% kernel / faults: 1 minor
04-0113:12:15.872 E/ActivityManager(  220):    5.5% 263/InputDispatcher: 0% user + 5.5% kernel
04-0113:12:15.872 E/ActivityManager(  220): 32%TOTAL: 28% user + 3.7% kernel

上述日志中，有这么三行：

04-01 13:12:14.123 I/Process( 220): Sending signal. PID: 21404 SIG: 3—发生ANR的时间和生成trace.txt的时间
04-0113:12:15.872 E/ActivityManager( 220): CPUusage from 4361ms to 699ms ago ----CPU在ANR发生前的使用情况
04-0113:12:15.872 E/ActivityManager( 220): 100%TOTAL: 4.8% user + 7.6% kernel + 87% iowait
04-0113:12:15.872 E/ActivityManager( 220): CPUusage from 3697ms to 4223ms later:-- ANR后CPU的使用量
从这个日志中可以看到CPU使用率很高，IO操作占比很大（87% iowait）， 由此导致系统资源紧张，但是也只能推测ANR非常可能由此产生，却不能100%确定， 因为这个CPU统计是一个时间段的，不是一个实时的， 具体还需要在日志中找找其他线索，以确定问题。