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

问题：在工厂段出现，一直提示“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=1305-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=1305-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=1305-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=1305-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=1305-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=1305-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=1305-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=1305-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 notifierSystemServer: HDMI Manager ServiceSystemServer: 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_hdmi05-14 09:00:11.812 805 805 V SettingsProvider: call(system:volume_music_hdmi) for 005-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 205-14 09:00:12.167 805 805 I SystemServer: PerfMgr state notifier05-14 09:04:39.720 484 484 I sn : Retry 2905-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);11831184 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 " + timeSinceLast4887 + "; 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 BlockedVoid systemReady() { // PowerManagerService, tid = 1Synchronized(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 BlockedVoid updateConfiguration(…) { //ActivityManagerService, tid = 22Synchronized(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的功能。
实际提供的解锁方案应当是可行，是解决问题出现的根本原因。

更多相关文章

随机推荐