一个AMS、PMS、WMS竞争锁引起死锁无法开启问题的分析过程

最新推荐文章于 2024-04-30 14:54:19 发布

海苔一笑倾城

最新推荐文章于 2024-04-30 14:54:19 发布

阅读量1.4k

点赞数 1

本文链接：https://blog.csdn.net/weixin_43709142/article/details/84190212

版权

Android Framework 专栏收录该内容

6 篇文章 0 订阅

订阅专栏

问题：在工厂段出现，一直提示“android 正在启动”，长按开机键恢复。由于产线生产机器都是按K计算，所以概率问题会放大，此问题大约1000台机器会出现10台左右的卡在android正在启动，由于到了量产阶段，问题紧急，无奈我还被紧急派去生产车间解决问题，最快的航班经济舱已满，生平第一次坐了一次头等舱（- -！）
首先就是要复现问题，抓到问题log，编译ENG版本，打开相关log，开始复现：

PackageManagerService中的：
static boolean DEBUG_SETTINGS = true;
static boolean DEBUG_PREFERRED = true;
static boolean DEBUG_UPGRADE = true;
private static boolean DEBUG_INSTALL = true;
private static boolean DEBUG_REMOVE = true;
private static boolean DEBUG_BROADCASTS = true;
private static boolean DEBUG_SHOW_INFO = true;
private static boolean DEBUG_PACKAGE_INFO = true;
private static boolean DEBUG_INTENT_MATCHING = true;
private static boolean DEBUG_PACKAGE_SCANNING = true;
private static boolean DEBUG_VERIFY = true;
private static boolean DEBUG_DEXOPT = true;
private static boolean DEBUG_ABI_SELECTION = true;
private static boolean DEBUG_PERMISSION = true;
ActivityManagerService中：
static boolean DEBUG_SERVICE = true;
static boolean DEBUG_SERVICE_EXECUTING = true;

由于问题的表现是“Android正在启动”异常，在log中能够看到开机时某些apk又去提取odex,列举如下：
1、//其中开机重新提取odex仅为arm64的apk有(无lib库)：

05-06 16:43:22.870 1076 1076 I dex2oat : /system/bin/dex2oat --zip-fd=11 --zip-location=/system/app/E163_WindPowerSaver/E163_WindPowerSaver.apk --oat-fd=12 --oat-location=/data/dalvik-cache/arm64/system@app@E163_WindPowerSaver@E163_WindPowerSaver.apk@classes.dex --instruction-set=arm64 --instruction-set-features=default --runtime-arg -Xms64m --runtime-arg -Xmx512m --swap-fd=13
05-06 16:43:24.415 1081 1081 I dex2oat : /system/bin/dex2oat --zip-fd=11 --zip-location=/system/plugin/UsbChecker/UsbChecker.apk --oat-fd=12 --oat-location=/data/dalvik-cache/arm64/system@plugin@UsbChecker@UsbChecker.apk@classes.dex --instruction-set=arm64 --instruction-set-features=default --runtime-arg -Xms64m --runtime-arg -Xmx512m --swap-fd=13
05-06 16:43:25.875 1098 1098 I dex2oat : /system/bin/dex2oat --zip-fd=11 --zip-location=/system/app/AtciService/AtciService.apk --oat-fd=12 --oat-location=/data/dalvik-cache/arm64/system@app@AtciService@AtciService.apk@classes.dex --instruction-set=arm64 --instruction-set-features=default --runtime-arg -Xms64m --runtime-arg -Xmx512m --swap-fd=13
05-06 16:43:29.491 1154 1154 I dex2oat : /system/bin/dex2oat --zip-fd=11 --zip-location=/system/priv-app/E163_ZteDeviceRegister/E163_ZteDeviceRegister.apk --oat-fd=12 --oat-location=/data/dalvik-cache/arm64/system@priv-app@E163_ZteDeviceRegister@E163_ZteDeviceRegister.apk@classes.dex --instruction-set=arm64 --instruction-set-features=default --runtime-arg -Xms64m --runtime-arg -Xmx512m --swap-fd=13
05-06 16:44:55.465 1249 1249 I dex2oat : /system/bin/dex2oat --zip-fd=11 --zip-location=/system/vendor/operator/app/E163_PoemChina/E163_PoemChina.apk --oat-fd=12 --oat-location=/data/dalvik-cache/arm64/system@vendor@operator@app@E163_PoemChina@E163_PoemChina.apk@classes.dex --instruction-set=arm64 --instruction-set-features=default --runtime-arg -Xms64m --runtime-arg -Xmx512m --swap-fd=13

Solution有两种：
1、删除LOCAL_MULTILIB :=32或LOCAL_32_BIT_ONLY=true
2、对于这个apk的解决办法为预编译时跳过提起其的odex文件：
\build\core\dex_preopt_odex_install.mk中添加：
ifeq ($(LOCAL_MODULE),MODULE_NAME)
LOCAL_DEX_PREOPT:=
endif

built_odex:=
installed_odex:=
…
MODULE_NAME写为需要替换的apk的module name(注意添加位置、避免编译报错)

2、//其中开机重新提取odex仅为arm的apk（仅支持32位）：

05-06 16:43:30.057 1163 1163 I dex2oat : /system/bin/dex2oat --zip-fd=11 --zip-location=/system/priv-app/E163_share/E163_share.apk --oat-fd=12 --oat-location=/data/dalvik-cache/arm/system@priv-app@E163_share@E163_share.apk@classes.dex --instruction-set=arm --instruction-set-features=default --runtime-arg -Xms64m --runtime-arg -Xmx512m --swap-fd=13
05-06 16:43:52.769 1232 1232 I dex2oat : /system/bin/dex2oat --zip-fd=11 --zip-location=/system/vendor/operator/app/E163_CBox_mm_ZTE/E163_CBox_mm_ZTE.apk --oat-fd=12 --oat-location=/data/dalvik-cache/arm/system@vendor@operator@app@E163_CBox_mm_ZTE@E163_CBox_mm_ZTE.apk@classes.dex --instruction-set=arm --instruction-set-features=default --runtime-arg -Xms64m --runtime-arg -Xmx512m --swap-fd=13
05-06 16:44:09.802 1235 1235 I dex2oat : /system/bin/dex2oat --zip-fd=11 --zip-location=/system/vendor/operator/app/E163_mCloud/E163_mCloud.apk --oat-fd=12 --oat-location=/data/dalvik-cache/arm/system@vendor@operator@app@E163_mCloud@E163_mCloud.apk@classes.dex --instruction-set=arm --instruction-set-features=default --runtime-arg -Xms64m --runtime-arg -Xmx512m --swap-fd=13
05-06 16:44:44.288 1239 1239 I dex2oat : /system/bin/dex2oat --zip-fd=11 --zip-location=/system/vendor/operator/app/E163_MMPlug/E163_MMPlug.apk --oat-fd=12 --oat-location=/data/dalvik-cache/arm/system@vendor@operator@app@E163_MMPlug@E163_MMPlug.apk@classes.dex --instruction-set=arm --instruction-set-features=default --runtime-arg -Xms64m --runtime-arg -Xmx512m --swap-fd=13

Solution：在Android.mk中设定LOCAL_MULTILIB :=32，则预编译时会提取该apk的32bit的odex

3、开机重新提取odex既有arm又有arm64的apk：

05-06 16:43:41.732 1200 1200 I dex2oat : /system/bin/dex2oat --zip-fd=11 --zip-location=/system/app/webview/webview.apk --oat-fd=12 --oat-location=/data/dalvik-cache/arm/system@app@webview@webview.apk@classes.dex --instruction-set=arm --instruction-set-features=default --runtime-arg -Xms64m --runtime-arg -Xmx512m --swap-fd=13
05-06 16:43:44.385 1203 1203 I dex2oat : /system/bin/dex2oat --zip-fd=11 --zip-location=/system/app/webview/webview.apk --oat-fd=12 --oat-location=/data/dalvik-cache/arm64/system@app@webview@webview.apk@classes.dex --instruction-set=arm64 --instruction-set-features=default --runtime-arg -Xms64m --runtime-arg -Xmx512m --swap-fd=13

Solution：在Android.mk中设定LOCAL_MULTILIB :=both，则预编译时会提取该apk的32bit和64bit的odex

问题分析到这的时候，我们发现一个现象，成功被带偏了，就是如果强制断电（拔电池），就会比较容易复现问题，实际上对于低概率的问题，还是尽量不要只往一个方向思考，期间研究了许多google对于断电系统的一些保护推测是开机时异常断电，有几率造成file corruption (如果是某app的oat file corruption，会造成app无法启动)
了解到Google设计了一套方法，只要上一次是异常断电，下一次开机就”全部重建”ART optimization files(*.oat)，因此
1. 会显示Application is starting…
2. 全部重建oat file，所以开机时间会延长
Emmmm，看起来好像找到了问题的方向。当然，后面这个推测被否了，因为发现不异常断电也能复现出问题。再仔细分析log，发现如下可疑点：
检查log发现systemserver都没有初始化好，下面log没走：

SystemServer: PerfMgr state notifier
SystemServer: HDMI Manager Service
SystemServer: Making services ready

//发现这里This kernel does not have HDMI audio support，
05-14 09:00:11.812 805 805 D SettingsProvider: lookupValue table system cache.fullyMatchesDisk() volume_music_hdmi
05-14 09:00:11.812 805 805 V SettingsProvider: call(system:volume_music_hdmi) for 0
05-14 09:00:11.921 805 805 W WiredAccessoryManager: This kernel does not have HDMI audio support

//即需要确认客户HDMI feature是否disable掉了
1196 if (!disableNonCoreServices && SystemProperties.get("ro.mtk_hdmi_support").equals("1")) {
1197 try {
1198 Slog.i(TAG, "HDMI Manager Service");
1199 hdmiManager = new MtkHdmiManagerService(context);
1200 ServiceManager.addService(Context.HDMI_SERVICE,
1201 hdmiManager.asBinder());
1202 } catch (Throwable e) {
1203 Slog.e(TAG, "Failure starting MtkHdmiManager", e);
1204 }
1205 }

然后这个和开不了机没有特别的关系。
从log看：

05-14 09:00:09.691 484 484 I sn : Retry 2
05-14 09:00:12.167 805 805 I SystemServer: PerfMgr state notifier
05-14 09:04:39.720 484 484 I sn : Retry 29
05-14 09:16:19.786 484 484 I sn : Retry 99

这之后就没有sn的log了。
但是一直到下边的时间点，还没看到launcher起来：

05-14 10:15:33.784

开机log中，system server跑到9点多一点就没log了，只有surface这边的log在跑。判断是卡到SystemServer初始化某个地方从而导致后面一直在跑“Android 正在启动”而得不到释放，因为跑到perfService这里还没有走到systemserver后面的watchdog，也不会走到重启。
//目前可以看到PerfMgr state notifier后面，HDMI Manager Service之前，确定与disable HDMI无关，
查看code:

1179 perfServiceMgr = new PerfServiceManager(context);
//1179这行函数里面的log是有打出来的
     //05-14 09:00:12.171 805 805 D PerfServiceManager: [PerfService] Created and started PerfService thread 
     
1181 IPerfService perfService = null;
1182 perfService = new PerfServiceImpl(context, perfServiceMgr);
1183
1184 Slog.d("perfservice", "perfService=" + perfService);
//1184这行log没有打出来，那么只有卡到PerfServiceImpl这个函数里面，而这个函数只是在处理广播 
     //mContext.registerReceiver(new PerfServiceBroadcastReceiver(), broadcastFilter);
     //那么有可能是ActivityManagerService.java中的registerReceiver（）函数中没有拿到这个锁： synchronized(this)

所以接下来是需要复现去抓SystemServer的backtrace来分析了，按照以下步骤打systemServer的backtrace：
1.先清除data/anr下文件
2.使用adb shell ps查看system_server的pid
>>adb shell
>>ps | grep system_server //过滤查询 system_server信息
3.使用adb shell kill -16 $(上面获得的pid)
>>kill -16 pid
4.重复2-3此上面步骤，多获取几次backtrace
5.以上backtrace会默认保存在data/anr下
找到问题原因和抓到trace，问题渐渐明朗：
1.总结：
通过抓取的call back分析肯定是上层system_server死锁导致。
2.原因：
具体原因就是AMS中的锁和POMS中的锁相互被占用导致，但是正常应该不会卡在这里。
3.怀疑点：
根据之前解这类开机卡住的经验，比较大的可能是哪里code修改或底层sensor配置不对导致，需要同步检查相关修改和配置。
4.发现一个必现路径：

“将手机时间修改为第一次出现正在启动消息框之后的3天，开机必现正在启动，更容易复现卡住问题”

原因：修改时间，必走这里所以会走正在启动：

4884 if (timeSinceLast > interval) { //interval定义的变量是3天：DEFAULT_MANDATORY_FSTRIM_INTERVAL = 3 * DateUtils.DAY_IN_MILLIS;
4885 doTrim = true; //时间改成超过3天，这里doTrim就置为true,就会走到下面 if (doTrim) showBootMessage() 从而必现“Android 正在启动“
4886 Slog.w(TAG, "No disk maintenance in " + timeSinceLast
4887 + "; running immediately");
4888 }

由于AMS、PMS和WMS在锁上存在竞争，导致死锁发生。想到的解决方法是需要解开循环等待的问题，需要将PowerManagerService中setScreenBrightnessOverrideFromWindowManagerInternal方法里面的synchronized(mLock)修改成非阻塞型的，这样需要将PowerManagerService中的mLock替换成显式锁，如java.util.Lock,然后用mLock.tryLock()和unLock()来对代码进行加锁和解锁。使用synchronized(obj)是内置锁，这样无法精细的控制锁。显式锁就是使用java.util.Lock或者其他的锁对象，然后采用非阻塞式锁.

Lock lock=new ReentrantLock(); 
if(lock.tryLock()) {
//获得锁，执行具体任务 
lock.unlock(); 
}
//其他地方可以使用阻塞锁：
lock.lock(); 
try{ 
//具体任务 
}finally{ 
lock.unlock(); 
}

总结：
Main thread拿PowerManagerService的mLock这把锁去抢AMS的锁，而：
android.display线程拿AMS的锁，去抢PowerManagerService的锁，两个线程发生死锁。怀疑是google的代码原生就存在这种可能性。
关键callStack如下

DALVIK THREADS (60):
"main" prio=5 tid=1 Blocked
| group="main" sCount=1 dsCount=0 obj=0x740befb8 self=0x7fa0caf800
| sysTid=798 nice=-2 cgrp=default sched=0/0 handle=0x7fa4e05eb0
| state=S schedstat=( 8332874739 193417372 11682 ) utm=589 stm=244 core=0 HZ=100
| stack=0x7fef078000-0x7fef07a000 stackSize=8MB
| held mutexes=
at com.android.server.am.ActivityManagerService.registerReceiver(ActivityManagerService.java:16635)
- waiting to lock <0x39099865> (a com.android.server.am.ActivityManagerService) held by thread 22 //竞争AMS的锁
at android.app.ContextImpl.registerReceiverInternal(ContextImpl.java:1776)
at android.app.ContextImpl.registerReceiver(ContextImpl.java:1744)
at android.app.ContextImpl.registerReceiver(ContextImpl.java:1738)
at com.android.server.display.DisplayPowerController.(DisplayPowerController.java:416)
at com.android.server.display.DisplayManagerService$LocalService.initPowerManagement(DisplayManagerService.java:1888)
- locked <0x38a2d93a> (a com.android.server.display.DisplayManagerService$SyncRoot)
at com.android.server.power.PowerManagerService.systemReady(PowerManagerService.java:605)
- locked <0x386259eb> (a java.lang.Object) //PowerMs的锁
at com.android.server.SystemServer.startOtherServices(SystemServer.java:1281)
at com.android.server.SystemServer.run(SystemServer.java:333)
at com.android.server.SystemServer.main(SystemServer.java:234)
at java.lang.reflect.Method.invoke!(Native method)
at java.lang.reflect.Method.invoke(Method.java:372)
at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:959)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:754)

另一个线程：
"android.display" prio=5 tid=22 Blocked
| group="main" sCount=1 dsCount=0 obj=0x12e91f20 self=0x7fa0cc2800
| sysTid=825 nice=-4 cgrp=default sched=0/0 handle=0x7f8d888000
| state=S schedstat=( 87739463 31037617 214 ) utm=7 stm=1 core=1 HZ=100
| stack=0x7f8d786000-0x7f8d788000 stackSize=1036KB
| held mutexes=
at com.android.server.power.PowerManagerService.setScreenBrightnessOverrideFromWindowManagerInternal(PowerManagerService.java:2873)
- waiting to lock <0x386259eb> (a java.lang.Object) held by thread 1 //竞争PowerMs的锁
at com.android.server.power.PowerManagerService.access$7300(PowerManagerService.java:100)
at com.android.server.power.PowerManagerService$LocalService.setScreenBrightnessOverrideFromWindowManager(PowerManagerService.java:3987)
at com.android.server.wm.WindowManagerService.performLayoutAndPlaceSurfacesLockedInner(WindowManagerService.java:10961)
at com.android.server.wm.WindowManagerService.performLayoutAndPlaceSurfacesLockedLoop(WindowManagerService.java:9573)
at com.android.server.wm.WindowManagerService.performLayoutAndPlaceSurfacesLocked(WindowManagerService.java:9515)
at com.android.server.wm.WindowManagerService.setNewConfiguration(WindowManagerService.java:4441)
- locked <0x22675592> (a java.util.HashMap)
at com.android.server.am.ActivityManagerService.updateConfigurationLocked(ActivityManagerService.java:17941)
at com.android.server.am.ActivityManagerService.updateConfiguration(ActivityManagerService.java:17801)
- locked <0x39099865> (a com.android.server.am.ActivityManagerService) //持有AMS的锁
at com.android.server.wm.WindowManagerService.sendNewConfiguration(WindowManagerService.java:7762)
at com.android.server.wm.WindowManagerService.updateRotationUnchecked(WindowManagerService.java:7120)
at com.android.server.wm.WindowManagerService.updateRotation(WindowManagerService.java:7070)
at com.android.internal.policy.impl.PhoneWindowManager.updateRotation(PhoneWindowManager.java:6383)
at com.android.internal.policy.impl.PhoneWindowManager.enableScreenAfterBoot(PhoneWindowManager.java:6354)
at com.android.server.wm.WindowManagerService.performEnableScreen(WindowManagerService.java:6515)
at com.android.server.wm.WindowManagerService$H.handleMessage(WindowManagerService.java:8663)
at android.os.Handler.dispatchMessage(Handler.java:111)
at android.os.Looper.loop(Looper.java:194)
at android.os.HandlerThread.run(HandlerThread.java:61)
at com.android.server.ServiceThread.run(ServiceThread.java:46)

tid=1和tid=22两个死锁线程
详细请看抓取的call back如下tid=1和tid=22两个线程，从中可以看出：

"main" prio=5 tid=1 Blocked

Void systemReady() { // PowerManagerService, tid = 1
Synchronized(mLock) { // java.lang.Object, may be held by this thread
……
registerReceiver(…) {
ams.registerReceiver(…) { // ActivityManagerService
……
synchronized(this) // com.android.server.am.ActivityManagerService, waiting!!!!, 
……
}
}
…
}
}

"android.display" prio=5 tid=22 Blocked

Void updateConfiguration(…) { //ActivityManagerService, tid = 22
Synchronized(this) { // com.android.server.am.ActivityManagerService, may be held by this thread
……
pms. setScreenBrightnessOverrideFromWindowManagerInternal() {
synchronized(mLock) { // java.lang.Object, may be held by this thread, waiting!!!!
……
}
}
...
}
}

自此，问题分析完成，考虑到修改锁类型的方案作用在设置屏幕亮度的地方，防止导致屏幕在某种情形下无法点亮等更严重的情况。在量产阶段暂时先采用了保守的解法：去掉3天更新doTrim的功能。
实际提供的解锁方案应当是可行，是解决问题出现的根本原因。

海苔一笑倾城

关注

1
点赞
踩
1

收藏

觉得还不错? 一键收藏
0
评论
一个AMS、PMS、WMS竞争锁引起死锁无法开启问题的分析过程

问题：在工厂段出现，一直提示“android 正在启动”，长按开机键恢复。由于产线生产机器都是按K计算，所以概率问题会放大，此问题大约1000台机器会出现10台左右的卡在android正在启动，由于到了量产阶段，问题紧急，无奈我还被紧急派去生产车间解决问题，最快的航班经济舱已满，生平第一次坐了一次头等舱（- -！）首先就是要复现问题，抓到问题log，编译ENG版本，打开相关log，开始复现：P...
复制链接

扫一扫