Change hwui jank detection to use deadline & gpu completion (1/2)

- Use GPU finish time as well as actual deadline to determine jank
rate.
- Use dynamic interval to adjust for 60/90hz switching
- Move frame metrics reporting into JankTracker to adjust the
deadline communicated to the app when in stuffing scenario.
- Adjust double-stuffing detection to be a bit more readable.

Test: GraphicsStatsValidationTest.java
Test: adb shell dumpsys gfxinfo
Test: FrameMetricsListenerTest
Test: Log output of FrameMetricsObserver
Bug: 169858044
Change-Id: I3a6b8ed163e2cf9cf2b67667110340ebe35f98a1

3 files changed, 53 insertions, 32 deletions

diff --git a/core/java/android/view/Choreographer.java b/core/java/android/view/Choreographer.java
index 7b3a8a64fc37..0a3963d782b1 100644
--- a/core/java/android/view/Choreographer.java
+++ b/core/java/android/view/Choreographer.java
@@ -177,8 +177,14 @@ public final class Choreographer {
     private boolean mCallbacksRunning;
     @UnsupportedAppUsage
     private long mLastFrameTimeNanos;
-    @UnsupportedAppUsage
+
+    /** DO NOT USE since this will not updated when screen refresh changes. */
+    @UnsupportedAppUsage(maxTargetSdk = Build.VERSION_CODES.R,
+            publicAlternatives = "Use {@link android.view.Display#getRefreshRate} instead")
+    @Deprecated
     private long mFrameIntervalNanos;
+    private long mLastFrameIntervalNanos;
+
     private boolean mDebugPrintNextFrameTimeDelta;
     private int mFPSDivisor = 1;
     private DisplayEventReceiver.VsyncEventData mLastVsyncEventData =
@@ -392,7 +398,9 @@ public final class Choreographer {
      * @hide
      */
     public long getFrameIntervalNanos() {
-        return mFrameIntervalNanos;
+        synchronized (mLock) {
+            return mLastFrameIntervalNanos;
+        }
     }
 
     void dump(String prefix, PrintWriter writer) {
@@ -688,6 +696,7 @@ public final class Choreographer {
     void doFrame(long frameTimeNanos, int frame,
             DisplayEventReceiver.VsyncEventData vsyncEventData) {
         final long startNanos;
+        final long frameIntervalNanos = vsyncEventData.frameInterval;
         synchronized (mLock) {
             if (!mFrameScheduled) {
                 return; // no work to do
@@ -702,17 +711,17 @@ public final class Choreographer {
             long intendedFrameTimeNanos = frameTimeNanos;
             startNanos = System.nanoTime();
             final long jitterNanos = startNanos - frameTimeNanos;
-            if (jitterNanos >= mFrameIntervalNanos) {
-                final long skippedFrames = jitterNanos / mFrameIntervalNanos;
+            if (jitterNanos >= frameIntervalNanos) {
+                final long skippedFrames = jitterNanos / frameIntervalNanos;
                 if (skippedFrames >= SKIPPED_FRAME_WARNING_LIMIT) {
                     Log.i(TAG, "Skipped " + skippedFrames + " frames!  "
                             + "The application may be doing too much work on its main thread.");
                 }
-                final long lastFrameOffset = jitterNanos % mFrameIntervalNanos;
+                final long lastFrameOffset = jitterNanos % frameIntervalNanos;
                 if (DEBUG_JANK) {
                     Log.d(TAG, "Missed vsync by " + (jitterNanos * 0.000001f) + " ms "
                             + "which is more than the frame interval of "
-                            + (mFrameIntervalNanos * 0.000001f) + " ms!  "
+                            + (frameIntervalNanos * 0.000001f) + " ms!  "
                             + "Skipping " + skippedFrames + " frames and setting frame "
                             + "time to " + (lastFrameOffset * 0.000001f) + " ms in the past.");
                 }
@@ -730,16 +739,17 @@ public final class Choreographer {
 
             if (mFPSDivisor > 1) {
                 long timeSinceVsync = frameTimeNanos - mLastFrameTimeNanos;
-                if (timeSinceVsync < (mFrameIntervalNanos * mFPSDivisor) && timeSinceVsync > 0) {
+                if (timeSinceVsync < (frameIntervalNanos * mFPSDivisor) && timeSinceVsync > 0) {
                     scheduleVsyncLocked();
                     return;
                 }
             }
 
             mFrameInfo.setVsync(intendedFrameTimeNanos, frameTimeNanos, vsyncEventData.id,
-                    vsyncEventData.frameDeadline, startNanos);
+                    vsyncEventData.frameDeadline, startNanos, vsyncEventData.frameInterval);
             mFrameScheduled = false;
             mLastFrameTimeNanos = frameTimeNanos;
+            mLastFrameIntervalNanos = frameIntervalNanos;
             mLastVsyncEventData = vsyncEventData;
         }
 
@@ -751,16 +761,17 @@ public final class Choreographer {
             AnimationUtils.lockAnimationClock(frameTimeNanos / TimeUtils.NANOS_PER_MS);
 
             mFrameInfo.markInputHandlingStart();
-            doCallbacks(Choreographer.CALLBACK_INPUT, frameTimeNanos);
+            doCallbacks(Choreographer.CALLBACK_INPUT, frameTimeNanos, frameIntervalNanos);
 
             mFrameInfo.markAnimationsStart();
-            doCallbacks(Choreographer.CALLBACK_ANIMATION, frameTimeNanos);
-            doCallbacks(Choreographer.CALLBACK_INSETS_ANIMATION, frameTimeNanos);
+            doCallbacks(Choreographer.CALLBACK_ANIMATION, frameTimeNanos, frameIntervalNanos);
+            doCallbacks(Choreographer.CALLBACK_INSETS_ANIMATION, frameTimeNanos,
+                    frameIntervalNanos);
 
             mFrameInfo.markPerformTraversalsStart();
-            doCallbacks(Choreographer.CALLBACK_TRAVERSAL, frameTimeNanos);
+            doCallbacks(Choreographer.CALLBACK_TRAVERSAL, frameTimeNanos, frameIntervalNanos);
 
-            doCallbacks(Choreographer.CALLBACK_COMMIT, frameTimeNanos);
+            doCallbacks(Choreographer.CALLBACK_COMMIT, frameTimeNanos, frameIntervalNanos);
         } finally {
             AnimationUtils.unlockAnimationClock();
             Trace.traceEnd(Trace.TRACE_TAG_VIEW);
@@ -774,7 +785,7 @@ public final class Choreographer {
         }
     }
 
-    void doCallbacks(int callbackType, long frameTimeNanos) {
+    void doCallbacks(int callbackType, long frameTimeNanos, long frameIntervalNanos) {
         CallbackRecord callbacks;
         synchronized (mLock) {
             // We use "now" to determine when callbacks become due because it's possible
@@ -799,13 +810,13 @@ public final class Choreographer {
             if (callbackType == Choreographer.CALLBACK_COMMIT) {
                 final long jitterNanos = now - frameTimeNanos;
                 Trace.traceCounter(Trace.TRACE_TAG_VIEW, "jitterNanos", (int) jitterNanos);
-                if (jitterNanos >= 2 * mFrameIntervalNanos) {
-                    final long lastFrameOffset = jitterNanos % mFrameIntervalNanos
-                            + mFrameIntervalNanos;
+                if (jitterNanos >= 2 * frameIntervalNanos) {
+                    final long lastFrameOffset = jitterNanos % frameIntervalNanos
+                            + frameIntervalNanos;
                     if (DEBUG_JANK) {
                         Log.d(TAG, "Commit callback delayed by " + (jitterNanos * 0.000001f)
                                 + " ms which is more than twice the frame interval of "
-                                + (mFrameIntervalNanos * 0.000001f) + " ms!  "
+                                + (frameIntervalNanos * 0.000001f) + " ms!  "
                                 + "Setting frame time to " + (lastFrameOffset * 0.000001f)
                                 + " ms in the past.");
                         mDebugPrintNextFrameTimeDelta = true;
diff --git a/core/java/android/view/DisplayEventReceiver.java b/core/java/android/view/DisplayEventReceiver.java
index e6cd25275ca2..e3f430bf3fe0 100644
--- a/core/java/android/view/DisplayEventReceiver.java
+++ b/core/java/android/view/DisplayEventReceiver.java
@@ -158,14 +158,23 @@ public abstract class DisplayEventReceiver {
         // allotted for the frame to be completed.
         public final long frameDeadline;
 
-        VsyncEventData(long id, long frameDeadline) {
+        /**
+         * The current interval between frames in ns. This will be used to align
+         * {@link FrameInfo#VSYNC} to the current vsync in case Choreographer callback was heavily
+         * delayed by the app.
+         */
+        public final long frameInterval;
+
+        VsyncEventData(long id, long frameDeadline, long frameInterval) {
             this.id = id;
             this.frameDeadline = frameDeadline;
+            this.frameInterval = frameInterval;
         }
 
         VsyncEventData() {
             this.id = FrameInfo.INVALID_VSYNC_ID;
             this.frameDeadline = Long.MAX_VALUE;
+            this.frameInterval = -1;
         }
     }
 
@@ -259,9 +268,9 @@ public abstract class DisplayEventReceiver {
     // Called from native code.
     @SuppressWarnings("unused")
     private void dispatchVsync(long timestampNanos, long physicalDisplayId, int frame,
-            long frameTimelineVsyncId, long frameDeadline) {
+            long frameTimelineVsyncId, long frameDeadline, long frameInterval) {
         onVsync(timestampNanos, physicalDisplayId, frame,
-                new VsyncEventData(frameTimelineVsyncId, frameDeadline));
+                new VsyncEventData(frameTimelineVsyncId, frameDeadline, frameInterval));
     }
 
     // Called from native code.
diff --git a/core/java/android/view/FrameMetrics.java b/core/java/android/view/FrameMetrics.java
index 9cdf91a55c39..f6d525c10cc9 100644
--- a/core/java/android/view/FrameMetrics.java
+++ b/core/java/android/view/FrameMetrics.java
@@ -243,18 +243,19 @@ public final class FrameMetrics {
         int DRAW_START = 8;
         int FRAME_DEADLINE = 9;
         int FRAME_START_TIME = 10;
-        int SYNC_QUEUED = 11;
-        int SYNC_START = 12;
-        int ISSUE_DRAW_COMMANDS_START = 13;
-        int SWAP_BUFFERS = 14;
-        int FRAME_COMPLETED = 15;
-        int DEQUEUE_BUFFER_DURATION = 16;
-        int QUEUE_BUFFER_DURATION = 17;
-        int GPU_COMPLETED = 18;
-        int SWAP_BUFFERS_COMPLETED = 19;
-        int DISPLAY_PRESENT_TIME = 20;
+        int FRAME_INTERVAL = 11;
+        int SYNC_QUEUED = 12;
+        int SYNC_START = 13;
+        int ISSUE_DRAW_COMMANDS_START = 14;
+        int SWAP_BUFFERS = 15;
+        int FRAME_COMPLETED = 16;
+        int DEQUEUE_BUFFER_DURATION = 17;
+        int QUEUE_BUFFER_DURATION = 18;
+        int GPU_COMPLETED = 19;
+        int SWAP_BUFFERS_COMPLETED = 20;
+        int DISPLAY_PRESENT_TIME = 21;
 
-        int FRAME_STATS_COUNT = 21; // must always be last and in sync with
+        int FRAME_STATS_COUNT = 22; // must always be last and in sync with
                                     // FrameInfoIndex::NumIndexes in libs/hwui/FrameInfo.h
     }