From 865907db099eed08cac7ab177161361f5c82e656 Mon Sep 17 00:00:00 2001 From: Dianne Hackborn Date: Wed, 21 Oct 2015 17:12:53 -0700 Subject: [PATCH] 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 --- .../com/android/server/am/ActiveServices.java | 18 ++++++++++++- .../com/android/server/am/BroadcastQueue.java | 27 +++++++++++++------ .../android/server/am/BroadcastRecord.java | 13 ++++++--- 3 files changed, 46 insertions(+), 12 deletions(-) diff --git a/services/core/java/com/android/server/am/ActiveServices.java b/services/core/java/com/android/server/am/ActiveServices.java index b87e109b549ff..970f1b5f2c86e 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 @@ public final class ActiveServices { 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 @@ public final class ActiveServices { 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 @@ public final class ActiveServices { // 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 0 || mOrderedBroadcasts.size() > 0 || mPendingBroadcast != null) { boolean printed = false; @@ -1301,7 +1303,7 @@ public final class BroadcastQueue { 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 @@ public final class BroadcastQueue { 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 @@ public final class BroadcastQueue { } pw.println(" Pending broadcast [" + mQueueName + "]:"); if (mPendingBroadcast != null) { - mPendingBroadcast.dump(pw, " "); + mPendingBroadcast.dump(pw, " ", sdf); } else { pw.println(" (null)"); } @@ -1366,7 +1368,7 @@ public final class BroadcastQueue { 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 @@ public final class BroadcastQueue { } // 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 @@ public final class BroadcastQueue { 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 1fbfd9feff8e4..b42bcff15f83a 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.PrintWriterPrinter; 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 @@ final class BroadcastRecord extends Binder { 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 @@ final class BroadcastRecord extends Binder { 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); }