am ac70b2d1: Merge "More debugging for bug 18201239." into lmp-mr1-dev

* commit 'ac70b2d1722fd3ad94b2bf1e8c7695bded56987a':
  More debugging for bug 18201239.

core/java/android/app/ActivityThread.java

@@ -2931,6 +2931,8 @@ public final class ActivityThread {
                             token, 0, 0, 0);
                 } catch (RemoteException e) {
                     // nothing to do.
+                    Slog.i(TAG, "handleStopService: unable to execute serviceDoneExecuting for "
+                            + token, e);
                 }
             } catch (Exception e) {
                 if (!mInstrumentation.onException(s, e)) {
@@ -2938,6 +2940,7 @@ public final class ActivityThread {
                             "Unable to stop service " + s
                             + ": " + e.toString(), e);
                 }
+                Slog.i(TAG, "handleStopService: exception for " + token, e);
             }
         } else {
             Slog.i(TAG, "handleStopService: token=" + token + " not found.");

services/core/java/com/android/server/am/ActiveServices.java

@@ -1638,6 +1638,7 @@ public final class ActiveServices {
         }
 
         if (DEBUG_SERVICE) Slog.v(TAG, "Bringing down " + r + " " + r.intent);
+        r.destroyTime = SystemClock.uptimeMillis();
         if (LOG_SERVICE_START_STOP) {
             EventLogTags.writeAmDestroyService(
                     r.userId, System.identityHashCode(r), (r.app != null) ? r.app.pid : -1);
@@ -1869,7 +1870,7 @@ public final class ActiveServices {
 
     private void serviceDoneExecutingLocked(ServiceRecord r, boolean inDestroying,
             boolean finishing) {
-        if (true || DEBUG_SERVICE) Slog.v(TAG, "<<< DONE EXECUTING " + r
+        if (DEBUG_SERVICE) Slog.v(TAG, "<<< DONE EXECUTING " + r
                 + ": nesting=" + r.executeNesting
                 + ", inDestroying=" + inDestroying + ", app=" + r.app);
         else if (DEBUG_SERVICE_EXECUTING) Slog.v(TAG, "<<< DONE EXECUTING " + r.shortName);
@@ -2393,13 +2394,15 @@ public final class ActiveServices {
                 sb.append("sxecuting service ");
                 sb.append(timeout.shortName);
                 sb.append(" (execStart=");
-                TimeUtils.formatDuration(now-timeout.executingStart, sb);
+                TimeUtils.formatDuration(timeout.executingStart - now, sb);
                 sb.append(", nesting=");
                 sb.append(timeout.executeNesting);
+                sb.append(", destroyed=");
+                TimeUtils.formatDuration(timeout.destroyTime - now, sb);
                 sb.append(", fg=");
                 sb.append(proc.execServicesFg);
                 sb.append(", create=");
-                TimeUtils.formatDuration(now-timeout.createTime, sb);
+                TimeUtils.formatDuration(timeout.createTime - now, sb);
                 sb.append(", proc=");
                 sb.append(timeout.app != null ? timeout.app.toShortString() : "null");
                 sb.append(")");

services/core/java/com/android/server/am/ActivityManagerService.java

@@ -15354,6 +15354,7 @@ public final class ActivityManagerService extends ActivityManagerNative
     public void serviceDoneExecuting(IBinder token, int type, int startId, int res) {
         synchronized(this) {
             if (!(token instanceof ServiceRecord)) {
+                Slog.e(TAG, "serviceDoneExecuting: Invalid service token=" + token);
                 throw new IllegalArgumentException("Invalid service token");
             }
             mServices.serviceDoneExecutingLocked((ServiceRecord)token, type, startId, res);

services/core/java/com/android/server/am/ServiceRecord.java

@@ -105,6 +105,7 @@ final class ServiceRecord extends Binder {
     long restartDelay;      // delay until next restart attempt.
     long restartTime;       // time of last restart.
     long nextRestartTime;   // time when restartDelay will expire.
+    long destroyTime;       // time at which destory was initiated.
 
     String stringName;      // caching of toString
     
@@ -250,6 +251,10 @@ final class ServiceRecord extends Binder {
                     TimeUtils.formatDuration(executingStart, now, pw);
                     pw.println();
         }
+        if (destroyTime != 0) {
+            pw.print(" destroyed=");
+            TimeUtils.formatDuration(destroyTime, now, pw);
+        }
         if (crashCount != 0 || restartCount != 0
                 || restartDelay != 0 || nextRestartTime != 0) {
             pw.print(prefix); pw.print("restartCount="); pw.print(restartCount);