愿历尽千帆 归来仍少年

AMS锁严重竞争导致的整机卡顿

字数统计: 1,091阅读时长: 4 min
2021/09/18
日志抓取

在问题机器上抓了一份Systrace
1.操作步骤: 进入设置界面滑动再退出
2.问题现象: 进入设置出现较长时间白屏,退出时有拖影,下拉状态栏尤为卡顿,解锁亮屏很慢。

问题分析

从下图可以看到进入设置时,Resume耗时近400ms,主要耗费在等binder上

来到对端1188_19线程所在区域,看下这个时间点1188_19在做什么操作?

1188_19是SystemServer中的线程,从上图可以看出,它在等AMS锁
到这里大致梳理如下
1.进入设置应用走到onResume环节时,调用到AMS的registerReceiverWithFeature注册广播,这是应用启动过程中很常见的操作,但是此时registerReceiverWithFeature执行操作被block了,因为执行registerReceiverWithFeature需要申请到AMS锁才行。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
public Intent registerReceiverWithFeature(IApplicationThread caller, String callerPackage,
String callerFeatureId, IIntentReceiver receiver, IntentFilter filter,
String permission, int userId, int flags) {
//省略部分代码
boolean instantApp;
synchronized(this) {
if (caller != null) {
callerApp = getRecordForAppLocked(caller);
if (callerApp == null) {
throw new SecurityException(
"Unable to find app for caller " + caller
+ " (pid=" + Binder.getCallingPid()
+ ") when registering receiver " + receiver);
}
//省略部分代码
}
//省略部分代码

2.此时Settings的registerReceiverWithFeature在等ActivityManagerService#finishReceiver释放锁,但其实ActivityManagerService#finishReceiver本身也是在等锁,锁在1188_6这个线程手中。
图中有一处waiters=6说明还有其它六处加上这次调用共计7处在等AMS的锁
纵观整个应用操作片段,发现很多地方都在等AMS锁,这也说明了为何系统会全局卡顿。

看下真正持有锁的1188_6这个线程,这个线程持有锁的这段时间内,大部分时候都是running状态

全局搜索了下在一分钟不到的时间内触发了197次,而且单次基本都在200ms之久。

为此对比了下正常情况下的Systrace,两分钟的时间内共触发14次,平均一分钟7次,且每次updateOomAdj_finishReceiver执行时间都不超过1ms

到这里大概整理下
1.为何updateOomAdj_finishReceiver会调用这么频繁?
updateOomAdj_finishReceiver是在广播处理结束后会触发调用,问题机器上一分钟调用197次,正常情况下一分钟调用次数是个位数.
2.为何updateOomAdj_finishReceiver耗时这么久?
单次执行都在200ms左右,这也意味着每次持有AMS锁大概200ms,也就意味着一分钟的时间finishReceiver持有AMS锁时间高达39s,这也解释了从Systrace看很多地方都在等AMS锁。
测试了下正常情况下,updateOomAdj_finishReceiver单次执行时间最长一般不会超过1ms

下面先从广播来源分析,updateOomAdj_finishReceiver触发频繁的原因

频繁触发原因

以导致设置应用resume耗时严重的这次updateOomAdj_finishReceiver为例

1416对应的是SystemUI中线程,直接来到SystemServer区域看下广播部分

再从全局来看

可以看到com.android.providers.media.module以及SystemUI这两个模块在交替不间断的发送android.intent.action.MEDIA_SCANNER_SCAN_FILE这个广播,查看代码得知是com.android.providers.media.module这个模块处理扫描文件事务后会发送MEDIA_SCANNER_SCAN_FILE这个广播给SystemUI,SystemUI收到这个广播进行一系列的业务处理,然后再次发送MEDIA_SCANNER_SCAN_FILE这个广播出来。
这种业务设计肯定是不合理的,这里暂不继续讨论这种做法的缘由。

单次处理耗时


从上图可以看到,问题发生时,SystemUI模块中单次处理该模块耗时达到1s多,这也和问题机器上SystemUI下拉栏滑动极其卡顿能够对应上。
结论: SystemUI主线程中广播处理耗时导致滑动很卡顿

问题结论

主要由于如下两点原因导致:
1.SystemUI中不合理的高频广播,导致AMS@finishReceiver触发频繁并持有AMS锁,造成了全局AMS锁争抢极其严重。
2.SystemUI主线程中单次处理广播耗时较长,加剧了卡顿的现象。

PS: SystemUI这个模块比较特殊,它不像其他应用模块。对于应用模块而言,即便是一直收发广播,卡顿也只是会局限在这个应用操作环节中,不会影响到其他模块。但是SystemUI就不同了,它是可以一直运行着,并且此时你可以操作其他任何应用。

CATALOG
  1. 1. 日志抓取
  2. 2. 问题分析
    1. 2.1. 频繁触发原因
    2. 2.2. 单次处理耗时
  3. 3. 问题结论