最近看了下ANR代码,结合之前项目上的一些ANR案例,打算对ANR的原理以及常见案例做下小结,涉及的代码均基于Android S
画了一张图,列举了可能导致ANR的一些影响因素
原理机制
我们平时遇到的ANR问题大部分都是input ANR类型,所以以input ANR为例进行梳理,这块机制并不复杂,只梳理埋计时和check超时的代码部分。
正常输入事件的分发流程如下1
2
3
4
5InputDispatcher::dispatchOnce()
->InputDispatcher::dispatchOnceInnerLocked
->InputDispatcher::dispatchKeyLocked
->InputDispatcher::findFocusedWindowTargetsLocked
......
findFocusedWindowTargetsLocked
这个函数从字面很好理解: 查找有焦点window。
因函数较长,我们将其拆分开来进行梳理
Step1: 未找到focused的window,也没有找到focused的application,drop该事件
1 | // If there is no currently focused window and no focused application |
Step2: 未找到focused的window,有focused的application,这是最为常见的情况
1 | if (focusedWindowHandle == nullptr && focusedApplicationHandle != nullptr) { |
Step3: 重置超时时间
1 | // we have a valid, non-null focused window |
执行到这步,说明本次findFocusedWindowTargetsLocked
找到了非空的window,这种情况下会resetNoFocusedWindowTimeoutLocked。
除此之外,系统还有多个场景下也会触发该重置接口,比如
- setFocusedApplicationLocked 当前focused应用发生变化
- setInputDispatchMode 调用了分发模式
- resetAndDropEverythingLocked 这个接口存在多处会调用,比如stopFreezingDisplayLocked解冻屏幕、performEnableScreen亮屏等场景
Step4: 其它窗口异常情况
如果当前window存在异常情况,也会做pending处理,同样可能会成为造成ANR的原因
比如窗口处于paused状态
1 | if (focusedWindowHandle->getInfo()->paused) { |
还有其他情况也会导致pending,如窗口未连接、窗口连接已满、窗口连接已死亡等,不再一一列出。
这里提到了造成消息pending的情况,我们自然会想到那什么场景下消息会drop掉呢?frameworks/native/services/inputflinger/dispatcher/InputDispatcher.cpp
大致有如上几种场景会造成消息drop,dropInboundEventLocked的触发时机是在InputDispatcher::dispatchOnceInnerLocked
中。
到这里我们已经清楚了埋下超时时间的流程,那么什么时候会检查超时时间有没有到呢?InputDispatcher.cpp@dispatchOnce-> InputDispatcher.cpp@processAnrsLocked
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40/**
* Check if any of the connections' wait queues have events that are too old.
* If we waited for events to be ack'ed for more than the window timeout, raise an ANR.
* Return the time at which we should wake up next.
*/
nsecs_t InputDispatcher::processAnrsLocked() {
const nsecs_t currentTime = now();
nsecs_t nextAnrCheck = LONG_LONG_MAX;
// Check if we are waiting for a focused window to appear. Raise ANR if waited too long
if (mNoFocusedWindowTimeoutTime.has_value() && mAwaitedFocusedApplication != nullptr) {
if (currentTime >= *mNoFocusedWindowTimeoutTime) {
processNoFocusedWindowAnrLocked();
mAwaitedFocusedApplication.reset();
mNoFocusedWindowTimeoutTime = std::nullopt;
return LONG_LONG_MIN;
} else {
//mNoFocusedWindowTimeoutTime代表的是这个window超时的时间点
// Keep waiting. We will drop the event when mNoFocusedWindowTimeoutTime comes.
nextAnrCheck = *mNoFocusedWindowTimeoutTime;
}
}
// Check if any connection ANRs are due
nextAnrCheck = std::min(nextAnrCheck, mAnrTracker.firstTimeout());
if (currentTime < nextAnrCheck) { // most likely scenario
return nextAnrCheck; // everything is normal. Let's check again at nextAnrCheck
}
// If we reached here, we have an unresponsive connection.
sp<Connection> connection = getConnectionLocked(mAnrTracker.firstToken());
if (connection == nullptr) {
ALOGE("Could not find connection for entry %" PRId64, mAnrTracker.firstTimeout());
return nextAnrCheck;
}
connection->responsive = false;
// Stop waking up for this unresponsive connection
mAnrTracker.eraseToken(connection->inputChannel->getConnectionToken());
onAnrLocked(connection);
return LONG_LONG_MIN;
}
如果当前时间已经满足超时时间,则触发onAnrLocked
1 | void InputDispatcher::onAnrLocked(std::shared_ptr<InputApplicationHandle> application) { |
onAnrLocked函数的主要作用是将doNotifyNoFocusedWindowAnrLockedInterruptible
通过postCommandLocked
塞进队列中。
在下一次InputDispatcher.dispatchOnce
中会执行runCommandsLockedInterruptible
runCommandsLockedInterruptible
方法很简单,取出所有的Command执行一遍
这里顺便提一下,我们平时分析日志时经常会遇到类似这样的片段
上面的日志片段其实是在processAnrsLocked中打印的,这块日志打印在S上已经被谷歌移除了。
分析步骤
Step1:系统环境因素
首先判断下是否受环境因素影响,这里所说的系统环境因素通常指的是整机负载/低内存/系统异常等,下面以高负载和低内存这两个场景为例进行说明
一. 受整机负载影响
搜索ANR in
关键词1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
1701-29 06:24:46.618452 1210 5962 I AnrManager: ANR in com.journeyui.calculator (com.journeyui.calculator/.Calculator), time=260439862
01-29 06:24:46.618452 1210 5962 I AnrManager: Reason: Input dispatching timed out (ActivityRecord{51e27ca u0 com.journeyui.calculator/.Calculator t1837} does not have a focused window)
01-29 06:24:46.618452 1210 5962 I AnrManager: Load: 31.7 / 33.43 / 30.98
01-29 06:24:46.618452 1210 5962 I AnrManager: Android time :[2022-01-29 06:24:46.60] [260451.594]
01-29 06:24:46.618452 1210 5962 I AnrManager: CPU usage from 167270ms to 0ms ago (2022-01-29 06:21:47.589 to 2022-01-29 06:24:34.860) with 99% awake:
01-29 06:24:46.618452 1210 5962 I AnrManager: 226% 1210/system_server: 173% user + 52% kernel / faults: 1026822 minor 8 major
01-29 06:24:46.618452 1210 5962 I AnrManager: 125% 459/logd: 16% user + 109% kernel / faults: 408 minor
01-29 06:24:46.618452 1210 5962 I AnrManager: 29% 21567/com.journeyui.globalsearch: 18% user + 10% kernel / faults: 45071 minor 25 major
01-29 06:24:46.618452 1210 5962 I AnrManager: 26% 639/surfaceflinger: 18% user + 8.6% kernel / faults: 4704 minor
01-29 06:24:46.618452 1210 5962 I AnrManager: 26% 20889/com.yulong.android.gamecenter: 16% user + 9.3% kernel / faults: 21143 minor
01-29 06:24:46.618452 1210 5962 I AnrManager: 24% 29706/com.sohu.inputmethod.sogou:home: 16% user + 8.6% kernel / faults: 21832 minor
01-29 06:24:46.618452 1210 5962 I AnrManager: 24% 545/com.android.messaging: 15% user + 9% kernel / faults: 26023 minor 2 major
01-29 06:24:46.618452 1210 5962 I AnrManager: 19% 803/guardserver: 3% user + 16% kernel
//....
01-29 06:24:46.618452 1210 5962 I AnrManager: 1.7% 3589/com.journeyui.calculator: 1% user + 0.6% kernel / faults: 3365 minor 5 major
//.....
01-29 06:24:46.618480 1210 5962 I AnrManager: 85% TOTAL: 42% user + 33% kernel + 0% iowait + 0% softirq
ANR in com.journeyui.calculator
ANR进程名Reason: Input dispatching timed out (ActivityRecord{51e27ca u0 com.journeyui.calculator/.Calculator t1837} does not have a focused window)
ANR原因,通俗的解释是:输入事件落到了
com.tencent.mm/.ui.LauncherUI这个窗口上,该窗口直到超时时间到了仍未响应输入事件,input超时时间系统默认是5s(我们客制化为8s)。- Load: 31.7 / 33.43 / 30.98 前 1,前 5,前 15 分钟的负载,我们通常看变化趋势。
2022-01-29 06:21:47.589 to 2022-01-29 06:24:34.860
统计的时间区域85% TOTAL: 42% user + 33% kernel + 0% iowait + 0% softirq
这行是我们通常比较关注的,代表了整体的负载情况,85% TOTAL说明整机负载很高。- 图中(4)-(5)之间的片段则是各个进程占据的CPU情况, 发生ANR的进程
com.journeyui.calculator
的CPU占用只有1.7%
PS: 整机CPU loading很高转给系统同事分析
二. 整机内存
我们知道通常内存紧张的时候,kswapd线程会活跃起来进行回收内存
比如下面这个案例
通常认为kswapd的CPU占据排进top3的话,这个问题受系统低内存影响比较大。
为何低内存会可能和ANR扯上关系呢?
因为整机一旦陷入低内存,会表现的响应慢以及多场景下操作卡顿。
比如启动应用时间变长 、滑动列表会掉更多帧、LMKD活跃杀进程以释放更多内存。
PS: 这个时候如果现场还在的话,可以执行通过adb shell cat proc/meminfo查看下内存情况
低内存对整机性能的影响
- 从过往分析的Systrace来看,低内存会出现大量的Uninterruptible Sleep | WakeKill - Block I/O block信息都是wait_on_page_bit_killable.
它的链路是do_page_fault —> lock_page_or_retry -> wait_on_page_bit_killable,由于低内存可能触发的fast path 回收 \ kswapd 回收 \ direct reclaim 回收 \ LMK杀进程回收等行为,造成do_page_fault 高频发生。
当出现大量的 IO 操作的时候,应用主线程的 Uninterruptible Sleep 也会变多,此时涉及到 io 操作(比如 view ,读文件,读配置文件、读 odex 文件),都会触发 Uninterruptible Sleep , 导致整个操作的时间变长,这就解释了为何低内存下为何应用响应卡顿。 - 另外低内存的时候,kswapd0和HeapTaskDaemon线程会非常活跃,从我们过往的分析来看,低内存时kswapd0和HeapTaskDaemon线程会跑在大核,占据很多的CPU资源,并且会和前台应用争抢CPU资源,这就可能会出现前台进程得不到足够的CPU资源而出现响应卡顿。
- 低内存时查杀进程,有些进程被kill后会立刻restart,我们之前项目上遇到过低内存时,persistent服务进程被kill立马restart,陷入了一种”死循环”,导致整机严重卡顿以及发烫。
所以,如果分析ANR问题遇到这种kswapd占据很高(通常认为排到top3内),基本可以认为该问题是由于系统环境因素导致。
另外这个时候,如果搜索”lowmemorykiller”关键词,可以看到问题时间区域会有较多的查杀进程行为,我们通常看”lowmemorykiller”这一行杀的进程adj值,adj值越低,说明当前系统内存越吃紧。
小结:如果出现了整机高负载或者低内存的情况,ANR的进程可能只是充当了受害者的角色。
Step2: 分析堆栈
如果前面已经排除了系统环境影响因素的话,那么接下来就要分析具体的callstack了
搜索”am_anr”关键字
时间点: 01-25 14:40:44
,进程号是17728
根据时间戳找到anr文件下对应的trace文件
文件头部看下进程号再次确认下
搜索关键字”sysTid=17728”, 这里的17728就是上面”am_anr”中包含的进程号也是主线程号
- 线程运行状态
- nice值代表该线程优先级,nice的取值范围为-20到19,通常来说nice的值越大,进程的优先级就越低,获得CPU调用的机会越少,nice值越小,进程的优先级则越高,获得CPU调用的机会越多。
- utm:该线程在用户态所执行的时间(单位是jiffies)
stm:该线程在内核态所执行的时间
该线程的cpu耗时是两者相加(utm+stm),utm,stm 单位换算成时间单位为 1 比 10ms - core:跑在哪个核上,core=7表示打印这段日志时该线程跑在大核CPU7上
- 函数调用堆栈
典型案例
主线程耗时操作
这种情况是最为常见一种类型
比如下面这个案例,是com.tencent.qqlive的ANR,callstack如下
通常来说,如果打印的堆栈是ANR进程的堆栈,业务验证证实这段代码确实存在耗时的可能,那么根据callstack位置找到代码修改即可。
主线程 Blocked/waiting/Sleeping
主线程当前的状态是(1)Blocked, 原因是它在等锁(2) 0x06573567,而0x06573567被(3)线程13所持有
看下tid=13线程 CallStack,在该份trace文件中搜索关键字”0x06573567”找到线程13的堆栈。
除了主线程陷入Blocked这种比较常见的情况之外,通常是由于真正持有锁的线程在做繁琐的事务或是发生了死锁,除此之外还有一些少见的情况
- 主线程处于waiting状态,说明其正在等待其他线程来notify它,堆栈同样是等锁,分析思路一样。
- 主线程处于Sleeping状态,说明当前线程主动调用sleep,其堆栈通常是sleeping on <锁ID>。
Binder block
这种情况比较常见,比如A进程在主线程中向B进程发起binder请求,B进程因为一些原因比如正在处理耗时消息或网络异常等原因,无法及时响应A进程的binder的请求,造成A进程一直阻塞等待binder的返回结果最终ANR。
比如下面这个案例
keyguard模块做native层的binder通信,阻塞等待对端结果返回。
涉及一个问题:我们该如何快速找到binder对端信息?
对于mtk平台而言,anr文件下的binderinfo会打印出binder交互的信息
搜索关键字”outgoing transaction” 表示的是当前线程扮演的是Client角色,向其它进程发起binder。
28444这个进程中28536这个线程向22767这个进程发起了binder请求。
需要注意一点的是:22767:0这里0代表的是server端当前没有可用binder线程。
如果binderinfo文件中没有找到的话,也可以在kernel日志中搜索”binder : release”关键词,这行日志通常是binder所在进程结束时会吐出来。
Binder 池耗尽
应用的Binder池最多支持16个binder线程,SystemServer比较特殊支持最多32个binder线程。
那么什么样的场景下可能会出现Binder 池耗尽的情况呢?
比如进程A发送太多重复binder请求给进程B,那么就会导致短时间内接收端进程B的binder线程池被占满,从而处理不了A进程发过来的binder请求。
比如下面这段日志
和上面binder block同样的分析策略,找到对端是谁以及对端的callstack即可,不再详细展开。
陷阱堆栈
何为陷阱堆栈,即出现的callstack并非真正的凶手,比如我们最为常见的CallStack落在nativePollOnce上,这种情况说明当前主线程的消息队列是空闲的,在等待处理下一个msg,打印日志时真正的block消息已经走完了。
以下面这个计算器的anr案例1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
1601-29 06:24:46.618452 1210 5962 I AnrManager: ANR in com.journeyui.calculator (com.journeyui.calculator/.Calculator), time=260439862
01-29 06:24:46.618452 1210 5962 I AnrManager: Reason: Input dispatching timed out (ActivityRecord{51e27ca u0 com.journeyui.calculator/.Calculator t1837} does not have a focused window)
01-29 06:24:46.618452 1210 5962 I AnrManager: Load: 31.7 / 33.43 / 30.98
01-29 06:24:46.618452 1210 5962 I AnrManager: Android time :[2022-01-29 06:24:46.60] [260451.594]
01-29 06:24:46.618452 1210 5962 I AnrManager: CPU usage from 167270ms to 0ms ago (2022-01-29 06:21:47.589 to 2022-01-29 06:24:34.860) with 99% awake:
01-29 06:24:46.618452 1210 5962 I AnrManager: 226% 1210/system_server: 173% user + 52% kernel / faults: 1026822 minor 8 major
01-29 06:24:46.618452 1210 5962 I AnrManager: 125% 459/logd: 16% user + 109% kernel / faults: 408 minor
01-29 06:24:46.618452 1210 5962 I AnrManager: 29% 21567/com.journeyui.globalsearch: 18% user + 10% kernel / faults: 45071 minor 25 major
01-29 06:24:46.618452 1210 5962 I AnrManager: 26% 639/surfaceflinger: 18% user + 8.6% kernel / faults: 4704 minor
01-29 06:24:46.618452 1210 5962 I AnrManager: 26% 20889/com.yulong.android.gamecenter: 16% user + 9.3% kernel / faults: 21143 minor
01-29 06:24:46.618452 1210 5962 I AnrManager: 24% 29706/com.sohu.inputmethod.sogou:home: 16% user + 8.6% kernel / faults: 21832 minor
01-29 06:24:46.618452 1210 5962 I AnrManager: 24% 545/com.android.messaging: 15% user + 9% kernel / faults: 26023 minor 2 major
//...
01-29 06:24:46.618452 1210 5962 I AnrManager: 1.7% 3589/com.journeyui.calculator: 1% user + 0.6% kernel / faults: 3365 minor 5 major
//...
01-29 06:24:46.618480 1210 5962 I AnrManager: 75% TOTAL: 42% user + 33% kernel + 0% iowait + 0% softirq
整机负载很高,但是前台进程com.journeyui.calculator占用只有1.7%,top5中没有kswapd的身影,排除低内存的影响。
PS: SystemServer占据如果稍高可能是正常的,Dump Trace时需要获取系统整体及各进程 CPU 使用情况,短时间内会造成SystemServer升高。
接着event日志中搜索”am_anr”关键字1
01-29 06:24:34.907471 1210 5962 I am_anr : [0,3589,com.journeyui.calculator,684244549,Input dispatching timed out (ActivityRecord{51e27ca u0 com.journeyui.calculator/.Calculator t1837} does not have a focused window)]
找到对应的anr文件
callstack落在了nativePollOnce上
我们前面说过落在nativePollOnce上,说明应用已经idle了
那么什么情况下会出现落在nativePollOnce上呢?
- 应用主线程历史调度中存在严重耗时的消息
- 应用主线程历史调度中存在多个耗时的消息
- 应用主线程历史调度中存在大量消息比如高频发送消息
- 应用主线程本身并不耗时,而是受到系统环境因素影响(IO/低内存/高负载等)
那么历史调度中的耗时消息我们应该如何得知?
谷歌本身在系统多处都加有耗时消息打印,比如我们常见的日志Looper : Slow dispatch等。
通常手机厂商也会做日志增强,常见的思路如下:
- 监控主线程的binder transaction的耗时情况, 超过阈值时输出相应的目标调用信息。
- 当某个线程等待lock的时间blocked超过阈值,则输出当前的持锁状态。
- 主线程的生命周期回调方法执行时间超过阈值,则输出相应信息。
- 当system_server等进程的线程池使用完, 无空闲线程时, 则binder通信都处于饥饿状态, 则饥饿状态超过一定阈值则输出信息。
- 当任意进程的非oneway的Binder调用耗时超过一定阈值的时候,输出Slow Binder信息。
- 当SystemServer进程响应其它任意Java进程的非oneway的Binder调用,耗时超过一定阈值的时候,输出Slow Binder信息
一些头部应用厂商如字节跳动有自研的Raster消息监控平台,出现这种落在nativePollOnce
上查找历史耗时消息即可。
除了落在nativePollOnce
的情况,还有一种情况则更加隐蔽,也更容易将我们带偏分析的方向。
那就是callstack打印出来确实是应用自身的堆栈,但是根据callstack找到对应代码后发现根本不可能会出现耗时,说明真正的”凶手”藏身在历史消息中。
应用内存问题
我们平时也会经常遇到这样的情况:应用自身内存使用不当导致的ANR
比如下面的美团ANR案例1
2
3
4
5
6
7
8
9
10
1101-08 14:53:20.130 1074 32039 I AnrManager: ANR in com.sankuai.meituan (com.sankuai.meituan/com.meituan.android.pt.homepage.activity.MainActivity), time=48329538
01-08 14:53:20.130 1074 32039 I AnrManager: Reason: Input dispatching timed out (c961943 com.sankuai.meituan/com.meituan.android.pt.homepage.activity.MainActivity (server) is not responding. Waited 8006ms for MotionEvent)
01-08 14:53:20.130 1074 32039 I AnrManager: Load: 27.74 / 27.04 / 27.19
01-08 14:53:20.130 1074 32039 I AnrManager: Android time :[2022-01-08 14:53:20.10] [48351.410]
01-08 14:53:20.130 1074 32039 I AnrManager: CPU usage from 9706ms to 0ms ago (2022-01-08 14:52:48.524 to 2022-01-08 14:52:58.230):
01-08 14:53:20.130 1074 32039 I AnrManager: 100% 32613/com.sankuai.meituan: 99% user + 1.5% kernel / faults: 72075 minor
01-08 14:53:20.130 1074 32039 I AnrManager: 24% 16662/com.ss.android.ugc.aweme:miniappX: 17% user + 7.3% kernel / faults: 1762 minor
01-08 14:53:20.130 1074 32039 I AnrManager: 17% 4548/com.ss.android.ugc.aweme: 11% user + 5.9% kernel / faults: 2500 minor
01-08 14:53:20.130 1074 32039 I AnrManager: 11% 1074/system_server: 8% user + 3.6% kernel / faults: 6412 minor 1 major
//...
01-08 14:53:20.130 1074 32039 I AnrManager: 30% TOTAL: 21% user + 8.1% kernel + 0.1% iowait + 1% softirq
整机负载不高,且kswapd占比很低,基本可以排除系统环境影响1
01-08 14:52:58.243 1074 32039 I am_anr : [0,32613,com.sankuai.meituan,949501508,Input dispatching timed out (c961943 com.sankuai.meituan/com.meituan.android.pt.homepage.activity.MainActivity (server) is not responding. Waited 8006ms for MotionEvent)]
时间点14:52:58,进程号32613
因为这份日志缺少anr文件,所以我们直接看系统日志
在案发时间点附近,我们发现出现有大量的GC片段
Clamp target GC heap from这行日志是在SetIdealFootprint即调整目标堆上限值时会打印,这块不太熟悉的话可以参见我们之前发表过的一篇文章
日志说明当前应用堆使用已超出上限512M,为了分配新的对象,一直持续的阻塞GC再尝试分配。
通过日志我们可以发现,尽管应用持续的阻塞GC,但是内存依旧没有降下来。
对于应用内存使用问题,通常有如下几种情况
- 频繁的生成临时对象导致堆内存增长迅速,达到下次堆GC触发阈值后便会触发Bg GC,进而导致回收线程跑大核和前台应用争抢CPU。
另外GC回收阶段会存在一次锁堆,应用的主线程会被pause,这种情况下势必会造成应用使用卡顿甚至ANR。 - 比较常见的一种情况是应用发生了较为严重的内存泄漏,导致GC一直无法回收足够的内存。
- 申请大内存触发阻塞GC以申请到足够的内存,这种情况一般会引起黑屏卡顿。
- 还有一种情况,我们知道系统低内存时会触发OnTrimMemory回调,如果应用在OnTrimMemory中并且是在主线程中直接调用显式GC接口即System.gc(),也容易引起应用卡顿。
上面这些情况虽不一定会导致ANR,但是应用操作卡顿可能在所难免。
写在最后
通常ANR是卡顿的一种严重表现形式,所以遇到卡顿问题时应趁早解决,防患于未然。
参考文献
https://www.androidperformance.com/
https://blog.csdn.net/feelabclihu/article/details/120574383