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

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 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 @@ 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<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.SystemClock;
 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 @@ public final class BroadcastQueue {
 
     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 @@ 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 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.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);
         }