ANR分析

1.什么是ANR

ANR即Application Not Responding，顾名思义就是应用程序无响应。在Android中，一般情况下，四大组件均是工作在主线程中的，Android中的Activity Manager和Window Manager会随时监控应用程序的响应情况，如果因为一些耗时操作（网络请求或者IO操作）造成主线程阻塞一定时间，那么系统就会显示ANR对话框提示用户对应的应用处于无响应状态。

2.为什么会发生ANR

一句话总结:主线程没有在规定的时间内，做完要做的事情，就会发生ANR。

• Input事件超过5s没有被处理完
• Service处理超时，前台20s，后台200s
• BroadcastReceiver处理超时，前台10s，后台60s
• ContentProvider执行超时10s

activity/broadcast/contentProvider超时(ActivityManagerService.java):

service超时(ActiveServices.java):
从发生的原因分:

• 主线程有耗时操作,如有复杂的layout布局,IO操作等;
• 被Binder对端block;
• 被子线程同步锁block;
• Binder被占满导致主线程无法和SystemServer通信;
• 得不到系统资源(CPU/RAM/IO);

从进程的角度分:

• 问题出在当前进程;
• 主线程本身耗时,或者主线程的消息队列存在耗时操作;
• 主线程被本进程的其他子线程block;
• 问题出在远端进程(一般是binder call或socket等通信方式);

3.怎么解决ANR

3.1 导出trace文件

如果ANR发生,对应的应用会收到SIGQUIT异常终止信号,dalvik虚拟机就会自动在/data/anr/目录下生成trace.txt文件,这个文件记录了在发生ANR时刻系统各个线程的执行状态,通过adb pull命令将这个文件导出分析。

3.2 trace文件格式解析

导出trace文件后，可以看到类似于如下的文件内容:

说明了发生ANR的进程id、时间和进程名称。

• tll:thread list lock
• tsl:thread suspend lock
• tscl:thread suspend count lock
• ghl:gc heap lock
• hwl:heap worker lock
• hwll:heap worker list lock

说明了线程名称、线程的优先级、线程锁id和线程状态。

线程名称是启动线程的时候手动指明的，这里的main标识是主线程，是Android自动设定的一个线程名称，如果是自己手动创建的线程，一般会被命名成“Thread-xx”的格式，其中xx是线程id，它只增不减不会被复用；
注意这其中的tid不是线程的id,它是一个在Java虚拟机中用来实现线程锁的变量，随着线程的增减，这个变量的值是可能被复用的；

最后线程的状态还分为如下几种:

• group:线程组名称;
• sCount:此线程被挂起的次数;
• dsCount:线程被调试器挂起的次数;当一个进程被调试后,sCount会重置为0,调试完毕后sCount会根据是否被正常挂起增长,但是dsCount不会被重置为0,所以dsCount也可以用来判断这个线程是否被调试过;
• obj:表示这个线程的Java对象的地址;
• self:表示这个线程本身的地址;

---

线程的调度信息:

• sysTid:Linux下的内核线程id;
• nice:线程的调度优先级;
• sched:分别标志了线程的调度策略和优先级;
• cgrp:调度属组;
• handle:线程的处理函数地址;

---

线程当前上下文信息:

• state:调度状态;
• schedstat:从 /proc/[pid]/task/[tid]/schedstat读出,三个值分别表示线程在cpu上执行的时间、线程的等待时间和线程执行的时间片长度,有的android内核版本不支持这项信息,得到的三个值都是0;
• utm:线程用户态下使用的时间值(单位是jiffies);
• stm:内核态下的调度时间值;
• core:最后执行这个线程的cpu核的序号;

3.3 trace文件分析

trace文件顶部的线程一般是ANR的元凶

这是一个简单的方法，但是大部分情况下都适用，可以通过这个方法来快速判断是否是自己的应用造成了本次ANR。但是，并不是trace文件包含的应用就一定是造成ANR的帮凶，应用出现在trace文件中，只能说明出现ANR的时候这个应用进程还活着，trace文件的顶部则是触发ANR的应用信息。因此，如果你的应用出现在了trace文件的顶部，那么很有可能是因为你的应用造成了ANR，否则是你的应用造成ANR的可能性不大，但是具体是不是还需要进一步分析。

注意死锁和等待

虽然说ANR一般情况是由于让主线程做了很多耗时的操作，但是死锁或者主线程等待也是ANR高发的原因。

3.3.1 案例一

----- pid 336 at 2019-01-01 03:38:12 -----
Cmd line: com.hhhh.core

JNI: CheckJNI is off; workarounds are off; pins=0; globals=190

DALVIK THREADS:
(mutexes: tll=0 tsl=0 tscl=0 ghl=0)

“main” prio=5 tid=1 NATIVE
| group=“main” sCount=1 dsCount=0 obj=0x1b5baca8 self=0x1b4f2410
| sysTid=336 nice=0 sched=0/0 cgrp=apps handle=436691284
| state=S schedstat=( 635623326 144405342424 ) utm=50 stm=13 core=3
#00 pc 00020660 /system/lib/libc.so (__ioctl+8)
#02 pc 0001d3ed /system/lib/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+140)
#05 pc 00019791 /system/lib/libbinder.so (android::BpBinder::transact(unsigned int,android::Parcel const&, android::Parcel*, unsigned int)+30)
#21 pc 0004e0a7 /system/lib/libandroid_runtime.so (android::AndroidRuntime::start(char const*, char const*)+354)
at android.os.BinderProxy.transact(Native Method)
at android.content.ContentProviderProxy.call(ContentProviderNative.java:634)
at android.provider.Settings$NameValueCache.putStringForUser(Settings.java:901)atandroid.provider.Settings$Global.putStringForUser(Settings.java:6020)
at android.provider.Settings$Global.putString(Settings.java:6010)atandroid.provider.Settings$Global.putInt(Settings.java:6098)
at com.hhhh.core.os.AutoService.initLocalStub(AutoService.java:206)
at com.hhhh.core.os.AutoService.onCreate(AutoService.java:100)
at android.app.ActivityThread.handleCreateService(ActivityThread.java:2558)
at android.app.ActivityThread.access$1800(ActivityThread.java:135)atandroid.app.ActivityThread$H.handleMessage(ActivityThread.java:1278)
at android.os.Handler.dispatchMessage(Handler.java:102)
at android.os.Looper.loop(Looper.java:136)
at android.app.ActivityThread.main(ActivityThread.java:5001)
at java.lang.reflect.Method.invokeNative(Native Method)
at java.lang.reflect.Method.invoke(Method.java:515)
at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:829)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:645)
at dalvik.system.NativeStart.main(Native Method)

虽然应用com.hhhh.core出现在了trace文件中，但是在ANR的时候它在通过IPCThread在进行进程间通信，可查看远端进程binder的block。

3.3.2 案例二

----- pid 13406 at 2015-11-27 11:46:14 -----
Cmd line: com.android.example

JNI: CheckJNI is off; workarounds are off; pins=0; globals=536 (plus 102 weak)

DALVIK THREADS:
(mutexes: tll=0 tsl=0 tscl=0 ghl=0)

“main” prio=5 tid=1 SUSPENDED
| group=“main” sCount=1 dsCount=0 obj=0x41795e58 self=0x416b58b0
| sysTid=13406 nice=-6 sched=0/0 cgrp=apps handle=1074557268
| state=S schedstat=( 2352435524847736727917292 2633566 ) utm=213075 stm=22168 core=1 > at java.lang.String.(String.java:~261)
at java.util.zip.ZipEntry.(ZipEntry.java:392)
at java.util.zip.ZipFile.readCentralDir(ZipFile.java:414)
at java.util.zip.ZipFile.(ZipFile.java:151)
at java.util.zip.ZipFile.(ZipFile.java:123)
at com.android.example.Utility.isValideFile(Utility.java:2700)
at com.android.example.Test.getPath(Test.java:243)
at com.android.example.Test$1.run(Test.java:531)atandroid.os.Handler.handleCallback(Handler.java:733)atandroid.os.Handler.dispatchMessage(Handler.java:95)atandroid.os.Looper.loop(Looper.java:136)atandroid.app.ActivityThread.main(ActivityThread.java:5050)atjava.lang.reflect.Method.invokeNative(NativeMethod)atjava.lang.reflect.Method.invoke(Method.java:515)atcom.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:807)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:623)
at dalvik.system.NativeStart.main(Native Method) …

这种情况说明ANR发生于com.android.example应用中，而且指明了ANR发生时代码的执行位置，很有可能是我们应用程序的问题，之后就需要通过这个trace文件指明的路径来对代码进行排查。

3.3.3 案例三

----- pid 260 at 2019-01-01 03:38:12 -----
Cmd line: system_server

JNI: CheckJNI is off; workarounds are off; pins=3; globals=470 (plus 7 weak)

DALVIK THREADS:
(mutexes: tll=0 tsl=0 tscl=0 ghl=0)

“Binder_3” prio=5 tid=36 MONITOR
| group=“main” sCount=1 dsCount=0 obj=0x1ba19088 self=0x37d1d7b8
| sysTid=358 nice=0 sched=0/0 cgrp=apps handle=936498544
| state=S schedstat=( 30849332 9234666273 ) utm=3 stm=0 core=0
at com.android.server.content.ContentService.getSyncManager(ContentService.java:~72)
waiting to lock <0x1b810a88> (a java.lang.Object) held by tid=12 (SystemServerBolt)
at com.android.server.content.ContentService.notifyChange(ContentService.java:283)
at android.content.ContentResolver.notifyChange(ContentResolver.java:1621)
at com.android.providers.settings.SettingsProvider.sendNotify(SettingsProvider.java:262)
at com.android.providers.settings.SettingsProvider.insertForUser(SettingsProvider.java:941)
at com.android.providers.settings.SettingsProvider.call(SettingsProvider.java:651)
at android.content.ContentProvider$Transport.call(ContentProvider.java:325)
at android.content.ContentProviderNative.onTransact(ContentProviderNative.java:275)
at android.os.Binder.execTransact(Binder.java:404)
at dalvik.system.NativeStart.run(Native Method)

“SystemServerBolt” prio=5 tid=12 SUSPENDED
| group=“main” sCount=1 dsCount=0 obj=0x1b660bc8 self=0x35b11010
| sysTid=278 nice=0 sched=0/0 cgrp=apps handle=900797544
| state=S schedstat=(19928119035 1036843972 8896 ) utm=1729 stm=263 core=3
at java.io.FileInputStream.available(FileInputStream.java:~110)
at java.io.InputStreamReader.read(InputStreamReader.java:223)
at org.kxml2.io.KXmlParser.fillBuffer(KXmlParser.java:1506)
at org.kxml2.io.KXmlParser.peekType(KXmlParser.java:986)
at org.kxml2.io.KXmlParser.next(KXmlParser.java:346)
at org.kxml2.io.KXmlParser.next(KXmlParser.java:310)
at com.android.server.content.SyncStorageEngine.readAccountInfoLocked(SyncStorageEngine.java:1701)
at com.android.server.content.SyncStorageEngine.(SyncStorageEngine.java:432)
at com.android.server.content.SyncStorageEngine.init(SyncStorageEngine.java:454)
at com.android.server.content.SyncManager.(SyncManager.java:383)
at com.android.server.content.ContentService.getSyncManager(ContentService.java:75)
at com.android.server.content.ContentService.systemReady(ContentService.java:157)
at com.android.server.ServerThread.makeContentServicerReady(SystemServer.java:886)
at com.ts.android.server.SystemServerThreadBolt.access$1700(SystemServerThreadBolt.java:84)
at com.ts.android.server.SystemServerThreadBolt$3.run(SystemServerThreadBolt.java:234)
at android.os.Handler.handleCallback(Handler.java:733)
at android.os.Handler.dispatchMessage(Handler.java:95)
at android.os.Looper.loop(Looper.java:136)
at android.os.HandlerThread.run(HandlerThread.java:61)

binder_3正处于monitor状态，也就是它在等待一个synchronized块或者方法，但是目前这个monitor正在被tid=12的线程持有，所以造成了此线程被阻塞。

mAccountInfoFile->accounts.xml文件地址：data/system/sync
accounts.xml文件乱码，读取时加了同步锁导致anr。

系统耗时分析方案

系统做了一些耗时分析的操作，Log里面有体现。

1. binder_sample

• 功能说明：监控每个进程的主线程的binder transaction的耗时情况, 当超过阈值时,则输出相应的目标调用信息，默认1000ms打开。
• log格式：52004 binder_sample (descriptor|3),(method_num|1|5),(time|1|3),(blocking_package|3),(sample_percent|1|6)
• log实例：2754 2754 I binder_sample: [android.app.IActivityManager,35,2900,android.process.media,5]
• log解释：执行android.app.IActivityManager接口时，所对应方法code =35(即STOP_SERVICE_TRANSACTION)，花费了2900ms，block在package为 android.process.media的地方。

2. dvm_lock_sample

• 功能说明：当某个线程等待lock的时间blocked超过阈值,则输出当前的持锁状态 ;
• log格式: 20003 dvm_lock_sample (process|3),(main|1|5),(thread|3),(time|1|3),(file|3),(line|1|5),(ownerfile|3),(ownerline|1|5),(sample_percent|1|6)
• log实例：dvm_lock_sample: [system_server,1,Binder_9,1500,ActivityManagerService.java,6403,-,1448,0]
• log解释：当system_server进程中的Binder_9线程执行到ActivityManagerService.java的6403行代码时,一直在等待AMS锁, 但该锁被同一文件的1448行代码所持有, 从而导致Binder_9线程被阻塞1500ms.