Hopefully fix issue #25153459: Sandboxed_process1 thrashing
There is a race where if you unbind to a service before its
process has come up, we would leave the service record active
and keep it running. Fix this by checking the service state
after its process up and proceed to bring it down if it is no
longer needed.
Also added a similar check when restarting a service, just in
case there are other ways we can get into this situation.
And while I am at it, I tweaked the broadcast queue dump output
a bit to hopefully make it a lot easier to figure out how long
it is taking to process broadcasts.
Change-Id: I46b98f1fe394ab8039ea4cc81fb5d3afb6391a31
diff --git a/services/core/java/com/android/server/am/ActiveServices.java b/services/core/java/com/android/server/am/ActiveServices.java
index b87e109..970f1b5 100755
--- a/services/core/java/com/android/server/am/ActiveServices.java
+++ b/services/core/java/com/android/server/am/ActiveServices.java
@@ -1314,6 +1314,15 @@
if (!mRestartingServices.contains(r)) {
return;
}
+ if (!isServiceNeeded(r, false, false)) {
+ // Paranoia: is this service actually needed? In theory a service that is not
+ // needed should never remain on the restart list. In practice... well, there
+ // have been bugs where this happens, and bad things happen because the process
+ // ends up just being cached, so quickly killed, then restarted again and again.
+ // Let's not let that happen.
+ Slog.wtf(TAG, "Restarting service that is not needed: " + r);
+ return;
+ }
try {
bringUpServiceLocked(r, r.intent.getIntent().getFlags(), r.createdFromFg, true);
} catch (TransactionTooLargeException e) {
@@ -2043,6 +2052,13 @@
mAm.mProcessStats);
realStartServiceLocked(sr, proc, sr.createdFromFg);
didSomething = true;
+ if (!isServiceNeeded(sr, false, false)) {
+ // We were waiting for this service to start, but it is actually no
+ // longer needed. This could happen because bringDownServiceIfNeeded
+ // won't bring down a service that is pending... so now the pending
+ // is done, so let's drop it.
+ bringDownServiceLocked(sr);
+ }
}
} catch (RemoteException e) {
Slog.w(TAG, "Exception in new application when starting service "
@@ -2055,7 +2071,7 @@
// be weird to bring up the process but arbitrarily not let the services
// run at this point just because their restart time hasn't come up.
if (mRestartingServices.size() > 0) {
- ServiceRecord sr = null;
+ ServiceRecord sr;
for (int i=0; i<mRestartingServices.size(); i++) {
sr = mRestartingServices.get(i);
if (proc != sr.isolatedProc && (proc.uid != sr.appInfo.uid
diff --git a/services/core/java/com/android/server/am/BroadcastQueue.java b/services/core/java/com/android/server/am/BroadcastQueue.java
index 960cbf1..6de8579 100644
--- a/services/core/java/com/android/server/am/BroadcastQueue.java
+++ b/services/core/java/com/android/server/am/BroadcastQueue.java
@@ -44,6 +44,7 @@
import android.os.UserHandle;
import android.util.EventLog;
import android.util.Slog;
+import android.util.TimeUtils;
import com.android.server.DeviceIdleController;
import static com.android.server.am.ActivityManagerDebugConfig.*;
@@ -1284,6 +1285,7 @@
final boolean dumpLocked(FileDescriptor fd, PrintWriter pw, String[] args,
int opti, boolean dumpAll, String dumpPackage, boolean needSep) {
+ SimpleDateFormat sdf = new SimpleDateFormat("yyyy-MM-dd HH:mm:ss");
if (mParallelBroadcasts.size() > 0 || mOrderedBroadcasts.size() > 0
|| mPendingBroadcast != null) {
boolean printed = false;
@@ -1301,7 +1303,7 @@
pw.println(" Active broadcasts [" + mQueueName + "]:");
}
pw.println(" Active Broadcast " + mQueueName + " #" + i + ":");
- br.dump(pw, " ");
+ br.dump(pw, " ", sdf);
}
printed = false;
needSep = true;
@@ -1319,7 +1321,7 @@
pw.println(" Active ordered broadcasts [" + mQueueName + "]:");
}
pw.println(" Active Ordered Broadcast " + mQueueName + " #" + i + ":");
- mOrderedBroadcasts.get(i).dump(pw, " ");
+ mOrderedBroadcasts.get(i).dump(pw, " ", sdf);
}
if (dumpPackage == null || (mPendingBroadcast != null
&& dumpPackage.equals(mPendingBroadcast.callerPackage))) {
@@ -1328,7 +1330,7 @@
}
pw.println(" Pending broadcast [" + mQueueName + "]:");
if (mPendingBroadcast != null) {
- mPendingBroadcast.dump(pw, " ");
+ mPendingBroadcast.dump(pw, " ", sdf);
} else {
pw.println(" (null)");
}
@@ -1366,7 +1368,7 @@
if (dumpAll) {
pw.print(" Historical Broadcast " + mQueueName + " #");
pw.print(i); pw.println(":");
- r.dump(pw, " ");
+ r.dump(pw, " ", sdf);
} else {
pw.print(" #"); pw.print(i); pw.print(": "); pw.println(r);
pw.print(" ");
@@ -1400,7 +1402,6 @@
}
// done skipping; dump the remainder of the ring. 'i' is still the ordinal within
// the overall broadcast history.
- SimpleDateFormat sdf = new SimpleDateFormat("yyyy-MM-dd HH:mm:ss");
do {
ringIndex = ringAdvance(ringIndex, -1, MAX_BROADCAST_SUMMARY_HISTORY);
Intent intent = mBroadcastSummaryHistory[ringIndex];
@@ -1422,9 +1423,19 @@
i++;
pw.print(" #"); pw.print(i); pw.print(": ");
pw.println(intent.toShortString(false, true, true, false));
- pw.print(" enq="); pw.print(sdf.format(new Date(mSummaryHistoryEnqueueTime[ringIndex])));
- pw.print(" disp="); pw.print(sdf.format(new Date(mSummaryHistoryDispatchTime[ringIndex])));
- pw.print(" fin="); pw.println(sdf.format(new Date(mSummaryHistoryFinishTime[ringIndex])));
+ pw.print(" ");
+ TimeUtils.formatDuration(mSummaryHistoryDispatchTime[ringIndex]
+ - mSummaryHistoryEnqueueTime[ringIndex], pw);
+ pw.print(" dispatch ");
+ TimeUtils.formatDuration(mSummaryHistoryFinishTime[ringIndex]
+ - mSummaryHistoryDispatchTime[ringIndex], pw);
+ pw.println(" finish");
+ pw.print(" enq=");
+ pw.print(sdf.format(new Date(mSummaryHistoryEnqueueTime[ringIndex])));
+ pw.print(" disp=");
+ pw.print(sdf.format(new Date(mSummaryHistoryDispatchTime[ringIndex])));
+ pw.print(" fin=");
+ pw.println(sdf.format(new Date(mSummaryHistoryFinishTime[ringIndex])));
Bundle bundle = intent.getExtras();
if (bundle != null) {
pw.print(" extras: "); pw.println(bundle.toString());
diff --git a/services/core/java/com/android/server/am/BroadcastRecord.java b/services/core/java/com/android/server/am/BroadcastRecord.java
index 1fbfd9f..b42bcff 100644
--- a/services/core/java/com/android/server/am/BroadcastRecord.java
+++ b/services/core/java/com/android/server/am/BroadcastRecord.java
@@ -32,6 +32,7 @@
import android.util.TimeUtils;
import java.io.PrintWriter;
+import java.text.SimpleDateFormat;
import java.util.Arrays;
import java.util.Date;
import java.util.List;
@@ -88,7 +89,7 @@
ComponentName curComponent; // the receiver class that is currently running.
ActivityInfo curReceiver; // info about the receiver that is currently running.
- void dump(PrintWriter pw, String prefix) {
+ void dump(PrintWriter pw, String prefix, SimpleDateFormat sdf) {
final long now = SystemClock.uptimeMillis();
pw.print(prefix); pw.print(this); pw.print(" to user "); pw.println(userId);
@@ -114,13 +115,19 @@
pw.print(prefix); pw.print("options="); pw.println(options.toBundle());
}
pw.print(prefix); pw.print("enqueueClockTime=");
- pw.print(new Date(enqueueClockTime));
+ pw.print(sdf.format(new Date(enqueueClockTime)));
pw.print(" dispatchClockTime=");
- pw.println(new Date(dispatchClockTime));
+ pw.println(sdf.format(new Date(dispatchClockTime)));
pw.print(prefix); pw.print("dispatchTime=");
TimeUtils.formatDuration(dispatchTime, now, pw);
+ pw.print(" (");
+ TimeUtils.formatDuration(dispatchClockTime-enqueueClockTime, pw);
+ pw.print(" since enq)");
if (finishTime != 0) {
pw.print(" finishTime="); TimeUtils.formatDuration(finishTime, now, pw);
+ pw.print(" (");
+ TimeUtils.formatDuration(finishTime-dispatchTime, pw);
+ pw.print(" since disp)");
} else {
pw.print(" receiverTime="); TimeUtils.formatDuration(receiverTime, now, pw);
}
