Use correct timestamps of events for logging.

Currently when WM detects certain events, it will notify the logger
of these events asynchronously and logger uses the timestamp at which it
gets notified to log these events. It's possible that the delay between
when the event actually occurs and when the logger gets notified could be
large. So for better accuracy, WM should also pass on the event timestamp
to the logger.

Bug: 62375480
Test: Triggered sysui_multi_action event logs and verified that
      APP_TRANSITION_DELAY_MS is less than APP_TRANSITION_WINDOWS_DRAWN_DELAY_MS.
Test: When the system is not busy, the timestamps we used to log earlier
      and timestamps we log with this change are almost same.
Change-Id: I5f62654a6b7f179d821c0082b180246c8a569df1

7 files changed, 62 insertions, 34 deletions

diff --git a/core/java/android/app/ActivityManagerInternal.java b/core/java/android/app/ActivityManagerInternal.java
index e9ee13866b1a..4e34a95b544b 100644
--- a/core/java/android/app/ActivityManagerInternal.java
+++ b/core/java/android/app/ActivityManagerInternal.java
@@ -24,6 +24,7 @@ import android.content.Intent;
 import android.content.res.Configuration;
 import android.os.Bundle;
 import android.os.IBinder;
+import android.os.SystemClock;
 import android.service.voice.IVoiceInteractionSession;
 import android.util.SparseIntArray;
 
@@ -134,8 +135,10 @@ public abstract class ActivityManagerInternal {
      *
      * @param reasons A map from stack id to a reason integer why the transition was started,, which
      *                must be one of the APP_TRANSITION_* values.
+     * @param timestamp The time at which the app transition started in
+     *                  {@link SystemClock#uptimeMillis()} timebase.
      */
-    public abstract void notifyAppTransitionStarting(SparseIntArray reasons);
+    public abstract void notifyAppTransitionStarting(SparseIntArray reasons, long timestamp);
 
     /**
      * Callback for window manager to let activity manager know that the app transition was
diff --git a/services/core/java/com/android/server/am/ActivityManagerService.java b/services/core/java/com/android/server/am/ActivityManagerService.java
index f3ecfeb40498..56f7b18dbef4 100644
--- a/services/core/java/com/android/server/am/ActivityManagerService.java
+++ b/services/core/java/com/android/server/am/ActivityManagerService.java
@@ -23708,9 +23708,10 @@ public class ActivityManagerService extends IActivityManager.Stub
         }
 
         @Override
-        public void notifyAppTransitionStarting(SparseIntArray reasons) {
+        public void notifyAppTransitionStarting(SparseIntArray reasons, long timestamp) {
             synchronized (ActivityManagerService.this) {
-                mStackSupervisor.mActivityMetricsLogger.notifyTransitionStarting(reasons);
+                mStackSupervisor.mActivityMetricsLogger.notifyTransitionStarting(
+                        reasons, timestamp);
             }
         }
 
diff --git a/services/core/java/com/android/server/am/ActivityMetricsLogger.java b/services/core/java/com/android/server/am/ActivityMetricsLogger.java
index bf7b663454b8..98815d7e18c7 100644
--- a/services/core/java/com/android/server/am/ActivityMetricsLogger.java
+++ b/services/core/java/com/android/server/am/ActivityMetricsLogger.java
@@ -230,12 +230,12 @@ class ActivityMetricsLogger {
     /**
      * Notifies the tracker that all windows of the app have been drawn.
      */
-    void notifyWindowsDrawn(int stackId) {
+    void notifyWindowsDrawn(int stackId, long timestamp) {
         final StackTransitionInfo info = mStackTransitionInfo.get(stackId);
         if (info == null || info.loggedWindowsDrawn) {
             return;
         }
-        info.windowsDrawnDelayMs = calculateCurrentDelay();
+        info.windowsDrawnDelayMs = calculateDelay(timestamp);
         info.loggedWindowsDrawn = true;
         if (allStacksWindowsDrawn() && mLoggedTransitionStarting) {
             reset(false /* abort */);
@@ -245,13 +245,13 @@ class ActivityMetricsLogger {
     /**
      * Notifies the tracker that the starting window was drawn.
      */
-    void notifyStartingWindowDrawn(int stackId) {
+    void notifyStartingWindowDrawn(int stackId, long timestamp) {
         final StackTransitionInfo info = mStackTransitionInfo.get(stackId);
         if (info == null || info.loggedStartingWindowDrawn) {
             return;
         }
         info.loggedStartingWindowDrawn = true;
-        info.startingWindowDelayMs = calculateCurrentDelay();
+        info.startingWindowDelayMs = calculateDelay(timestamp);
     }
 
     /**
@@ -260,11 +260,11 @@ class ActivityMetricsLogger {
      * @param stackIdReasons A map from stack id to a reason integer, which must be on of
      *                       ActivityManagerInternal.APP_TRANSITION_* reasons.
      */
-    void notifyTransitionStarting(SparseIntArray stackIdReasons) {
+    void notifyTransitionStarting(SparseIntArray stackIdReasons, long timestamp) {
         if (!isAnyTransitionActive() || mLoggedTransitionStarting) {
             return;
         }
-        mCurrentTransitionDelayMs = calculateCurrentDelay();
+        mCurrentTransitionDelayMs = calculateDelay(timestamp);
         mLoggedTransitionStarting = true;
         for (int index = stackIdReasons.size() - 1; index >= 0; index--) {
             final int stackId = stackIdReasons.keyAt(index);
@@ -344,6 +344,11 @@ class ActivityMetricsLogger {
         return (int) (SystemClock.uptimeMillis() - mCurrentTransitionStartTime);
     }
 
+    private int calculateDelay(long timestamp) {
+        // Shouldn't take more than 25 days to launch an app, so int is fine here.
+        return (int) (timestamp - mCurrentTransitionStartTime);
+    }
+
     private void logAppTransitionMultiEvents() {
         for (int index = mStackTransitionInfo.size() - 1; index >= 0; index--) {
             final StackTransitionInfo info = mStackTransitionInfo.valueAt(index);
diff --git a/services/core/java/com/android/server/am/ActivityRecord.java b/services/core/java/com/android/server/am/ActivityRecord.java
index ec6a4f6b7f7c..01c52b9e4658 100644
--- a/services/core/java/com/android/server/am/ActivityRecord.java
+++ b/services/core/java/com/android/server/am/ActivityRecord.java
@@ -1928,18 +1928,19 @@ final class ActivityRecord extends ConfigurationContainer implements AppWindowCo
     }
 
     @Override
-    public void onStartingWindowDrawn() {
+    public void onStartingWindowDrawn(long timestamp) {
         synchronized (service) {
-            mStackSupervisor.mActivityMetricsLogger.notifyStartingWindowDrawn(getStackId());
+            mStackSupervisor.mActivityMetricsLogger.notifyStartingWindowDrawn(
+                    getStackId(), timestamp);
         }
     }
 
     @Override
-    public void onWindowsDrawn() {
+    public void onWindowsDrawn(long timestamp) {
         synchronized (service) {
-            mStackSupervisor.mActivityMetricsLogger.notifyWindowsDrawn(getStackId());
+            mStackSupervisor.mActivityMetricsLogger.notifyWindowsDrawn(getStackId(), timestamp);
             if (displayStartTime != 0) {
-                reportLaunchTimeLocked(SystemClock.uptimeMillis());
+                reportLaunchTimeLocked(timestamp);
             }
             mStackSupervisor.sendWaitingVisibleReportLocked(this);
             startTime = 0;
diff --git a/services/core/java/com/android/server/wm/AppWindowContainerController.java b/services/core/java/com/android/server/wm/AppWindowContainerController.java
index 66401846c034..c76b8da4af93 100644
--- a/services/core/java/com/android/server/wm/AppWindowContainerController.java
+++ b/services/core/java/com/android/server/wm/AppWindowContainerController.java
@@ -36,6 +36,8 @@ import android.graphics.Rect;
 import android.os.Debug;
 import android.os.Handler;
 import android.os.IBinder;
+import android.os.Looper;
+import android.os.Message;
 import android.os.Trace;
 import android.util.Slog;
 import android.view.IApplicationToken;
@@ -59,23 +61,38 @@ public class AppWindowContainerController
     private final IApplicationToken mToken;
     private final Handler mHandler;
 
-    private final Runnable mOnStartingWindowDrawn = () -> {
-        if (mListener == null) {
-            return;
+    private final class H extends Handler {
+        public static final int NOTIFY_WINDOWS_DRAWN = 1;
+        public static final int NOTIFY_STARTING_WINDOW_DRAWN = 2;
+
+        public H(Looper looper) {
+            super(looper);
         }
-        if (DEBUG_VISIBILITY) Slog.v(TAG_WM, "Reporting drawn in "
-                + AppWindowContainerController.this.mToken);
-        mListener.onStartingWindowDrawn();
-    };
 
-    private final Runnable mOnWindowsDrawn = () -> {
-        if (mListener == null) {
-            return;
+        @Override
+        public void handleMessage(Message msg) {
+            switch (msg.what) {
+                case NOTIFY_WINDOWS_DRAWN:
+                    if (mListener == null) {
+                        return;
+                    }
+                    if (DEBUG_VISIBILITY) Slog.v(TAG_WM, "Reporting drawn in "
+                            + AppWindowContainerController.this.mToken);
+                    mListener.onWindowsDrawn(msg.getWhen());
+                    break;
+                case NOTIFY_STARTING_WINDOW_DRAWN:
+                    if (mListener == null) {
+                        return;
+                    }
+                    if (DEBUG_VISIBILITY) Slog.v(TAG_WM, "Reporting drawn in "
+                            + AppWindowContainerController.this.mToken);
+                    mListener.onStartingWindowDrawn(msg.getWhen());
+                    break;
+                default:
+                    break;
+            }
         }
-        if (DEBUG_VISIBILITY) Slog.v(TAG_WM, "Reporting drawn in "
-                + AppWindowContainerController.this.mToken);
-        mListener.onWindowsDrawn();
-    };
+    }
 
     private final Runnable mOnWindowsVisible = () -> {
         if (mListener == null) {
@@ -210,7 +227,7 @@ public class AppWindowContainerController
             int targetSdkVersion, int rotationAnimationHint, long inputDispatchingTimeoutNanos,
             WindowManagerService service, Configuration overrideConfig, Rect bounds) {
         super(listener, service);
-        mHandler = new Handler(service.mH.getLooper());
+        mHandler = new H(service.mH.getLooper());
         mToken = token;
         synchronized(mWindowMap) {
             AppWindowToken atoken = mRoot.getAppWindowToken(mToken.asBinder());
@@ -734,11 +751,11 @@ public class AppWindowContainerController
     }
 
     void reportStartingWindowDrawn() {
-        mHandler.post(mOnStartingWindowDrawn);
+        mHandler.sendMessage(mHandler.obtainMessage(H.NOTIFY_STARTING_WINDOW_DRAWN));
     }
 
     void reportWindowsDrawn() {
-        mHandler.post(mOnWindowsDrawn);
+        mHandler.sendMessage(mHandler.obtainMessage(H.NOTIFY_WINDOWS_DRAWN));
     }
 
     void reportWindowsVisible() {
diff --git a/services/core/java/com/android/server/wm/AppWindowContainerListener.java b/services/core/java/com/android/server/wm/AppWindowContainerListener.java
index 26537f27bce8..8a39a7408058 100644
--- a/services/core/java/com/android/server/wm/AppWindowContainerListener.java
+++ b/services/core/java/com/android/server/wm/AppWindowContainerListener.java
@@ -19,7 +19,7 @@ package com.android.server.wm;
 /** Interface used by the creator of the controller to listen to changes with the container. */
 public interface AppWindowContainerListener extends WindowContainerListener {
     /** Called when the windows associated app window container are drawn. */
-    void onWindowsDrawn();
+    void onWindowsDrawn(long timestamp);
     /** Called when the windows associated app window container are visible. */
     void onWindowsVisible();
     /** Called when the windows associated app window container are no longer visible. */
@@ -28,7 +28,7 @@ public interface AppWindowContainerListener extends WindowContainerListener {
     /**
      * Called when the starting window for this container is drawn.
      */
-    void onStartingWindowDrawn();
+    void onStartingWindowDrawn(long timestamp);
 
     /**
      * Called when the key dispatching to a window associated with the app window container
diff --git a/services/core/java/com/android/server/wm/WindowManagerService.java b/services/core/java/com/android/server/wm/WindowManagerService.java
index 9d1b3d9ed81a..d2b4fb56060c 100644
--- a/services/core/java/com/android/server/wm/WindowManagerService.java
+++ b/services/core/java/com/android/server/wm/WindowManagerService.java
@@ -5132,7 +5132,8 @@ public class WindowManagerService extends IWindowManager.Stub
                 }
                 break;
                 case NOTIFY_APP_TRANSITION_STARTING: {
-                    mAmInternal.notifyAppTransitionStarting((SparseIntArray) msg.obj);
+                    mAmInternal.notifyAppTransitionStarting((SparseIntArray) msg.obj,
+                            msg.getWhen());
                 }
                 break;
                 case NOTIFY_APP_TRANSITION_CANCELLED: {