一 . 什么是ANR?
二 . ANR 产生的原因?
只有UI线程阻塞才会发生ANR,发生ANR的根本原因有以下三种:
- KeyDispatchTimeOut :
View的按键事件或者触摸事件在特定的时间(5秒)内无法得到响应; - BroadcaseTimeOut:
BroadcastReceiver的onReceiver()函数运行在主线程中,在特定的时间(10秒)内无法完成处理。 - ServiceTimeOut:
Service的各个生命周期函数在特定时间(20秒)内无法完成处理,这种比较少见。
从出现ANR的原因可以看出发生ANR之前的特定时间(5s, 10s, 20s)之内主线程很繁忙,在做耗时操作,Android中常见的耗时操作有哪些呢?
耗时操作:
- IO文件读写操作,会导致iowait负载较大;
- SQL语句, 当数据库内容太复杂太大时,会出现读写很慢的问题;
- Bitmap 位图的一些运算,比如毛玻璃等特效;
- 等待系统GC垃圾回收,当App出现严重的内存泄漏时很容易出现这种ANR;
三 . 如果分析ANR ?
在开始分析ANR之前我们应该学习一些必要的如下前提知识:
1. 如何获取ANR log 信息?
在发生ANR的时候,系统会收集ANR相关的log:
会收集ANR相关的关键信息,ANR前后CPU使用情况,还会收集trace信息,trace记录了ANR时各个线程的执行情况
手动获取trace.txt:
chmod 777 /data/anr
adb pull data/anr/traces.txt ~/traces.txt
获取DropBox中的log
traces.txt只保留最后一次发生ANR时的信息, android 2.2开始增加了DropBox功能, 保留历史上发生的所有ANR的log.
“/data/system/dropbox”是DB指定的文件存放位置.
日志保存的最长时间, 默认是3天.
2. 如何判断是否此段代码在主线程?
//方法一:使用 Looper 类判断
Looper.myLooper() != Looper.getMainLooper()
//方法二:通过查看 Thread 类的当前线程
Thread.currentThread() == Looper.getMainLooper().getThread()
3. 线程的状态:
ThreadState (defined at “dalvik/vm/thread.h “)
THREAD_UNDEFINED = -1, /* makes enum compatible with int32_t */
THREAD_ZOMBIE = 0, /* TERMINATED */ ( 线程死亡,终止运行)
THREAD_RUNNING = 1, /* RUNNABLE or running now */(线程可运行或正在运行)
THREAD_TIMED_WAIT = 2, /* TIMED_WAITING in Object.wait() */(执行了带有超时参数的wait、sleep或join函数)
THREAD_MONITOR = 3, /* BLOCKED on a monitor */(线程阻塞,等待获取对象锁)
THREAD_WAIT = 4, /* WAITING in Object.wait() */( 执行了无超时参数的wait函数)
THREAD_INITIALIZING= 5, /* allocated, not yet running */(新建,正在初始化,为其分配资源)
THREAD_STARTING = 6, /* started, not yet on thread list */(新建,正在启动)
THREAD_NATIVE = 7, /* off in a JNI native method */(正在执行JNI本地函数)
THREAD_VMWAIT = 8, /* waiting on a VM resource */(正在等待VM资源)
THREAD_SUSPENDED = 9, /* suspended, usually by GC or debugger */ (线程暂停,通常是由于GC或debug被暂停)
知道上述分析ANR的基础知识后我们再来看看分析ANR常用的一些套路,通过这些套路我们可以很快定位大多数ANR问题出现的原因:
1. 判断是那个App出现了ANR?
在log中搜索cmd line
关键字来查看是那个App发生了ANR;
----- pid 20342 at 2020-05-09 15:07:29 -----
Cmd line: com.cjl.mybook
Build fingerprint: 'HUAWEI/EML-AL00/HWEML:10/HUAWEIEML-AL00/10.0.0.130C00:user/release-keys'
ABI: 'arm'
Build type: optimized
Zygote loaded classes=12068 post zygote classes=6611
从上述log可以看到ANR的进程id、时间和进程名称。
2. 具体分析
知道发生在时间地方后我们应该需要将关注的重点放在发生 ANR 的前一分钟内的log信息,看下系统在做哪些事情?
在ANR log中搜索ANR in
或者am_anr
关键字来查看App发生ANR的事发现场是那个类,具体的时间(trace log中一般没有该log)
此时如果是BroadcastReceiver的ANR可以怀疑BroadCastReceiver.onRecieve()的问题,如果的Service或Provider就怀疑可能是onCreate()的问题,因为这些方法都运行在主线程中;
在该条log之后会有CPU usage的信息,表明了CPU在ANR前后的用量(log会表明截取ANR的时间),从各种CPU Usage信息中大概可以分析如下几点:
(1). 如果某些进程的CPU占用百分比较高,几乎占用了所有CPU资源,而发生ANR的进程CPU占用为0%或非常低,则认为CPU资源被占用,进程没有被分配足够的资源,从而发生了ANR。这种情况多数可以认为是系统状态的问题,并不是由本应用造成的。
(2). 如果发生ANR的进程CPU占用较高,如到了80%或90%以上,则可以怀疑应用内一些代码不合理消耗掉了CPU资源,如出现了死循环或者后台有许多线程执行任务等等原因,这就要结合trace和ANR前后的log进一步分析了。
(3). 如果CPU总用量不高,该进程和其他进程的占用过高,这有一定概率是由于某些主线程的操作就是耗时过长,或者是由于主进程被锁造成的。
除了上述的情况(1)以外,分析CPU usage之后,确定问题需要我们进一步分析trace文件。trace文件记录了发生ANR前后该进程的各个线程的stack。对我们分析ANR问题最有价值的就是其中主线程的stack,一般主线程的trace可能有如下几种情况:
(1). 主线程是running或者native而对应的栈对应了我们应用中的函数,则很有可能就是执行该函数时候发生了超时。
(2). 主线程被block:非常明显的线程被锁,这时候可以看是被哪个线程锁了,可以考虑优化代码。如果是死锁问题,就更需要及时解决了。
(3). 由于抓trace的时刻很有可能耗时操作已经执行完了(ANR -> 耗时操作执行完毕 ->系统抓trace),这时候的trace就没有什么用了,主线程的stack就是这样的:
-
判断 cpu 的使用情况,
判断当前负载如何,负载如果在 6-7 以下,属于正常,如果高于 8,在 11 以上,可以表明,当前系统负载过重,系统出现问题,需要再次定位。
负载过高,需要调查具体哪种原因,比如是 iowait 比重过高,系统频繁的读写操作引起。
负载一般,正常,那么就要去看下是否写的代码处会产生挂起等待,导致 anr
四 . 常见的ANR问题示例?
1. OOM导致的ANR
这种ANR很常见,如果你的App代码里存在太多的内存泄漏,那在跑Monkey时最容易出现的可能就是OOM导致的ANR了;
内存占用情况解读
Total number of allocations 82104153 //进程创建到现在一共创建了多少对象
Total bytes allocated 4958MB //进程创建到现在一共申请了多少内存
Total bytes freed 4574MB //进程创建到现在一共释放了多少内存
Free memory 191KB //不扩展堆的情况下可用的内存
Free memory until GC 191KB //GC前的可用内存
Free memory until OOME 191KB //OOM之前的可用内存
Total memory 384MB // 当前总内存(已用+可用)
Max memory 384MB //进程最多能申请的内存
- 栈信息,去看对应代码,发现此处是个跨进程调用,循环调用,查询语句,那么出现 anr 的原因,可以去怀疑这里耗时,等待;
- 如果是跨进程调用,那么需要看下对应进程的堆栈,看下请求是否响应,是否在等待锁。(搜索下栈里面是否有 block);
判断 cpu 的使用情况,
判断当前负载如何,负载如果在 6-7 以下,属于正常,如果高于 8,在 11 以上,可以表明,当前系统负载过重,系统出现问题,需要再次定位。
负载过高,需要调查具体哪种原因,比如是 iowait 比重过高,系统频繁的读写操作引起。
负载一般,正常,那么就要去看下是否写的代码处会产生挂起等待,导致 anr
关注 log 信息
在发生 anr 的前一分钟内,看下系统在忙于哪些事情。
可以从log中搜索“ANR in”或“am_anr”,会找到ANR发生的log,该行会包含了ANR的时间、进程、是何种ANR等信息,如果是BroadcastReceiver的ANR可以怀疑BroadCastReceiver.onRecieve()的问题,如果的Service或Provider就怀疑是否其onCreate()的问题。
在该条log之后会有CPU usage的信息,表明了CPU在ANR前后的用量(log会表明截取ANR的时间),从各种CPU Usage信息中大概可以分析如下几点:
(1). 如果某些进程的CPU占用百分比较高,几乎占用了所有CPU资源,而发生ANR的进程CPU占用为0%或非常低,则认为CPU资源被占用,进程没有被分配足够的资源,从而发生了ANR。这种情况多数可以认为是系统状态的问题,并不是由本应用造成的。
(2). 如果发生ANR的进程CPU占用较高,如到了80%或90%以上,则可以怀疑应用内一些代码不合理消耗掉了CPU资源,如出现了死循环或者后台有许多线程执行任务等等原因,这就要结合trace和ANR前后的log进一步分析了。
(3). 如果CPU总用量不高,该进程和其他进程的占用过高,这有一定概率是由于某些主线程的操作就是耗时过长,或者是由于主进程被锁造成的。
除了上述的情况(1)以外,分析CPU usage之后,确定问题需要我们进一步分析trace文件。trace文件记录了发生ANR前后该进程的各个线程的stack。对我们分析ANR问题最有价值的就是其中主线程的stack,一般主线程的trace可能有如下几种情况:
(1). 主线程是running或者native而对应的栈对应了我们应用中的函数,则很有可能就是执行该函数时候发生了超时。
(2). 主线程被block:非常明显的线程被锁,这时候可以看是被哪个线程锁了,可以考虑优化代码。如果是死锁问题,就更需要及时解决了。
(3). 由于抓trace的时刻很有可能耗时操作已经执行完了(ANR -> 耗时操作执行完毕 ->系统抓trace),这时候的trace就没有什么用了,主线程的stack就是这样的:
// main 代表线程名称
// prio = 优先级
// Native = 代表当前线程的状态,Native代表执行JNI代码
"main" prio=5 tid=1 Native
//group是线程组名称 sCount是线程被挂起的次数 dsCount是线程调试状态下挂起的次数
//obj是这个线程的Java对象的地址 self表是这个线程Native的地址。
| group="main" sCount=1 dsCount=0 flags=1 obj=0x72fac298 self=0xeab9fc00
// sysTid 是此线程在内核中对应的线程ID
// nice 代表着struct_task任务被调度的优先级
// cgrp是调度组 sched分别是线程的调度策略和优先级 handle是线程的处理函数地址。
| sysTid=25409 nice=-10 cgrp=default sched=1073741825/2 handle=0xeafe6dc0
//state = native 线程状态 schedstat值来自于/proc/[pid]/task/[tid]/schedstat,分别是cpu上执行的时间、线程的等待时间和线程执行的时间片
// utm是线程用户态下执行时间 stm是内核态下执行时间(单位是jiffies) HZ可推出执行时间 stm = 747*1000/100
| state=S schedstat=( 114142562712 4466525515 117490 ) utm=8451 stm=2962 core=0 HZ=100
| stack=0xff107000-0xff109000 stackSize=8192KB
| held mutexes=
kernel: (couldn't read /proc/self/task/25409/stack)
native: #00 pc 0008bed0 /apex/com.android.runtime/lib/bionic/libc.so (__ioctl+8)
native: #01 pc 00059c7d /apex/com.android.runtime/lib/bionic/libc.so (ioctl+32)
native: #02 pc 000433c5 /system/lib/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+212)
native: #03 pc 00043fcf /system/lib/libbinder.so (android::IPCThreadState::waitForResponse(android::Parcel*, int*)+26)
native: #04 pc 00043dc7 /system/lib/libbinder.so (android::IPCThreadState::transact(int, unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+194)
native: #05 pc 0003bf71 /system/lib/libbinder.so (android::BpBinder::transact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+36)
native: #06 pc 0010118f /system/lib/libandroid_runtime.so (android_os_BinderProxy_transact(_JNIEnv*, _jobject*, int, _jobject*, _jobject*, int)+286)
at android.os.BinderProxy.transactNative(Native method)
at android.os.BinderProxy.transact(BinderProxy.java:532)
at com.android.internal.telephony.IHwTelephony$Stub$Proxy.getPreferredDataSubscription(IHwTelephony.java:3013)
at android.telephony.HwTelephonyManagerInner.getPreferredDataSubscription(HwTelephonyManagerInner.java:1079)
at android.telephony.MSimTelephonyManager.getPreferredDataSubscription(MSimTelephonyManager.java:531)
at java.lang.reflect.Method.invoke(Native method)
at com.huawei.openalliance.ad.utils.aj.a(unavailable:-1)
当然这种情况很有可能是由于该进程的其他线程消耗掉了CPU资源,这就需要分析其他线程的trace以及ANR前后该进程自己输出的log了。
//说明了发生ANR的进程id、时间和进程名称。
----- pid 2023 at 2018-07-24 19:33:17
----- Cmd line: com.rui.android.poc
//下面三行是线程的基本信息
JNI: CheckJNI is off; workarounds are off; pins=0; globals=348
DALVIK THREADS://以下是各个线程的函数堆栈信息
(mutexes: tll=0 tsl=0 tscl=0 ghl=0)
//下面一行说明了线程名称、daemon表示守护进程,线程的优先级(默认5)、线程锁id和线程状态,
//线程名称是启动线程的时候手动指明的,这里的main标识是主线程,是Android自动设定的
//一个线程名称,如果是自己手动创建的线程,一般会被命名成“Thread-xx”的格式,其中xx是
//线程id,它只增不减不会被复用;注意这其中的tid不是线程的id,它是一个在Java虚拟机中用
//来实现线程锁的变量,随着线程的增减,这个变量的值是可能被复用的;
"main" prio=5 tid=1 NATIVE
//group是线程组名称。sCount是此线程被挂起的次数,dsCount是线程被调试器挂起的次数,
//当一个进程被调试后,sCount会重置为0,调试完毕后sCount会根据是否被正常挂起增长,
//但是dsCount不会被重置为0,所以dsCount也可以用来判断这个线程是否被调试过。obj表示
//这个线程的Java对象的地址,self表示这个线程Native的地址。
| group="main" sCount=1 dsCount=0 obj=0x4164dcf0 self=0x41565628
//此后是线程的调度信息,sysTid是Linux下的内核线程id,nice是线程的调度优先级,
//sched分别标志了线程的调度策略和优先级,cgrp是调度属组,handle是线程的处理函数地址。
| sysTid=2023 nice=-1 sched=0/0 cgrp=apps handle=1074626900
//线程当前上下文信息,state是调度状态;schedstat从 /proc/[pid]/task/[tid]/schedstat读出,
//三个值分别表示线程在cpu上执行的时间、线程的等待时间和线程执行的时间片长度,有的
//android内核版本不支持这项信息,得到的三个值都是0;utm是线程用户态下使用的时间
//值(单位是jiffies);stm是内核态下的调度时间值;core是最后执行这个线程的cpu核的序号。
| state=S schedstat=( 0 0 0 ) utm=49 stm=21 core=0
//线程的调用栈信息(这里可查看导致ANR的代码调用流程,分析ANR最重要的信息)
(native backtrace unavailable)
at libcore.io.Posix.open(Native Method)
at libcore.io.BlockGuardOs.open(BlockGuardOs.java:110)
at libcore.io.IoBridge.open(IoBridge.java:430)
at java.io.FileInputStream.<init>(FileInputStream.java:78)
at com.ruiven.android.Peripheral.util.kingFiles.write(kingFiles.java:58)
at com.ruiven.android.Peripheral.util.kingFiles.write(kingFiles.java:51)
at com.ruiven.android.Peripheral.util.kingLog.writeToFiles(kingLog.java:71)
at com.ruiven.android.Peripheral.util.kingLog.f(kingLog.java:47)
at com.ruiven.android.poc.receiver.ReceiverBatteryChanged.onReceive(ReceiverBatteryChanged.java:114)
at android.app.LoadedApk$ReceiverDispatcher$Args.run(LoadedApk.java:767)
at android.os.Handler.handleCallback(Handler.java:769)
at android.os.Handler.dispatchMessage(Handler.java:97)
at android.os.Looper.loop(Looper.java:136)
at com.ruiven.android.Peripheral.util.Cockroach$1.run(Cockroach.java:38)
at android.os.Handler.handleCallback(Handler.java:769)
at android.os.Handler.dispatchMessage(Handler.java:97)
at android.os.Looper.loop(Looper.java:136)
at android.app.ActivityThread.main(ActivityThread.java:5375)
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:976)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:792)
at dalvik.system.NativeStart.main(Native Method)
//Binder线程是进程的线程池中用来处理binder请求的线程
"Binder_3" prio=5 tid=23 NATIVE
| group="main" sCount=1 dsCount=0 obj=0x41b765f8 self=0x4f213f18
| sysTid=1347 nice=0 sched=0/0 cgrp=apps handle=1327603952
| state=S schedstat=( 0 0 0 ) utm=0 stm=3 core=1
#00 pc 000205d0 /system/lib/libc.so (__ioctl+8)
#01 pc 0002d01f /system/lib/libc.so (ioctl+14)
#02 pc 0001e519 /system/lib/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+140)
#03 pc 0001ec67 /system/lib/libbinder.so (android::IPCThreadState::getAndExecuteCommand()+6)
#04 pc 0001ecfd /system/lib/libbinder.so (android::IPCThreadState::joinThreadPool(bool)+48)
#05 pc 000236cd /system/lib/libbinder.so
#06 pc 0000ea19 /system/lib/libutils.so (android::Thread::_threadLoop(void*)+216)
#07 pc 0004e769 /system/lib/libandroid_runtime.so (android::AndroidRuntime::javaThreadShell(void*)+68)
#08 pc 0000e54b /system/lib/libutils.so
#09 pc 0000d240 /system/lib/libc.so (__thread_entry+72)
#10 pc 0000d3dc /system/lib/libc.so (pthread_create+240)
at dalvik.system.NativeStart.run(Native Method)
log 查找
搜索 am_anr 会搜到一段异常信息。
iowait 故障:
待续...
五 . 如果防止出现ANR?
DDMS:Start Methord Tracing:
使用traceview的方式,获取每个方法的耗时。
BlockCanary:
加入三方库,完成自动检测anr
网友评论