More debugging for bug 18201239.

Fixes bug 19045133.

Change-Id: I2ef2b8600278ed91df59db4acf4740dac970ee3a
diff --git a/core/java/android/app/ActivityThread.java b/core/java/android/app/ActivityThread.java
index 3304c76..b5c0e90 100644
--- a/core/java/android/app/ActivityThread.java
+++ b/core/java/android/app/ActivityThread.java
@@ -2931,6 +2931,8 @@
                             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 @@
                             "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.");
diff --git a/services/core/java/com/android/server/am/ActiveServices.java b/services/core/java/com/android/server/am/ActiveServices.java
index ce69391..10e4410 100755
--- a/services/core/java/com/android/server/am/ActiveServices.java
+++ b/services/core/java/com/android/server/am/ActiveServices.java
@@ -1638,6 +1638,7 @@
         }
 
         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 @@
 
     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 @@
                 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(")");
diff --git a/services/core/java/com/android/server/am/ActivityManagerService.java b/services/core/java/com/android/server/am/ActivityManagerService.java
index b107d9a..87e7090 100755
--- a/services/core/java/com/android/server/am/ActivityManagerService.java
+++ b/services/core/java/com/android/server/am/ActivityManagerService.java
@@ -15354,6 +15354,7 @@
     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);
diff --git a/services/core/java/com/android/server/am/ServiceRecord.java b/services/core/java/com/android/server/am/ServiceRecord.java
index d4a378b..8381c4a 100644
--- a/services/core/java/com/android/server/am/ServiceRecord.java
+++ b/services/core/java/com/android/server/am/ServiceRecord.java
@@ -105,6 +105,7 @@
     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 @@
                     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);