Improve short service debug log

Test: atest CtsShortFgsTestCases
Bug: 260748204

Change-Id: I2f4e3cc400eb9f413105cdcf9b6efa98ede47970

2 files changed, 58 insertions, 31 deletions

diff --git a/services/core/java/com/android/server/am/ActiveServices.java b/services/core/java/com/android/server/am/ActiveServices.java
index 24c9e0f55ab9..231037682603 100644
--- a/services/core/java/com/android/server/am/ActiveServices.java
+++ b/services/core/java/com/android/server/am/ActiveServices.java
@@ -2066,7 +2066,9 @@ public final class ActiveServices {
                     final boolean isOldTypeShortFgs = r.isShortFgs();
                     final boolean isNewTypeShortFgs =
                             foregroundServiceType == FOREGROUND_SERVICE_TYPE_SHORT_SERVICE;
-                    final boolean isOldTypeShortFgsAndTimedOut = r.shouldTriggerShortFgsTimeout();
+                    final long nowUptime = SystemClock.uptimeMillis();
+                    final boolean isOldTypeShortFgsAndTimedOut =
+                            r.shouldTriggerShortFgsTimeout(nowUptime);
 
                     // If true, we skip the BFSL check.
                     boolean bypassBfslCheck = false;
@@ -3191,9 +3193,11 @@ public final class ActiveServices {
 
     void onShortFgsTimeout(ServiceRecord sr) {
         synchronized (mAm) {
-            if (!sr.shouldTriggerShortFgsTimeout()) {
+            final long nowUptime = SystemClock.uptimeMillis();
+            if (!sr.shouldTriggerShortFgsTimeout(nowUptime)) {
                 if (DEBUG_SHORT_SERVICE) {
-                    Slog.d(TAG_SERVICE, "[STALE] Short FGS timed out: " + sr);
+                    Slog.d(TAG_SERVICE, "[STALE] Short FGS timed out: " + sr
+                            + " " + sr.getShortFgsTimedEventDescription(nowUptime));
                 }
                 return;
             }
@@ -3227,7 +3231,8 @@ public final class ActiveServices {
             if (sr == null) {
                 return false;
             }
-            return sr.shouldTriggerShortFgsTimeout();
+            final long nowUptime = SystemClock.uptimeMillis();
+            return sr.shouldTriggerShortFgsTimeout(nowUptime);
         } finally {
             Binder.restoreCallingIdentity(ident);
         }
@@ -3235,9 +3240,11 @@ public final class ActiveServices {
 
     void onShortFgsProcstateTimeout(ServiceRecord sr) {
         synchronized (mAm) {
-            if (!sr.shouldDemoteShortFgsProcState()) {
+            final long nowUptime = SystemClock.uptimeMillis();
+            if (!sr.shouldDemoteShortFgsProcState(nowUptime)) {
                 if (DEBUG_SHORT_SERVICE) {
-                    Slog.d(TAG_SERVICE, "[STALE] Short FGS procstate demotion: " + sr);
+                    Slog.d(TAG_SERVICE, "[STALE] Short FGS procstate demotion: " + sr
+                            + " " + sr.getShortFgsTimedEventDescription(nowUptime));
                 }
                 return;
             }
@@ -3258,9 +3265,11 @@ public final class ActiveServices {
         synchronized (mAm) {
             tr.mLatencyTracker.waitingOnAMSLockEnded();
 
-            if (!sr.shouldTriggerShortFgsAnr()) {
+            final long nowUptime = SystemClock.uptimeMillis();
+            if (!sr.shouldTriggerShortFgsAnr(nowUptime)) {
                 if (DEBUG_SHORT_SERVICE) {
-                    Slog.d(TAG_SERVICE, "[STALE] Short FGS ANR'ed: " + sr);
+                    Slog.d(TAG_SERVICE, "[STALE] Short FGS ANR'ed: " + sr
+                            + " " + sr.getShortFgsTimedEventDescription(nowUptime));
                 }
                 return;
             }
diff --git a/services/core/java/com/android/server/am/ServiceRecord.java b/services/core/java/com/android/server/am/ServiceRecord.java
index 61801177ffba..663121ea3212 100644
--- a/services/core/java/com/android/server/am/ServiceRecord.java
+++ b/services/core/java/com/android/server/am/ServiceRecord.java
@@ -392,6 +392,15 @@ final class ServiceRecord extends Binder implements ComponentName.WithComponentN
             return mStartTime + ams.mConstants.mShortFgsTimeoutDuration
                     + ams.mConstants.mShortFgsAnrExtraWaitDuration;
         }
+
+        String getDescription() {
+            return "sfc=" + this.mStartForegroundCount
+                    + " sid=" + this.mStartId
+                    + " stime=" + this.mStartTime
+                    + " tt=" + this.getTimeoutTime()
+                    + " dt=" + this.getProcStateDemoteTime()
+                    + " at=" + this.getAnrTime();
+        }
     }
 
     /**
@@ -1413,10 +1422,7 @@ final class ServiceRecord extends Binder implements ComponentName.WithComponentN
         this.mShortFgsInfo = null;
     }
 
-    /**
-     * @return true if it's a short FGS that's still up and running, and should be timed out.
-     */
-    public boolean shouldTriggerShortFgsTimeout() {
+    private boolean shouldTriggerShortFgsTimedEvent(long targetTime, long nowUptime) {
         if (!isAppAlive()) {
             return false;
         }
@@ -1424,36 +1430,48 @@ final class ServiceRecord extends Binder implements ComponentName.WithComponentN
                 || !mShortFgsInfo.isCurrent()) {
             return false;
         }
-        return mShortFgsInfo.getTimeoutTime() <= SystemClock.uptimeMillis();
+        return targetTime <= nowUptime;
+    }
+
+    /**
+     * @return true if it's a short FGS that's still up and running, and should be timed out.
+     */
+    public boolean shouldTriggerShortFgsTimeout(long nowUptime) {
+        return shouldTriggerShortFgsTimedEvent(
+                (mShortFgsInfo == null ? 0 : mShortFgsInfo.getTimeoutTime()),
+                nowUptime);
     }
 
     /**
      * @return true if it's a short FGS's procstate should be demoted.
      */
-    public boolean shouldDemoteShortFgsProcState() {
-        if (!isAppAlive()) {
-            return false;
-        }
-        if (!this.startRequested || !isShortFgs() || mShortFgsInfo == null
-                || !mShortFgsInfo.isCurrent()) {
-            return false;
-        }
-        return mShortFgsInfo.getProcStateDemoteTime() <= SystemClock.uptimeMillis();
+    public boolean shouldDemoteShortFgsProcState(long nowUptime) {
+        return shouldTriggerShortFgsTimedEvent(
+                (mShortFgsInfo == null ? 0 : mShortFgsInfo.getProcStateDemoteTime()),
+                nowUptime);
     }
 
     /**
      * @return true if it's a short FGS that's still up and running, and should be declared
      * an ANR.
      */
-    public boolean shouldTriggerShortFgsAnr() {
-        if (!isAppAlive()) {
-            return false;
-        }
-        if (!this.startRequested || !isShortFgs() || mShortFgsInfo == null
-                || !mShortFgsInfo.isCurrent()) {
-            return false;
-        }
-        return mShortFgsInfo.getAnrTime() <= SystemClock.uptimeMillis();
+    public boolean shouldTriggerShortFgsAnr(long nowUptime) {
+        return shouldTriggerShortFgsTimedEvent(
+                (mShortFgsInfo == null ? 0 : mShortFgsInfo.getAnrTime()),
+                nowUptime);
+    }
+
+    /**
+     * Human readable description about short-FGS internal states.
+     */
+    public String getShortFgsTimedEventDescription(long nowUptime) {
+        return "aa=" + isAppAlive()
+                + " sreq=" + this.startRequested
+                + " isfg=" + this.isForeground
+                + " type=" + Integer.toHexString(this.foregroundServiceType)
+                + " sfc=" + this.mStartForegroundCount
+                + " now=" + nowUptime
+                + " " + (mShortFgsInfo == null ? "" : mShortFgsInfo.getDescription());
     }
 
     private boolean isAppAlive() {