2020-05-15
2020-05-15 本文已影响0人
SongSea
重置应用偏好，AMS和PMS deadlock,导致手机重启
在Android Q中，今天遇到个死机重启问题。在Setting中reset app preference会卡死，过段时间，手机重启。抓了下log看看，发现是PMS和AMS deadlock，导致手机重启。
从下面的log可以看出，android.fg、main、ActivityManager 阻塞了。
05-09 10:13:03.736 1146 1170 W Watchdog: *** WATCHDOG KILLING SYSTEM PROCESS: Blocked in handler on foreground thread (android.fg), Blocked in handler on main thread (main), Blocked in handler on ActivityManager (ActivityManager)
05-09 10:13:03.742 1146 1170 W Watchdog: android.fg annotated stack trace:
05-09 10:13:03.743 1146 1170 W Watchdog: at com.android.server.am.ActivityManagerService.broadcastIntent(ActivityManagerService.java:15799)
05-09 10:13:03.744 1146 1170 W Watchdog: - waiting to lock <0x0235fe7d> (a com.android.server.am.ActivityManagerService)
05-09 10:13:03.745 1146 1170 W Watchdog: at android.app.ContextImpl.sendBroadcastAsUser(ContextImpl.java:1264)
05-09 10:13:03.746 1146 1170 W Watchdog: at android.app.ContextImpl.sendBroadcastAsUser(ContextImpl.java:1236)
05-09 10:13:03.747 1146 1170 W Watchdog: at com.android.server.usb.UsbPortManager.lambda$sendPortChangedBroadcastLocked$0$UsbPortManager(UsbPortManager.java:1016)
05-09 10:13:03.748 1146 1170 W Watchdog: at com.android.server.usb.-$$Lambda$UsbPortManager$FUqGOOupcl6RrRkZBk-BnrRQyPI.run(Unknown Source:4)
05-09 10:13:03.749 1146 1170 W Watchdog: at android.os.Handler.handleCallback(Handler.java:883)
05-09 10:13:03.749 1146 1170 W Watchdog: at android.os.Handler.dispatchMessage(Handler.java:100)
05-09 10:13:03.750 1146 1170 W Watchdog: at android.os.Looper.loop(Looper.java:214)
05-09 10:13:03.750 1146 1170 W Watchdog: at android.os.HandlerThread.run(HandlerThread.java:67)
05-09 10:13:03.751 1146 1170 W Watchdog: at com.android.server.ServiceThread.run(ServiceThread.java:44)
05-09 10:13:03.754 1146 1170 W Watchdog: main annotated stack trace:
05-09 10:13:03.755 1146 1170 W Watchdog: at com.android.server.am.ActivityManagerService.broadcastIntent(ActivityManagerService.java:15799)
05-09 10:13:03.756 1146 1170 W Watchdog: - waiting to lock <0x0235fe7d> (a com.android.server.am.ActivityManagerService)
05-09 10:13:03.756 1146 1170 W Watchdog: at android.app.ContextImpl.sendBroadcastAsUser(ContextImpl.java:1225)
05-09 10:13:03.757 1146 1170 W Watchdog: at com.android.server.BatteryService$7.run(BatteryService.java:617)
05-09 10:13:03.757 1146 1170 W Watchdog: at android.os.Handler.handleCallback(Handler.java:883)
05-09 10:13:03.758 1146 1170 W Watchdog: at android.os.Handler.dispatchMessage(Handler.java:100)
05-09 10:13:03.758 1146 1170 W Watchdog: at android.os.Looper.loop(Looper.java:214)
05-09 10:13:03.759 1146 1170 W Watchdog: at com.android.server.SystemServer.run(SystemServer.java:570)
05-09 10:13:03.759 1146 1170 W Watchdog: at com.android.server.SystemServer.main(SystemServer.java:364)
05-09 10:13:03.760 1146 1170 W Watchdog: at java.lang.reflect.Method.invoke(Native Method)
05-09 10:13:03.761 1146 1170 W Watchdog: at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:492)
05-09 10:13:03.761 1146 1170 W Watchdog: at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:958)
05-09 10:13:03.763 1146 1170 W Watchdog: ActivityManager annotated stack trace:
05-09 10:13:03.764 1146 1170 W Watchdog: at com.android.server.am.BroadcastQueue.processNextBroadcast(BroadcastQueue.java:948)
05-09 10:13:03.765 1146 1170 W Watchdog: - waiting to lock <0x0235fe7d> (a com.android.server.am.ActivityManagerService)
05-09 10:13:03.766 1146 1170 W Watchdog: at com.android.server.am.BroadcastQueue$BroadcastHandler.handleMessage(BroadcastQueue.java:186)
05-09 10:13:03.766 1146 1170 W Watchdog: at android.os.Handler.dispatchMessage(Handler.java:107)
05-09 10:13:03.766 1146 1170 W Watchdog: at android.os.Looper.loop(Looper.java:214)
05-09 10:13:03.767 1146 1170 W Watchdog: at android.os.HandlerThread.run(HandlerThread.java:67)
05-09 10:13:03.767 1146 1170 W Watchdog: at com.android.server.ServiceThread.run(ServiceThread.java:44)
05-09 10:13:03.768 1146 1170 W Watchdog: *** GOODBYE!
05-09 10:13:03.769 1146 1170 I Process : Sending signal. PID: 1146 SIG: 9
之后取出dropbox，看了下log，大致信息如下。
Process: system_server
Subject: Blocked in monitor com.android.server.am.ActivityManagerService on foreground thread (android.fg), Blocked in handler on main thread (main), Blocked in handler on ActivityManager (ActivityManager)
接下来搜索android.fg,log信息如下，线程状态是Blocked状态。根据 - waiting to lock <0x0cdd7d88> (a com.android.server.am.ActivityManagerService) held by thread 34这句log可以知道thread 34目前持有ActivityManagerService.this这个对象的锁。
"android.fg" prio=5 tid=11 Blocked
| group="main" sCount=1 dsCount=0 flags=1 obj=0x13343b80 self=0x6f792fe800
| sysTid=1169 nice=0 cgrp=default sched=0/0 handle=0x6f26b09d50
| state=S schedstat=( 19549844370 13678424454 84937 ) utm=1554 stm=400 core=4 HZ=100
| stack=0x6f26a07000-0x6f26a09000 stackSize=1039KB
| held mutexes=
at com.android.server.am.ActivityManagerService.monitor(ActivityManagerService.java:17816)
- waiting to lock <0x0cdd7d88> (a com.android.server.am.ActivityManagerService) held by thread 34
at com.android.server.Watchdog$HandlerChecker.run(Watchdog.java:260)
at android.os.Handler.handleCallback(Handler.java:883)
at android.os.Handler.dispatchMessage(Handler.java:100)
at android.os.Looper.loop(Looper.java:214)
at android.os.HandlerThread.run(HandlerThread.java:67)
at com.android.server.ServiceThread.run(ServiceThread.java:44)
接下来先看下另外两个线程main和ActivityManager。接下来搜索main，可以看到log信息如下，可以看到线程状态也是Blocked状态，根据 waiting to lock <0x0dfda30d> (a android.util.ArrayMap) held by thread 10
at com.android.server.pm.PackageManagerService.resolveContentProviderInternal(PackageManagerService.java:9045)这个线程在ackageManagerService.java中进入mPackages为锁的同步代码块时进入了阻塞状态。
PackageManagerService.java中代码
private ProviderInfo resolveContentProviderInternal(String name, int flags, int userId) { if (!sUserManager.exists(userId)) return null; flags = updateFlagsForComponent(flags, userId, name); final int callingUid = Binder.getCallingUid(); final ProviderInfo providerInfo = mComponentResolver.queryProvider(name, flags, userId); if (providerInfo == null) { return null; } if (!mSettings.isEnabledAndMatchLPr(providerInfo, flags, userId)) { return null; } synchronized (mPackages) { final PackageSetting ps = mSettings.mPackages.get(providerInfo.packageName); final ComponentName component = new ComponentName(providerInfo.packageName, providerInfo.name); if (filterAppAccessLPr(ps, callingUid, component, TYPE_PROVIDER, userId)) { return null; } return providerInfo; } }
Log信息
"main" prio=5 tid=1 Blocked
| group="main" sCount=1 dsCount=0 flags=1 obj=0x72831908 self=0x700f5c5c00
| sysTid=1152 nice=-2 cgrp=default sched=0/0 handle=0x7010b31ed0
| state=S schedstat=( 18586425702 3677321603 20776 ) utm=1405 stm=452 core=2 HZ=100
| stack=0x7fe8ddc000-0x7fe8dde000 stackSize=8192KB
| held mutexes=
at com.android.server.pm.ComponentResolver.queryProvider(ComponentResolver.java:289)
- waiting to lock <0x0dfda30d> (a android.util.ArrayMap) held by thread 10
at com.android.server.pm.PackageManagerService.resolveContentProviderInternal(PackageManagerService.java:9045)
at com.android.server.pm.PackageManagerService.resolveContentProvider(PackageManagerService.java:9038)
at com.android.server.am.ActivityManagerService.checkContentProviderAccess(ActivityManagerService.java:6598)
at com.android.server.am.ActivityManagerService$LocalService.checkContentProviderAccess(ActivityManagerService.java:18035)
at com.android.server.content.ContentService.notifyChange(ContentService.java:408)
at android.content.ContentResolver.notifyChange(ContentResolver.java:2387)
at com.android.providers.settings.SettingsProvider$SettingsRegistry$MyHandler.handleMessage(SettingsProvider.java:3244)
at android.os.Handler.dispatchMessage(Handler.java:107)
at android.os.Looper.loop(Looper.java:214)
at com.android.server.SystemServer.run(SystemServer.java:570)
at com.android.server.SystemServer.main(SystemServer.java:364)
at java.lang.reflect.Method.invoke(Native method)
at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:492)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:958)
接下来搜索"ActivityManager"，可以搜索到下面log。可以看到线程状态是Blocked状态，根据这行log waiting to lock <0x0cdd7d88> (a com.android.server.am.ActivityManagerService) held by thread 34。我们知道ActivityManager也阻塞在thread 34.
"ActivityManager" prio=5 tid=20 Blocked
| group="main" sCount=1 dsCount=0 flags=1 obj=0x133475e0 self=0x6f201f3c00
| sysTid=1179 nice=-2 cgrp=default sched=0/0 handle=0x6f1cc7dd50
| state=S schedstat=( 3150670929 981176628 9232 ) utm=222 stm=92 core=1 HZ=100
| stack=0x6f1cb7b000-0x6f1cb7d000 stackSize=1039KB
| held mutexes=
at com.android.server.am.BroadcastQueue.processNextBroadcast(BroadcastQueue.java:948)
- waiting to lock <0x0cdd7d88> (a com.android.server.am.ActivityManagerService) held by thread 34
at com.android.server.am.BroadcastQueue$BroadcastHandler.handleMessage(BroadcastQueue.java:186)
at android.os.Handler.dispatchMessage(Handler.java:107)
at android.os.Looper.loop(Looper.java:214)
at android.os.HandlerThread.run(HandlerThread.java:67)
at com.android.server.ServiceThread.run(ServiceThread.java:44)
接下来我们搜索一下thread 34的log。可以看到thread 34也是Blocked状态。根据waiting to lock <0x0dfda30d> (a android.util.ArrayMap) held by thread 10这行log，我们知道thread 34被thread 10阻塞了。
"PackageManager" prio=5 tid=34 Blocked
| group="main" sCount=1 dsCount=0 flags=1 obj=0x1334b238 self=0x6f201d8000
| sysTid=1197 nice=-2 cgrp=default sched=0/0 handle=0x6f0dca1d50
| state=S schedstat=( 472019375 664779689 999 ) utm=28 stm=18 core=6 HZ=100
| stack=0x6f0db9f000-0x6f0dba1000 stackSize=1039KB
| held mutexes=
at com.android.server.pm.PackageManagerService.getInstantAppPackageName(PackageManagerService.java:7256)
- waiting to lock <0x0dfda30d> (a android.util.ArrayMap) held by thread 10
at com.android.server.pm.PackageManagerService.queryIntentReceiversInternal(PackageManagerService.java:8319)
at com.android.server.pm.PackageManagerService.queryIntentReceivers(PackageManagerService.java:8308)
at com.android.server.am.ActivityManagerService.collectReceiverComponents(ActivityManagerService.java:14883)
at com.android.server.am.ActivityManagerService.broadcastIntentLocked(ActivityManagerService.java:15535)
at com.android.server.am.ActivityManagerService.broadcastIntentLocked(ActivityManagerService.java:15042)
at com.android.server.am.ActivityManagerService.broadcastIntent(ActivityManagerService.java:15825)
- locked <0x0cdd7d88> (a com.android.server.am.ActivityManagerService)
at com.android.server.pm.PackageManagerService.lambda$postPreferredActivityChangedBroadcast$24(PackageManagerService.java:20440)
at com.android.server.pm.-$$Lambda$PackageManagerService$Yfnee_CTmno9dIMhv8Cxk-LIk7w.run(lambda:-1)
at android.os.Handler.handleCallback(Handler.java:883)
at android.os.Handler.dispatchMessage(Handler.java:100)
at android.os.Looper.loop(Looper.java:214)
at android.os.HandlerThread.run(HandlerThread.java:67)
at com.android.server.ServiceThread.run(ServiceThread.java:44)
接下来我们总结一下，“android.fg” thread 11被thread34 阻塞，thread 34被thread 10阻塞。”main“ thread 1被thread 10阻塞。"ActivityManager" thread 20 被thread 34阻塞，而thread 34又被thread 10阻塞。从中我们可以看到最终都是被thread 10阻塞。接下来我们看下thread 10的log。从这句log waiting to lock <0x0cdd7d88> (a com.android.server.am.ActivityManagerService) held by thread 34可以看出thread 10被thread 34阻塞，而thread 34又被thread 10阻塞。这很明显是deadlock问题，PMS和AMS 死锁了。从thread 10的log中，我们可以知道这个线程是执行reset app preference方法的线程。所以我们从这里开始分析。com.android.server.pm.PackageManagerService.resetApplicationPreferences(PackageManagerService.java:20672)
"Binder:1152_2" prio=5 tid=10 Blocked
| group="main" sCount=1 dsCount=0 flags=1 obj=0x133439f8 self=0x6f7de2e000
| sysTid=1166 nice=0 cgrp=default sched=0/0 handle=0x6f28b57d50
| state=S schedstat=( 7163637231 3095463661 25055 ) utm=517 stm=198 core=0 HZ=100
| stack=0x6f28a61000-0x6f28a63000 stackSize=991KB
| held mutexes=
at com.android.server.am.ActivityManagerService.getContentProviderImpl(ActivityManagerService.java:6841)
- waiting to lock <0x0cdd7d88> (a com.android.server.am.ActivityManagerService) held by thread 34
at com.android.server.am.ActivityManagerService.getContentProviderExternalUnchecked(ActivityManagerService.java:7392)
at com.android.server.am.ActivityManagerService.getProviderMimeType(ActivityManagerService.java:7812)
at android.content.ContentResolver.getType(ContentResolver.java:746)
at android.content.Intent.resolveType(Intent.java:7592)
at android.content.Intent.resolveTypeIfNeeded(Intent.java:7614)
at com.android.server.pm.PackageManagerService$PackageManagerInternalImpl.queryIntentActivities(PackageManagerService.java:24778)
at com.android.server.pm.Settings.applyDefaultPreferredActivityLPw(Settings.java:3349)
at com.android.server.pm.Settings.applyDefaultPreferredActivityLPw(Settings.java:3310)
at com.android.server.pm.Settings.readDefaultPreferredActivitiesLPw(Settings.java:3466)
at com.android.server.pm.Settings.applyDefaultPreferredAppsLPw(Settings.java:3212)
at com.android.server.pm.PackageManagerService.resetApplicationPreferences(PackageManagerService.java:20672)
- locked <0x0dfda30d> (a android.util.ArrayMap)
at android.content.pm.IPackageManager$Stub.onTransact(IPackageManager.java:3059)
at com.android.server.pm.PackageManagerService.onTransact(PackageManagerService.java:4084)
at android.os.Binder.execTransactInternal(Binder.java:1021)
at android.os.Binder.execTransact(Binder.java:994)
打开PackageManagerService.java的代码看下，没什么有用的信息，接下来我们看下Settings.java文件。从这个方法中下面黑体代码可以知道，这个是"etc/preferred-apps"目录下有文件的话才会执行到下面的死锁代码
File preferredDir = new File(Environment.getRootDirectory(), "etc/preferred-apps");
而"etc/preferred-apps"下面主要是Google GMS应用内置的配置文件。也就是说这个目录下面没有文件的话，那就不会死锁。换个说法就是这个死锁是Google搞出来的。
void applyDefaultPreferredAppsLPw(int userId) {
// First pull data from any pre-installed apps.
final PackageManagerInternal pmInternal =
LocalServices.getService(PackageManagerInternal.class);
for (PackageSetting ps : mPackages.values()) {
if ((ps.pkgFlags&ApplicationInfo.FLAG_SYSTEM) != 0 && ps.pkg != null
&& ps.pkg.preferredActivityFilters != null) {
ArrayList<PackageParser.ActivityIntentInfo> intents
= ps.pkg.preferredActivityFilters;
for (int i=0; i<intents.size(); i++) {
PackageParser.ActivityIntentInfo aii = intents.get(i);
applyDefaultPreferredActivityLPw(pmInternal, aii, new ComponentName(
ps.name, aii.activity.className), userId);
}
}
}
// Read preferred apps from .../etc/preferred-apps directory.
File preferredDir = new File(Environment.getRootDirectory(), "etc/preferred-apps");
if (!preferredDir.exists() || !preferredDir.isDirectory()) {
return;
}
if (!preferredDir.canRead()) {
Slog.w(TAG, "Directory " + preferredDir + " cannot be read");
return;
}
// Iterate over the files in the directory and scan .xml files
for (File f : preferredDir.listFiles()) {
if (!f.getPath().endsWith(".xml")) {
Slog.i(TAG, "Non-xml file " + f + " in " + preferredDir + " directory, ignoring");
continue;
}
if (!f.canRead()) {
Slog.w(TAG, "Preferred apps file " + f + " cannot be read");
continue;
}
if (PackageManagerService.DEBUG_PREFERRED) Log.d(TAG, "Reading default preferred " + f);
InputStream str = null;
try {
str = new BufferedInputStream(new FileInputStream(f));
XmlPullParser parser = Xml.newPullParser();
parser.setInput(str, null);
int type;
while ((type = parser.next()) != XmlPullParser.START_TAG
&& type != XmlPullParser.END_DOCUMENT) {
;
}
if (type != XmlPullParser.START_TAG) {
Slog.w(TAG, "Preferred apps file " + f + " does not have start tag");
continue;
}
if (!"preferred-activities".equals(parser.getName())) {
Slog.w(TAG, "Preferred apps file " + f
+ " does not start with 'preferred-activities'");
continue;
}
readDefaultPreferredActivitiesLPw(parser, userId);
} catch (XmlPullParserException e) {
Slog.w(TAG, "Error reading apps file " + f, e);
} catch (IOException e) {
Slog.w(TAG, "Error reading apps file " + f, e);
} finally {
if (str != null) {
try {
str.close();
} catch (IOException e) {
}
}
}
}
}
接下来我们进入这里看一下代码
at com.android.server.pm.PackageManagerService$PackageManagerInternalImpl.queryIntentActivities(PackageManagerService.java:24778)
从上面的堆栈信息我们可以知道死锁发生在下面这个方法的intent.resolveTypeIfNeeded(mContext.getContentResolver())方法内，这个方法通过调用activity manager service来获取到它的type。在获取com.android.server.am.ActivityManagerService.this时阻塞了，发生了死锁。
public List<ResolveInfo> queryIntentActivities(
Intent intent, int flags, int filterCallingUid, int userId) {
final String resolvedType = intent.resolveTypeIfNeeded(mContext.getContentResolver());
return PackageManagerService.this
.queryIntentActivitiesInternal(intent, resolvedType, flags, filterCallingUid,
userId, false /*resolveForStart*/, true /*allowDynamicSplits*/);
}
在这里我们可以避免调用ActiviytManagerService来查询type，可以通过intent.getType()来直接获取type，来避免这个死锁的发生。当然如果重要的话，需用通过preferred-activity 声明来定义 mime 类型。从Settings.java的3310行代码可知，这段代码没有设置intent type，现在intent的type为null。
if (doScheme) {
Uri.Builder builder = new Uri.Builder();
builder.scheme(scheme);
Intent finalIntent = new Intent(intent);
finalIntent.setData(builder.build());
applyDefaultPreferredActivityLPw(pmInternal, finalIntent, flags, cn,
scheme, null, null, null, userId);
}
所以最后的修改方法就是避免调用intent.resolveTypeIfNeeded()方法，重定义一个queryIntentActivities（）方法，通过intent.getType()来获取mime type。patch如下。
From 3fa88533316995c52d29a14df600e477f83c04d9 Mon Sep 17 00:00:00 2001
From: Patrick Baumann <patb@google.com>
Date: Mon, 18 Nov 2019 13:43:11 -0800
Subject: [PATCH] DO NOT MERGE Avoids deadlock when applying preferred activities
Prior to this change, we were resolving the mime type of a given intent
while holding the package lock. With this change, we instead rely on the
preferred-activity declaration to define the mime type if it's
important, removing need for an activity manager service call and the
potential for deadlock.
Fixes: 143105100
Test: Manual; sideload to /system/etc/preferred-apps/ and reset app preferences
Change-Id: Ia87b7ecbd7987ef654fb0fc2bda942cd6a9c00a7
---
diff --git a/core/java/android/content/pm/PackageManagerInternal.java b/core/java/android/content/pm/PackageManagerInternal.java
index 28d9152..30a3bd4 100644
--- a/core/java/android/content/pm/PackageManagerInternal.java
+++ b/core/java/android/content/pm/PackageManagerInternal.java
@@ -415,6 +415,17 @@
@ResolveInfoFlags int flags, int filterCallingUid, int userId);
/**
+ * Retrieve all activities that can be performed for the given intent.
+ * @param filterCallingUid The results will be filtered in the context of this UID instead
+ * of the calling UID.
+ * @see PackageManager#queryIntentActivities(Intent, int)
+ */
+ public abstract List<ResolveInfo> queryIntentActivities(
+ Intent intent, @Nullable String resolvedType, @ResolveInfoFlags int flags,
+ int filterCallingUid, int userId);
+
+
+ /**
* Retrieve all services that can be performed for the given intent.
* @see PackageManager#queryIntentServices(Intent, int)
*/
diff --git a/services/core/java/com/android/server/pm/PackageManagerService.java b/services/core/java/com/android/server/pm/PackageManagerService.java
index d7d7345..54051ba 100644
--- a/services/core/java/com/android/server/pm/PackageManagerService.java
+++ b/services/core/java/com/android/server/pm/PackageManagerService.java
@@ -24520,6 +24520,12 @@
public List<ResolveInfo> queryIntentActivities(
Intent intent, int flags, int filterCallingUid, int userId) {
final String resolvedType = intent.resolveTypeIfNeeded(mContext.getContentResolver());
+ return queryIntentActivities(intent, resolvedType, flags, filterCallingUid, userId);
+ }
+
+ @Override
+ public List<ResolveInfo> queryIntentActivities(
+ Intent intent, String resolvedType, int flags, int filterCallingUid, int userId) {
return PackageManagerService.this
.queryIntentActivitiesInternal(intent, resolvedType, flags, filterCallingUid,
userId, false /*resolveForStart*/, true /*allowDynamicSplits*/);
diff --git a/services/core/java/com/android/server/pm/Settings.java b/services/core/java/com/android/server/pm/Settings.java
index 3bc2236..4ecfbfe 100644
--- a/services/core/java/com/android/server/pm/Settings.java
+++ b/services/core/java/com/android/server/pm/Settings.java
@@ -3337,7 +3337,8 @@
int flags, ComponentName cn, String scheme, PatternMatcher ssp,
IntentFilter.AuthorityEntry auth, PatternMatcher path, int userId) {
final List<ResolveInfo> ri =
- pmInternal.queryIntentActivities(intent, flags, Binder.getCallingUid(), 0);
+ pmInternal.queryIntentActivities(
+ intent, intent.getType(), flags, Binder.getCallingUid(), 0);
if (PackageManagerService.DEBUG_PREFERRED) {
Log.d(TAG, "Queried " + intent + " results: " + ri);
}
