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.coreJNI: 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 N a m e V a l u e C a c h e . p u t S t r i n g F o r U s e r ( S e t t i n g s . j a v a : 901 ) a t a n d r o i d . p r o v i d e r . S e t t i n g s NameValueCache.putStringForUser(Settings.java:901) at android.provider.Settings NameValueCache.putStringForUser(Settings.java:901)atandroid.provider.SettingsGlobal.putStringForUser(Settings.java:6020)
at android.provider.Settings G l o b a l . p u t S t r i n g ( S e t t i n g s . j a v a : 6010 ) a t a n d r o i d . p r o v i d e r . S e t t i n g s Global.putString(Settings.java:6010) at android.provider.Settings Global.putString(Settings.java:6010)atandroid.provider.SettingsGlobal.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 ( A c t i v i t y T h r e a d . j a v a : 135 ) a t a n d r o i d . a p p . A c t i v i t y T h r e a d 1800(ActivityThread.java:135) at android.app.ActivityThread 1800(ActivityThread.java:135)atandroid.app.ActivityThreadH.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.exampleJNI: 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. r u n ( T e s t . j a v a : 531 ) a t a n d r o i d . o s . H a n d l e r . h a n d l e C a l l b a c k ( H a n d l e r . j a v a : 733 ) a t a n d r o i d . o s . H a n d l e r . d i s p a t c h M e s s a g e ( H a n d l e r . j a v a : 95 ) a t a n d r o i d . o s . L o o p e r . l o o p ( L o o p e r . j a v a : 136 ) a t a n d r o i d . a p p . A c t i v i t y T h r e a d . m a i n ( A c t i v i t y T h r e a d . j a v a : 5050 ) a t j a v a . l a n g . r e f l e c t . M e t h o d . i n v o k e N a t i v e ( N a t i v e M e t h o d ) a t j a v a . l a n g . r e f l e c t . M e t h o d . i n v o k e ( M e t h o d . j a v a : 515 ) a t c o m . a n d r o i d . i n t e r n a l . o s . Z y g o t e I n i t 1.run(Test.java:531) 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.app.ActivityThread.main(ActivityThread.java:5050) at java.lang.reflect.Method.invokeNative(Native Method) at java.lang.reflect.Method.invoke(Method.java:515) at com.android.internal.os.ZygoteInit 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.ZygoteInitMethodAndArgsCaller.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_serverJNI: 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里面有体现。
- 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的地方。
- 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.