目录
1.ANR是如何产生的
1.1 service是如何产生ANR的?
1.2 input是如何产生ANR的?
2. ANR和主线程耗时关系
3. ANR的定位和ANR实战分析! ANR堆栈如何分析?
3.2Trace文件怎么生成的?
4.典型的ANR场景
5. bugly是如何检测到ANR的? 安卓系统是如何检测ANR的?
6. 线上如何监控?nativePollOnce导致的ANR
---------------------------------------正文-------------------------------------------------
1.ANR是如何产生的
1.1 Anr是什么?
ANR(Application Not responding),是指应用程序未响应,Android系统对于一些事件需要在一定的时间范围内完成,如果超过预定时间能未能得到有效响应或者响应时间过长,都会造成ANR。
ANR的产生有两个必要条件:
- 至少需要两个事件;
- 在第二个事件到来的时候,第一个事件尚未处理完毕,并且处理时间超过5秒。
如果当前还有事件, 不会取当前事件, 而是取之前的事件! 然后是否有焦点, 然后分发事件!
ANR根本原因:
在Android系统中,应用程序是有Android的四大组件组成,AMS负责对应用程序四大组件生命周期的管理,
当AMS对应用程序组件的生命周期进行回调超过AMS定义的响应时间时,AMS就会报ANR。
1.2 那么哪些场景会造成ANR呢?(4大组件)------本质就是AMS
inputDispatching Timeout: 输入事件分发超时**5s**,包括按键分发事件的超时。==**主要类型**
BroadcastQueue Timeout:比如前台广播在**10s**内执行完成,后台超过60s完成
ContentProvider Timeout:内容提供者执行超时(读写权限导致的)10s
Service Timeout:服务在1**0s**内未执行完成;===**小概率类型**
问题: 这些参数来自哪里?
在ActivityManagerService.java里面,AMS
1.3 service是如何产生ANR的?
1).service启动anr的原因:AMS启动anr,然后发了一个延时消息20s,超过20s,出现系统弹框。正常情况:actiityThread在执行完oncrate()把消息移除了。所以移除消息也不会anr了
所以条件是:监控范围内+耗时超过指定时间!!!!
实质: 埋炸弹和拆炸蛋的一个过程(Service源码分析)
service、broadcast、provider 的ANR原理都是埋定时炸弹和拆炸弹原理,
但是input的超时检测机制稍微有点不同,需要等收到下一次input事件,才会去检测上一次input事件是否超时,input事件里埋的炸弹是普通炸弹,需要通过扫雷来排查。
service的ANR产生原理分析:
ActivityManagerService------->.startServiceLocked
ActiveServices----------->.scheduleServiceTimeoutLocked
ActivityService------------->realStartServiceLocked
bumpServiceExecutingLocked(埋炸弹)
scheduleServiceTimeoutLocked(定时)
void scheduleServiceTimeoutLocked(ProcessRecord proc) {
if (proc.mServices.numberOfExecutingServices() == 0 || proc.getThread() == null) {
return;
}
Message msg = mAm.mHandler.obtainMessage(
ActivityManagerService.SERVICE_TIMEOUT_MSG);
msg.obj = proc;
// 延时指定时间后,发送消息:SERVICE_TIMEOUT_MSG
// 前台进程中执行 Service,SERVICE_TIMEOUT = 20s
// 后台进程中执行 Service,SERVICE_BACKGROUND_TIMEOUT = 200s
mAm.mHandler.sendMessageDelayed(msg, proc.mServices.shouldExecServicesFg()
? SERVICE_TIMEOUT : SERVICE_BACKGROUND_TIMEOUT);
}
发送定时20s, ActivityService.serviceTimeout().
到时间了,要么移除anr消息, 要么dump ANR消息!
void serviceTimeout(ProcessRecord proc) {
synchronized(mAm) {
if (timeout != null && mAm.mProcessList.isInLruListLOSP(proc)) {
mAm.mHandler.removeCallbacks(mLastAnrDumpClearer);
mAm.mHandler.postDelayed(mLastAnrDumpClearer, LAST_ANR_LIFETIME_DURATION_MSECS);
anrMessage = "executing service " + timeout.shortInstanceName;
} else {
Message msg = mAm.mHandler.obtainMessage(
ActivityManagerService.SERVICE_TIMEOUT_MSG);
msg.obj = proc;
mAm.mHandler.sendMessageAtTime(msg, psr.shouldExecServicesFg()
? (nextTime+SERVICE_TIMEOUT) : (nextTime + SERVICE_BACKGROUND_TIMEOUT));
}
}
if (anrMessage != null) {
mAm.mAnrHelper.appNotResponding(proc, anrMessage);
}
}
启动service:
ActivityThread------------>scheduleCreateService
在 `onCreate()` 被调用前,会通知 `ActiveServices` 取消掉这条超时引爆的信息
Handler------------------>service.onCreate()
1.4 input是如何产生ANR的?
与组件类ANR
不同的是,Input
类型的超时机制并非时间到了一定就会爆炸,而是处理后续上报事件的过程才会去检测是否该爆炸,所以更像是 扫雷 的过程。
什么叫做 扫雷 呢,对于 输入系统 而言,即使某次事件执行时间超过预期的时长,只要用户后续没有再生成输入事件,那么也不需要ANR
。
而只有当新一轮的输入事件到来,此时正在分发事件的窗口(即App
应用本身)迟迟无法释放资源给新的事件去分发,这时InputDispatcher
才会根据超时时间,动态的判断是否需要向对应的窗口提示ANR
信息。
这也正是用户在第一次点击屏幕,即使事件处理超时,也没有弹出ANR
窗口,而当用户下意识再次点击屏幕时,屏幕上才提示出了ANR
信息的原因。
详细来说:
input 超时机制为什么是扫雷,而非定时爆炸?由于对于 input 来说即便某次事件执行时间超过 Timeout 时长,只要用户后续没有再生成输入事件,则不会触发 ANR。这里的扫雷是指当前输入系统中正在处理着某个耗时事件的前提下,后续的每一次 input 事件都会检测前一个正在处理的事件是否超时(进入扫雷状态),检测当前的时间距离上次输入事件分发时间点是否超过 timeout 时长。如果没有超过,则会重置 anr 的 Timeout,从而不会爆炸。
Input ANR 时间区间便是指当前这次的事件 dispatch 过程中执行 findFocusedWindowTargetsLocked() 方法到下一次执行 resetANRTimeoutsLocked() 的时间区间。看源码有 5 个时机会 reset。都位于InputDispatcher.cpp 文件:
源码分析:
InputDispatcher
bool InputDispatcherThread::threadLoop() {
mDispatcher->dispatchOnce(); // 重要的方法!
return true;
}
void InputDispatcher::dispatchOnce() {
nsecs_t nextWakeupTime = LONG_LONG_MAX;
// 如果有commands需要处理,优先处理commands
if (!haveCommandsLocked()) {
//当commands处理完后,处理events
dispatchOnceInnerLocked(&nextWakeupTime);
}
// 新增:如果还有event在处理中,需要提前唤醒检查是否发生anr
const nsecs_t nextAnrCheck = processAnrsLocked();
nextWakeupTime = std::min(nextWakeupTime, nextAnrCheck);
nsecs_t currentTime = now();
int timeoutMillis = toMillisecondTimeoutDelay(currentTime, nextWakeupTime);
mLooper->pollOnce(timeoutMillis); //进入epoll_wait
}
2. ANR和主线程耗时关系
2.1 举例说明:
以前我的理解就是 “在主线程做了耗时操作”就会引起ANR,现在我觉得我是错误的,ANR的意思是应用没有响应,耗时操作实际上 并不一定会导致没有响应,我对没有响应的理解是
1.休眠10s不会anr 不会
2.休眠10d的时候按了一个键,就会anr 会
3.休眠10s的时候,更新了ui,会ANR吗? 不会,执行顺序都不一样
4.onstop的时候 休眠10s会不会anr 不会。不在监控范围内
结论:主线程在无事件处理时本身就会处于阻塞状态,当有点击事件传递给主线程或者其他线程使用Handler向MessageQueue中存放消息,
导致loop被唤醒时,主线程就会被唤醒执行相应事件,但是这时如果主线程还是被阻塞住,就会导致事件无法处理。当时间超过阀值(activity貌似是5s)时,就会触发ANR异常。
2.2 我们先来思考一个问题,如果我在Activity
的dispatchTouchEvent
中,手动让线程sleep一段时间。这种情况一定会报ANR么?
var count = 0;
override fun dispatchTouchEvent(ev: MotionEvent?): Boolean {
// 让第0个event,卡住9s
if(count == 0){
try {
Thread.sleep(9000)
} catch (e: Throwable) {
e.printStackTrace()
}
}
count++
return super.dispatchTouchEvent(ev)
}
我相信很多同学会回答一定,因为主线程 sleep 的时间远远超过了 Input 事件报ANR的超时时间,所以会报ANR。
但真实的情况是,在主线程sleep 大于 5s 不一定会报ANR。下面我们就从InputDispatcher
源码的角度来看看,Input ANR到底是怎么产生的吧。
结论:
为什么在主线程中sleep 9s不一定会造成ANR呢?
因为ANR的检查逻辑,是在下个事件的分发流程中进行的。如果在这个9s中,没有后续事件,或者后续事件的等待时间不超过5s,则不会触发ANR。
3. ANR的定位和ANR实战分析! ANR堆栈如何分析?
3.1 分析方案 :
日志查看搜索定位信息
1).通过包名
2).通过pid进程号
3).ANR in
ANR 相关信息并存档(data/anr/trace,data/system/dropbox)
adb pull /data/anr/traces.txt d:/ 大于8.0用bugreport
Logcat分析和trace文件2个文件
Logcat:主要看是4种类型的哪一种
Trace文件:看CPU,等等信息
ANR的定位和分析总结:
1).看logcat定位ANR的类型
2). 导出trace文件, trace.txt文件,
3). trace文件分析:
3.1). 找到自己的堆栈
3.2). 看看主线程main! 要看自己应用的主现场! (排除低级的业务问题)
看io线程,内存,cpu, 运行前和运行后的变化! cpu要看时间段
可以看出时自己的原因还是系统的原因!
3.3). 如果怀疑是系统Binder或者NativePollOnce 要具体分析了 !用到自己研制的工具
需要看线程(线程的(utm,stm)! 先看在哪个进程(cpu的占比中可以看到)
然后找哪个线程?怎么找?
比对线程的耗时(utm+stm), 找到是哪个线程
4).看相关的代码
5).线上分析工具: 字节的或者blockCanary 查看哪里耗时
6).工具分析: traceview文件分析堆栈 分析方法的耗时,可以在profile和ddms里面看的
当ANR发生时,我们可以先通过logcat定位ANR的类型,然后通过trace信息分析产生ANR的原因,需要重点关注主线程(main****)的当前状态和CPU的使用情况!
3.2 ANR堆栈的指标
1). 正常的一种情况nativePollOnce或者next:
"main" prio=5 tid=1 Native
| group="main" sCount=1 dsCount=0 flags=1 obj=0x74b38080 self=0x7ad9014c00
| sysTid=23081 nice=0 cgrp=default sched=0/0 handle=0x7b5fdc5548
| state=S schedstat=( 284838633 166738594 505 ) utm=21 stm=7 core=1 HZ=100
| stack=0x7fc95da000-0x7fc95dc000 stackSize=8MB
| held mutexes=
kernel: __switch_to+0xb0/0xbc
kernel: SyS_epoll_wait+0x288/0x364
kernel: SyS_epoll_pwait+0xb0/0x124
kernel: cpu_switch_to+0x38c/0x2258
native: #00 pc 000000000007cd8c /system/lib64/libc.so (__epoll_pwait+8)
native: #01 pc 0000000000014d48 /system/lib64/libutils.so (android::Looper::pollInner(int)+148)
native: #02 pc 0000000000014c18 /system/lib64/libutils.so (android::Looper::pollOnce(int, int*, int*, void**)+60)
native: #03 pc 00000000001275f4 /system/lib64/libandroid_runtime.so (android::android_os_MessageQueue_nativePollOnce(_JNIEnv*, _jobject*, long, int)+44)
at android.os.MessageQueue.nativePollOnce(Native method)
at android.os.MessageQueue.next(MessageQueue.java:330)
at android.os.Looper.loop(Looper.java:169)
at android.app.ActivityThread.main(ActivityThread.java:7073)
at java.lang.reflect.Method.invoke(Native method)
at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:536)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:876)
比如这个主线程堆栈,看起来很正常,主线程是空闲的,因为它正处于nativePollOnce,正在等待新消息。处于这个状态,那还发生了ANR,可能有2个原因:
- dump堆栈时机太晚了,ANR已经发生过了,才去dump堆栈,此时主线程已经恢复正常了
- CPU抢占或者内存紧张等其他因素引起
遇到这种情况,要先去分析CPU、内存的使用情况。其次可以关注抓取日志的时间和ANR发生的时间是否相隔太久,时间太久这个堆栈就没有分析的意义了。
2).查看CPU usage和io wait,不用看内存!
各个进程的CPU使用情况;
- CPU负载;
- IOWait;
- 线程:有没有死锁
分析日志:
- ago 表示ANR发生前的CPU的使用情况
- later表示ANR发生后的CPU的使用情况
- 在later之前会有数据百分比,重点关注xxx%TOTAL: xxx% user + xxx% kernel + xxx% iowait,可通过这几项了解到CPU的占用情况。
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---发生ANR的时间和生成trace.txt的时间
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
4.典型的ANR场景
案例总结: 应用导致和系统导致
应用层导致 ANR:
- 函数阻塞:如死循环、主线程 IO、处理大数据
- 锁出错:主线程等待子线程的锁
- 内存紧张:系统分配给一个应用的内存是有上限的,长期处于内存紧张,会导致频繁内存交换,进而导致应用的一些操作超时
系统导致ANR:
- CPU 被抢占:一般来说,前台在玩游戏,可能会导致你的后台广播被抢占
- 系统服务无法及时响应:比如获取系统联系人等,系统的服务都是 Binder 机制,服务能力也是有限的,有可能系统服务长时间不响应导致 ANR
- 其他应用占用大量内存
1). 主线程被其他线程锁(占比57%):调用了thread的sleep()、wait()等方法,导致的主线程等待超时。
多线程操作的死锁,导致主线程等待超时;
搜索mLock加锁代码的调用,发现了仅在MainActivity文件中,才会存在“mLock.readLock.lock()”代码, 由此判断,异常代码仅存在于MainActivity中,因此我们缩小了问题代码范围。 在正在的代码编写过程中,锁的申请与释放已经成为一种编码习惯,如果锁未释放,可能是在释放锁之前,出现了某种我们编码未考虑的异常,导致锁未释放或释放失败。 由此分析,我们接下来尝试使用“找到ANR问题发生之前,应用是否有异常发生”的思路,继续分析
我们已经知道导致该ANR问题的具体原因:异常场景导致锁资源未被释放,从而造成了主线程出现死锁。
死锁案例二: Blocked. waiting to lock. ............by thread
问题: 常见因锁而ANR的场景是SharePreference写入。?
问题: 死锁如何监控?
https://juejin.cn/post/6973564044351373326
2). 主线程耗时工作导致线程卡死(占比9%):例如大量的数据库读写,耗时的网络情况,高强度的硬件计算等主线程频繁进行IO操作,比如读写文件或者数据库;
2.1.数据库和sp读写导致ANR(最多)
2.2.为什么sp会导致ANR(看源代码)
SharedPreference 相关修改使用 apply 方法进行提交会先写入内存,然后异步写入磁盘,commit
方法是直接写入磁盘。如果频繁操作的话 apply 的性能会优于 commit,apply会将最后修改内容写入磁盘。
但是如果希望立刻获取存储操作的结果,并据此做相应的其他操作,应当使用 commit。
二.项目中出现的案例
SharedPreferences ANR问题分析和解决 & Android 8.0的优化
原因:8.0之前,排队,队列阻塞。单线程,阻塞
8.0之后,线程池,排队
但是另一方面android的系统会在Activity的onStop,onPause等生命周期中,调用QueuedWork.waitToFinish,等待落盘的任务队列执行完成,如果任务队列中的任务很多,或者待写入的数据量很大时(sp文件是全量读写的),在一些io性能差的中低端机型上就会很容易出现anr.
3).View绘制太耗时
viewGroup = (ViewGroup) LayoutInflater.from(context).inflate(R.layout.ai_question_float_layout, null);</pre>
4).资源不足案例:(系统导致ANR)
CPU被其他应用抢占
CPU usage from 0ms to 10625ms later (2020-03-09 14:38:31.633 to 2020-03-09 14:38:42.257):
543% 2045/com.test.demo: 54% user + 89% kernel / faults: 4608 minor 1 major //注意看这里
99% 674/android.hardware.camera.provider@2.4-service: 81% user + 18% kernel / faults: 403 minor
24% 32589/com.wang.test: 22% user + 1.4% kernel / faults: 7432 minor 1 major
......
(1)IO占比很高
CPU占用是100%、IO占用是84%、未发生过低内存、应用被分配堆是26.50MB、应用已用堆是8.69MB,从系统资源来看,CPU占用和IO占用出现明显异常,如下图所示:
<pre> 由定位大部分ANR问题经验可知,该ANR问题是由于系统资源不足导致,那么分析该ANR问题思路为:找到自身应用程序ANR代码片段,分析否能够优化代码,在高IO情况下,不触发ANR。
从LOG可以看出ANR的类型,CPU的使用情况,
如果CPU使用量接近100%,说明当前设备很忙,有可能是CPU饥饿导致了ANR
(2)查看主线程状态:发现问题原因 我们切换到“主线程堆栈”页签,观察主线程代码。
通过观察主线程堆栈,我们发现了一个存在问题的地方,主线程里面直接在做数据库操作,在系统IO高的情况,此操作必定会导致主线程被阻塞
所以,如果IO占用比较高的话,就是数据库和文件读写,网络请求放在了主线程!
如果CPU使用量很少,说明主线程被BLOCK了, 如果IOwait很高,说明ANR有可能是主线程在进行I/O操作造成的
,具体进一步查看有没有进程faults major比较多
、Load: 5.28 / 5.71 / 5.58 // 代表了设备在 1、5、15 分钟内 正在使用和等待使用CPU 的活动进程的平均数
2、CPU usage from 275243ms to 190078ms ago (2022-06-16 15:25:36.158 to 2022-06-16 15:27:01.323) // 表明负载信息抓取是在
5).系统服务超时(系统导致ANR)
如果系统服务超时,日志中一般会包含 BinderProxy.transactNative
关键字,如下:
at android.os.Binder.blockUntilThreadAvailable(Native method)
"main" prio=5 tid=1 Native
| group="main" sCount=1 dsCount=0 flags=1 obj=0x727851e8 self=0x78d7060e00
| sysTid=4894 nice=0 cgrp=default sched=0/0 handle=0x795cc1e9a8
| state=S schedstat=( 8292806752 1621087524 7167 ) utm=707 stm=122 core=5 HZ=100
| stack=0x7febb64000-0x7febb66000 stackSize=8MB
| held mutexes=
kernel: __switch_to+0x90/0xc4
kernel: binder_thread_read+0xbd8/0x144c
kernel: binder_ioctl_write_read.constprop.58+0x20c/0x348
kernel: binder_ioctl+0x5d4/0x88c
kernel: do_vfs_ioctl+0xb8/0xb1c
kernel: SyS_ioctl+0x84/0x98
kernel: cpu_switch_to+0x34c/0x22c0
native: #00 pc 000000000007a2ac /system/lib64/libc.so (__ioctl+4)
native: #01 pc 00000000000276ec /system/lib64/libc.so (ioctl+132)
native: #02 pc 00000000000557d4 /system/lib64/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+252)
native: #03 pc 0000000000056494 /system/lib64/libbinder.so (android::IPCThreadState::waitForResponse(android::Parcel*, int*)+60)
native: #04 pc 00000000000562d0 /system/lib64/libbinder.so (android::IPCThreadState::transact(int, unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+216)
native: #05 pc 000000000004ce1c /system/lib64/libbinder.so (android::BpBinder::transact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+72)
native: #06 pc 00000000001281c8 /system/lib64/libandroid_runtime.so (???)
native: #07 pc 0000000000947ed4 /system/framework/arm64/boot-framework.oat (Java_android_os_BinderProxy_transactNative__ILandroid_os_Parcel_2Landroid_os_Parcel_2I+196)
at android.os.BinderProxy.transactNative(Native method) ————————————————关键行!!!
at android.os.BinderProxy.transact(Binder.java:804)
at android.net.IConnectivityManager$Stub$Proxy.getActiveNetworkInfo(IConnectivityManager.java:1204)—关键行!
at android.net.ConnectivityManager.getActiveNetworkInfo(ConnectivityManager.java:800)
at com.xiaomi.NetworkUtils.getNetworkInfo(NetworkUtils.java:2)
at com.xiaomi.frameworkbase.utils.NetworkUtils.getNetWorkType(NetworkUtils.java:1)
at com.xiaomi.frameworkbase.utils.NetworkUtils.isWifiConnected(NetworkUtils.java:1)
如果其他应用占用了 Binder 线程,那么当前应用只能等待,可进一步搜索 blockUntilThreadAvailable
关键字
5. bugly是如何检测到ANR的? 安卓系统是如何检测ANR的?
5.1. 监听 SIGNAL_QUIT 信号 (真正靠谱的方案Matrix)
市面上的ANR监控工具,或者并非真正意义上的ANR的监控(而是5秒卡顿监控)
这种方案才是真正的监控ANR,matrix、xCrash都在使用这种方案。已经在国民应用微信等app上检验过,稳定性和可靠性都能得到保证。
也是通过系统源代码, ANR发生,得到的结论!
ProcessRecord-->appNotResponding()
ActivityManagerService------>.dumpStackTraces
Debug-------------------------->debuggerd_trigger_dump
native-------->c++层(SIGQUIT信号)
void signalHandler(int sig, siginfo_t *info, void *uc) {
__android_log_print(ANDROID_LOG_DEBUG, "xfhy_anr", "我监听到SIGQUIT信号了,可能发生anr了");
//在这里去dump主线程堆栈
}
extern "C"
JNIEXPORT jboolean JNICALL
Java_com_xfhy_watchsignaldemo_MainActivity_startWatch(JNIEnv *env, jobject thiz) {
sigset_t set, old_set;
sigemptyset(&set);
sigaddset(&set, SIGQUIT);
/*
* 这里需要调用SIG_UNBLOCK,因为目标进程被Zogyte fork出来的时候,主线程继承了
* Zogyte的主线程的信号屏蔽关系,Zogyte主线程在初始化的时候,通过
* pthread_sigmask SIG_BLOCK把SIGQUIT的信号给屏蔽了,因此我们需要在自己进程的主线程,
* 设置pthread_sigmask SIG_UNBLOCK ,这会导致原来的SignalCatcher sigwait将失效,
* 原因是SignalCatcher 线程会对SIGQUIT 信号处理
*/
int r = pthread_sigmask(SIG_UNBLOCK, &set, &old_set);
if (0 != r) {
return false;
}
struct sigaction sa{};
sa.sa_sigaction = signalHandler;
sa.sa_flags = SA_ONSTACK | SA_SIGINFO | SA_RESTART;
return sigaction(SIGQUIT, &sa, nullptr) == 0;
}
监控方案:
误报ANR的情况:
问题: 监控SIGN_QUIT ,但是监控了我们收到, 系统就收不到了, 所以我们要再发一个给系统!
问题: 发生ANR的进程一定会收到SIGQUIT信号;但是收到SIGQUIT信号的进程并不一定发生了ANR。
可能是下面2种情况:
- 其他进程的ANR:发生ANR之后,发生ANR的进程并不是唯一需要dump堆栈的进程,系统会收集许多其他的进程进行dump,也就是说当一个应用发生ANR的时候,其他的应用也有可能收到SIGQUIT信号。所以,我们收到SIGQUIT信号,可能是其他进程发生了ANR,这个时候上报的话就属于是误报了。
- 非ANR发送SIGQUIT:发送SIGQUIT信号非常容易,系统和应用级app都能轻易发送SIGQUIT信号:java层调用android.os.Process.sendSignal方法;Native层调用kill或者tgkill方法。我们收到SIGQUIT信号时,可能并非是ANR流程发送的SIGQUIT信号,也会产生误报。
有一个标志, 是否是ANR的标志
漏报ANR的情况:
2:进程处于NOT_RESPONDING的状态可以确认该进程发生了ANR。但是发生ANR的进程并不一定会被设置为NOT_RESPONDING状态
两种情况:
下面2种是特殊情况:
- 后台ANR(SilentAnr):如果ANR被标记为了后台ANR(即SilentAnr),那么杀死进程后就会直接return,不会执行到makeAppNotRespondingLocked,那么该进程就不会有
NOT_RESPONDING
这个flag。这意味着,后台的ANR没办法捕捉到,但后台ANR的量也挺大的,并且后台ANR会直接杀死进程,对用户的体验也是非常负面的,这么大一部分ANR监控不到,当然是无法接受的。 - 闪退ANR:想当一部分机型(如OPPO、VIVO两家的高Android版本的机型)修改了ANR的流程,即使是发生在前台的ANR,也并不会弹窗,而是直接杀死进程,即闪退。
问题: 如何采集系统的堆栈信息:
如果我们能够hook到这里的write,我们甚至就可以拿到系统dump的ANR Trace内容。这个内容非常全面,包括了所有线程的各种状态、锁和堆栈(包括native堆栈),对于我们排查问题十分有用,尤其是一些native问题和死锁等问题。Native Hook我们采用PLT Hook 方案
为啥用hook? 不然要多dump一次!
系统dump很卡顿, 我们有什么优化吗? 我们通过hook, 不需要再次dump
Matrix的源码里面, 有2个监控ANR的类, 有一个是signal ,就是通过信号监控的!
总结: 监控SIGQUIT信号, 然后监控一个标志位, 最后比较重要的是采集
微信Android客户端的ANR监控方案(只是说监控方案, 没有解决nativepollonce)
总结: 终极的解决方案
我们需要一种机制,在收到SIGQUIT信号后,需要非常快速的侦查出自己是否已经处于ANR的状态,进行快速的dump和上报。此时我们可以通过主线程释放处于卡顿状态来判断,怎么快速的知道主线程是否卡住了?可以通过Looper的mMessage对象,该对象的when变量,表示的是当前正在处理的消息入队的时间,我们可以通过when变量减去当前时间,得到的就是等待时间,如果等待时间过长,就说明主线程是处于卡住的状态。这时候收到SIGQUIT信号基本上就可以认为的确发生了一次ANR:
private static boolean isMainThreadStuck(){
try {
MessageQueue mainQueue = Looper.getMainLooper().getQueue();
Field field = mainQueue.getClass().getDeclaredField("mMessages");
field.setAccessible(true);
final Message mMessage = (Message) field.get(mainQueue);
if (mMessage != null) {
long when = mMessage.getWhen();
if(when == 0) {
return false;
}
long time = when - SystemClock.uptimeMillis();
long timeThreshold = BACKGROUND_MSG_THRESHOLD;
if (foreground) {
timeThreshold = FOREGROUND_MSG_THRESHOLD;
}
return time < timeThreshold;
}
} catch (Exception e){
return false;
}
return false;
}
总结一下,
该方案通过去监听SIGQUIT信号,从而感知当前进程可能发生了ANR,需配合当前进程是否处于NOT_RESPONDING
状态以及主线程是否卡顿来进行甄别,以免误判。注册监听SIGQUIT信号之后,系统原来的Signal Catcher线程就监听不到这个信号了,需要把该信号转发出去,让它接收到,以免影响。当前进程的Signal Catcher线程要dump堆栈的时候,会通过socket的write向system server进程进行传输dump好的数据,我们可以hook这个write,从而拿到系统dump好的ANR Trace内容,相当于我们并没有影响系统的任何流程,还拿到了想要拿到的东西。这个方案完全是在系统的正常dump anr trace的过程中获取信息,所以能拿到的东西更加全面,但是系统的dump过程其实是对性能影响比较大的,时间也比较久。
5.2 系统如何采集ANR的?
进程之间是相互隔离的,即使是系统进程也无法直接获取其它进程相关信息。因此需要借助 IPC 通信的方式,将指令发送到目标进程,目标进程接. 收到信号后,协助完成自身进程 Dump 信息并发送给系统进程
dump特别耗系统资源:
而且从上面流程可以看到发生 ANR 时,系统进程除了发送信号给其它进程之外,自身也 Dump Trace,并获取系统整体及各进程 CPU 使用情况,且将其它进程 Dump 发送的数据写到文件中。因此这些开销将会导致系统进程在 ANR 过程承担很大的负载,这是为什么我们经常在 ANR Trace 中看到 SystemServer 进程 CPU 占比普遍较高的主要原因。
缺点: 该方案从思路上来说优于第一种方案,并且遵循系统信息获取方式,获取的线程信息及虚拟机信息更加全面,但缺点是对性能影响比较大,对于复杂的 App 来 说,统计 其耗时,部分场景一次 Dump 耗时可能要超过 10S。
问题: 为什么要dump这些信息?
因为ANR不一定是程序的问题,还和系统有关系
5.3 问题: Trace文件怎么生成的?
当APP(包括系统APP和用户APP)进程出现ANR、应用响应慢或WatchDog的监视没有得到回馈时,
系统会dump此时的top进程,进程中Thread的运行状态就都dump到这个Trace文件中了.
应用ANR产生的时候,ActivityManagerService的appNotResponding方法就会被调用,然后在/data/anr/traces.txt文件中写入ANR相关信息.
AMS中的AppNotRespondingViaProvider方法
@Override
public void appNotRespondingViaProvider(IBinder connection) {
enforceCallingPermission(REMOVE_TASKS, "appNotRespondingViaProvider()");
final ContentProviderConnection conn = (ContentProviderConnection) connection;
if (conn == null) {
Slog.w(TAG, "ContentProviderConnection is null");
return;
}
final ProcessRecord host = conn.provider.proc;
if (host == null) {
Slog.w(TAG, "Failed to find hosting ProcessRecord");
return;
}
mHandler.post(new Runnable() {
@Override
public void run() {
host.appNotResponding(
6. 线上如何监控?nativePollOnce导致的ANR
源码:有大佬根据该文章的原理实现了一个类似的开源库: MoonlightTreasureBox
https://github.com/xiaolutang/MoonlightTreasureBox
6.1 ANR经典案例
可能很多小伙伴的项目中都集成了bugly,确实bugly是很不错的线上监控组件,像Crash、ANR都能够检测到,但是很多时候,日志是不全的,堆栈信息不全就没法定位问题
ANR分析:并且占据了 top1。
ANR 都是 nativePollOnce 的堆栈
对比下nativePollOnce和主线程闲遐区别(重点),怎么都有nativePollOnce
6.2 监控缺陷
缺陷: 系统监控能力不完善: 安卓系统都是dump当前的信息, 为了性能, 只采集了5个进程的信息!
其实真正发生Anr的并不是它! 刻舟求剑, ****抓一次堆栈日志是不准的!
此时的堆栈抓取是一种事后策略,除了一些非常明显的比如线程死锁或者当前正好存在异常耗时的业务逻辑外,对更隐晦和复杂的原因就无能为力了,这种“事后策略”往往导致上报的 ANR 数据里充斥着大量的“无效堆栈”。比如经典的 MessageQueue.nativePollOnce
:
6.3 问题: 为什么总是抓到nativePollOnce?
线程是基于消息队列的方式进行调度,在每次消息调度完成之后都会从消息队列读取下一个待调度的消息,如果消息队列没有消息,或者下一个消息没有到设定的调度时间,并且也没有 IDLE 消息等待调度,那么主线程将会进入 IDLE 状态
使得主线程在消息调度过程中会多次进入 IDLE 状态,而这个过程也涉及到线程上下文切换(如:Java 环境切换到 Native 环境),会去检测是否有挂起请求,所以对调用频繁的接口来说,会在 ANR 发生时被命中,理论上调用越频繁的接口被命中的概率越大****
导致ANR的原因, 可以看到对于导致ANR的原因归为以下几类:
第一类(正常情况): 当前 Trace 堆栈所在业务耗时严重;
第二类(误抓): 当前 Trace 堆栈所在业务耗时并不严重,但是历史调度有一个严重耗时;
当前 Trace 堆栈所在业务耗时并不严重,但是历史调度有多个消息耗时;
第三类(消息太多了, 比较少用): 当前 Trace 堆栈所在业务耗时并不严重,但是历史调度存在巨量重复消息(业务频繁发送消息);
第四类(正常,系统问题),当前 Trace 堆栈业务逻辑并不耗时,但是其他线程存在严重资源抢占,如 IO,Mem,CPU;
当前 Trace 堆栈业务逻辑并不耗时,但是其他进程存在严重资源抢占,如 IO,Mem,CPU;
之所以会出现 MessageQueue.nativePollOnce 和 MessageQueue.next 是由于这两个方法在主线程中是高频执行的!
next()方法里面就是nativePollOnce()
@UnsupportedAppUsage
Message next() {
// Return here if the message loop has already quit and been disposed.
// This can happen if the application tries to restart a looper after quit
// which is not supported.
int pendingIdleHandlerCount = -1; // -1 only during first iteration
int nextPollTimeoutMillis = 0;
for (;;) {
if (nextPollTimeoutMillis != 0) {
Binder.flushPendingCommands();
}
nativePollOnce(ptr, nextPollTimeoutMillis);
由于前面的消息产生了耗时,不断堆积,等发生了ANR正好执行在这两个方法上,于是它们成了替罪羊被系统捕获。那么我们该怎样去获取到当前发生卡顿的消息呢?
ANR 的信号是异步产生的,在接收到 ANR 信号时采集堆栈,除了有可能采集到当前消息内执行的业务堆栈外,也有可能采集到主线程 MesageQueue 正在取消息的“过程”,这个取下一条消息的方法 MessageQueue.next() 调用得非常频繁,所以命中概率很高,这也是为什么很多 ANR 上报里最终都命中了这个堆栈。
MessageQueue.nativePollOnce: 沉睡, 休眠
6.4 线上监控的解决方案
解放方案: 需要知道ANR前一段时间时间的堆栈信息!
记录主线程过去 10s 内所有消息的调度历史,保存业务方需要的关键数据,并处理好性能和内存占用,在问题发生时,上报监控阈值内的调度数据:
有提示的可感知 ANR 最长耗时是 10s,如果可以通过一种机制! (为啥是10s,因为你看4种anr的图,前台不超过10s)
NativePollOnce的案例总结:
发生 ANR 问题时,NativePollOnce 场景耗时并不长,导致本次 ANR 的主要原因是历史消息在 UI 绘制过程中同步创建 Webview,导致耗时严重。
这类场景在线上线下都大量存在,但是从 ANR 设计原理和 Trace 采集流程来看,很多并不耗时的消息在调度过程中都成为了“替罪羊”。
Sliver主要作用:记录线程历史堆栈调用信息(主要用这个)**
具体方案:
超过 200ms 的消息就要开始记录了!
(多条小消息聚合, 更新最新的消息)小消息聚合成一条,记录最后一条小消息的 callback 和 traget,总耗时和消息的 occurTime,用来串起整个消息 Record 队列。
消息 Record 队列的最大值目前设置为 500 条,并通过 Size + occurTime 滚动淘汰旧值。概括来说就是“超出队列上限的”以及“消息发生时间超出设定阈值比如 10s 的旧数据”会被滚动删除。
总结:
1.消息累计耗时超过设置的阈值,则汇总并生成一条记录(最多存储100条,一条记录共300ms)
们需要对 ActivityThread.H 的消息调度进行监控,当发现上面这些组件有关的消息在执行时,不管其耗时多少,都对其进行单独记录
基础数据外,还需要知道当前调度的是哪一类系统消息,从而筛选出会导致 ANR 的四大组件调度信息。
采集如何高效率的采集? 不是上面的ANR采集, 是工具采集
1). 在每个消息开始执行时,触发子线程的超时监控,如果在超时之后本次消息还没执行结束,则抓取主线程堆栈,并继续对该消息设置下一次超时监控,直到该消息执行结束并取消本轮监控。如果在触发超时之前已经执行完毕,则取消本次监控并在下次消息开始执行时,再次设置超时监控,但是因为大部分消息耗时都很少,如果每次都频繁设置和取消,将会带来性能影响,因此我们对此进行优化,采用系统 ANR 超时监控相同的时间对齐方案,具体来说就是:
2). 以消息开始时间加上超时时长为目标超时时间,每次超时时间到了之后,检查当前时间是否大于或等于目标时间,如果满足,则说明目标时间没有更新,也就是说本次消息没结束,则抓取堆栈。如果每次超时之后,检查当前时间小于目标时间,则说明上次消息执行结束,新的消息开始执行并更新了目标超时时间,这时异步监控需对齐目标超时,再次设置超时监控,如此往复。
工具需要的3部分*****信息, 主要是主线程的堆栈*
1. 历史主消息堆栈(history)
2. 正在发生ANR得堆栈(Block)
3. 将要发生的堆栈(Pending) , 要这个有啥用????
通过这3部分信息,就可以完整的还原现场!
可以发现这个堆栈就是前面提到程序员的噩梦堆栈,由于发生anr之后,dump应用的线程堆栈,会有延迟,有时候dump到的堆栈就是导致ANR的Message运行结束之后,拿到的trace的日志就是这样子。
单单从堆栈已经无法找到罪魁祸首了,但是可以从HISTORY MSG可以看到这个Message运行了7002毫秒,这个就是前面am_anr中打印的Working Message,也就是导致这次ANR的罪魁祸首。
Message 0 :start=64631 delay=278ms took=7002ms repeat=0 { when=0 what=114 obj=CreateServiceData{token=android.os.BinderProxy@2d85d09 className=com.kobe.fpstest.Service packageName=com.kobe.fpstest intent=null} target=android.app.ActivityThread$H }
工具的案例分析:
在ANR 之前存在一个索引为 46 的历史消息耗时严重(wall duration:10747ms),同时还有一个索引为 32 的历史消息耗时也比较严重(wall duration:10747ms)。
lock 时长为 9487ms,因此我们排除了索引为 32 的历史消息