Merge "Fix overcounting after end in case of incomplete callbacks" into tm-dev

core/java/com/android/internal/jank/FrameTracker.java

@@ -36,6 +36,7 @@ import android.os.Trace;
 import android.text.TextUtils;
 import android.util.Log;
 import android.util.SparseArray;
+import android.util.StatsLog;
 import android.view.Choreographer;
 import android.view.FrameMetrics;
 import android.view.SurfaceControl;
@@ -98,6 +99,7 @@ public class FrameTracker extends SurfaceControl.OnJankDataListener
     private final ViewRootImpl.SurfaceChangedCallback mSurfaceChangedCallback;
     private final Handler mHandler;
     private final ChoreographerWrapper mChoreographer;
+    private final StatsLogWrapper mStatsLog;
     private final Object mLock = InteractionJankMonitor.getInstance().getLock();
     private final boolean mDeferMonitoring;
 
@@ -148,6 +150,7 @@ public class FrameTracker extends SurfaceControl.OnJankDataListener
             @NonNull SurfaceControlWrapper surfaceControlWrapper,
             @NonNull ChoreographerWrapper choreographer,
             @Nullable FrameMetricsWrapper metrics,
+            @NonNull StatsLogWrapper statsLog,
             int traceThresholdMissedFrames, int traceThresholdFrameTimeMillis,
             @Nullable FrameTrackerListener listener, @NonNull Configuration config) {
         mSurfaceOnly = config.isSurfaceOnly();
@@ -155,6 +158,7 @@ public class FrameTracker extends SurfaceControl.OnJankDataListener
         mHandler = handler;
         mChoreographer = choreographer;
         mSurfaceControlWrapper = surfaceControlWrapper;
+        mStatsLog = statsLog;
         mDeferMonitoring = config.shouldDeferMonitor();
 
         // HWUI instrumentation init.
@@ -215,7 +219,7 @@ public class FrameTracker extends SurfaceControl.OnJankDataListener
                             }
                             if (!mMetricsFinalized) {
                                 end(REASON_END_SURFACE_DESTROYED);
-                                finish(mJankInfos.size() - 1);
+                                finish();
                             }
                         }
                     }, 50);
@@ -309,7 +313,7 @@ public class FrameTracker extends SurfaceControl.OnJankDataListener
                 // Waiting at most 10 seconds for all callbacks to finish.
                 mWaitForFinishTimedOut = () -> {
                     Log.e(TAG, "force finish cuj because of time out:" + mSession.getName());
-                    finish(mJankInfos.size() - 1);
+                    finish();
                 };
                 mHandler.postDelayed(mWaitForFinishTimedOut, TimeUnit.SECONDS.toMillis(10));
                 notifyCujEvent(ACTION_SESSION_END);
@@ -426,51 +430,45 @@ public class FrameTracker extends SurfaceControl.OnJankDataListener
         }
     }
 
-    /**
+    private boolean hasReceivedCallbacksAfterEnd() {
-     * Finds the first index in {@link #mJankInfos} which happened on or after {@link #mEndVsyncId},
+        if (mEndVsyncId == INVALID_ID) {
-     * or -1 if the session hasn't ended yet.
+            return false;
-     */
-    private int getIndexOnOrAfterEnd() {
-        if (mEndVsyncId == INVALID_ID || mMetricsFinalized) {
-            return -1;
         }
         JankInfo last = mJankInfos.size() == 0 ? null : mJankInfos.valueAt(mJankInfos.size() - 1);
         if (last == null) {
-            return -1;
+            return false;
         }
         if (last.frameVsyncId < mEndVsyncId) {
-            return -1;
+            return false;
         }
-
-        int lastIndex = -1;
         for (int i = mJankInfos.size() - 1; i >= 0; i--) {
             JankInfo info = mJankInfos.valueAt(i);
             if (info.frameVsyncId >= mEndVsyncId) {
-                if (isLastIndexCandidate(info)) {
+                if (callbacksReceived(info)) {
-                    lastIndex = i;
+                    return true;
                 }
-            } else {
-                break;
             }
         }
-        return lastIndex;
+        return false;
     }
 
     private void processJankInfos() {
-        int indexOnOrAfterEnd = getIndexOnOrAfterEnd();
+        if (mMetricsFinalized) {
-        if (indexOnOrAfterEnd == -1) {
             return;
         }
-        finish(indexOnOrAfterEnd);
+        if (!hasReceivedCallbacksAfterEnd()) {
+            return;
+        }
+        finish();
     }
 
-    private boolean isLastIndexCandidate(JankInfo info) {
+    private boolean callbacksReceived(JankInfo info) {
         return mSurfaceOnly
                 ? info.surfaceControlCallbackFired
                 : info.hwuiCallbackFired && info.surfaceControlCallbackFired;
     }
 
-    private void finish(int indexOnOrAfterEnd) {
+    private void finish() {
         mHandler.removeCallbacks(mWaitForFinishTimedOut);
         mWaitForFinishTimedOut = null;
         mMetricsFinalized = true;
@@ -484,12 +482,15 @@ public class FrameTracker extends SurfaceControl.OnJankDataListener
         int missedAppFramesCount = 0;
         int missedSfFramesCount = 0;
 
-        for (int i = 0; i <= indexOnOrAfterEnd; i++) {
+        for (int i = 0; i < mJankInfos.size(); i++) {
             JankInfo info = mJankInfos.valueAt(i);
             final boolean isFirstDrawn = !mSurfaceOnly && info.isFirstFrame;
             if (isFirstDrawn) {
                 continue;
             }
+            if (info.frameVsyncId > mEndVsyncId) {
+                break;
+            }
             if (info.surfaceControlCallbackFired) {
                 totalFramesCount++;
                 boolean missedFrame = false;
@@ -541,7 +542,7 @@ public class FrameTracker extends SurfaceControl.OnJankDataListener
             triggerPerfetto();
         }
         if (mSession.logToStatsd()) {
-            FrameworkStatsLog.write(
+            mStatsLog.write(
                     FrameworkStatsLog.UI_INTERACTION_FRAME_INFO_REPORTED,
                     mSession.getStatsdInteractionType(),
                     totalFramesCount,
@@ -691,6 +692,13 @@ public class FrameTracker extends SurfaceControl.OnJankDataListener
         }
     }
 
+    public static class StatsLogWrapper {
+        public void write(int code,
+                int arg1, long arg2, long arg3, long arg4, long arg5, long arg6) {
+            FrameworkStatsLog.write(code, arg1, arg2, arg3, arg4, arg5, arg6);
+        }
+    }
+
     /**
      * A listener that notifies cuj events.
      */

core/java/com/android/internal/jank/InteractionJankMonitor.java

@@ -385,7 +385,8 @@ public class InteractionJankMonitor {
         synchronized (mLock) {
             FrameTrackerListener eventsListener = (s, act) -> handleCujEvents(act, s);
             return new FrameTracker(session, mWorker.getThreadHandler(),
-                    threadedRenderer, viewRoot, surfaceControl, choreographer, mMetrics,
+                    threadedRenderer, viewRoot, surfaceControl, choreographer,
+                    mMetrics, new FrameTracker.StatsLogWrapper(),
                     mTraceThresholdMissedFrames, mTraceThresholdFrameTimeMillis,
                     eventsListener, config);
         }

core/tests/coretests/src/com/android/internal/jank/FrameTrackerTest.java

@@ -23,11 +23,14 @@ import static android.view.SurfaceControl.JankData.JANK_SURFACEFLINGER_DEADLINE_
 import static com.android.internal.jank.FrameTracker.SurfaceControlWrapper;
 import static com.android.internal.jank.FrameTracker.ViewRootWrapper;
 import static com.android.internal.jank.InteractionJankMonitor.CUJ_NOTIFICATION_SHADE_EXPAND_COLLAPSE;
+import static com.android.internal.jank.InteractionJankMonitor.CUJ_TO_STATSD_INTERACTION_TYPE;
 import static com.android.internal.jank.InteractionJankMonitor.CUJ_WALLPAPER_TRANSITION;
+import static com.android.internal.util.FrameworkStatsLog.UI_INTERACTION_FRAME_INFO_REPORTED;
 
 import static com.google.common.truth.Truth.assertThat;
 
 import static org.mockito.ArgumentMatchers.any;
+import static org.mockito.ArgumentMatchers.eq;
 import static org.mockito.Mockito.doNothing;
 import static org.mockito.Mockito.doReturn;
 import static org.mockito.Mockito.mock;
@@ -50,6 +53,7 @@ import androidx.test.rule.ActivityTestRule;
 
 import com.android.internal.jank.FrameTracker.ChoreographerWrapper;
 import com.android.internal.jank.FrameTracker.FrameMetricsWrapper;
+import com.android.internal.jank.FrameTracker.StatsLogWrapper;
 import com.android.internal.jank.FrameTracker.ThreadedRendererWrapper;
 import com.android.internal.jank.InteractionJankMonitor.Configuration;
 import com.android.internal.jank.InteractionJankMonitor.Session;
@@ -76,6 +80,7 @@ public class FrameTrackerTest {
     private SurfaceControlWrapper mSurfaceControlWrapper;
     private ViewRootWrapper mViewRootWrapper;
     private ChoreographerWrapper mChoreographer;
+    private StatsLogWrapper mStatsLog;
     private ArgumentCaptor<OnJankDataListener> mListenerCapture;
     private SurfaceControl mSurfaceControl;
 
@@ -103,6 +108,7 @@ public class FrameTrackerTest {
                 mListenerCapture.capture());
 
         mChoreographer = mock(ChoreographerWrapper.class);
+        mStatsLog = mock(StatsLogWrapper.class);
     }
 
     private FrameTracker spyFrameTracker(int cuj, String postfix, boolean surfaceOnly) {
@@ -111,9 +117,10 @@ public class FrameTrackerTest {
         Configuration config = mock(Configuration.class);
         when(config.isSurfaceOnly()).thenReturn(surfaceOnly);
         when(config.getSurfaceControl()).thenReturn(mSurfaceControl);
+        when(config.shouldDeferMonitor()).thenReturn(true);
         FrameTracker frameTracker = Mockito.spy(
                 new FrameTracker(session, handler, mRenderer, mViewRootWrapper,
-                        mSurfaceControlWrapper, mChoreographer, mWrapper,
+                        mSurfaceControlWrapper, mChoreographer, mWrapper, mStatsLog,
                         /* traceThresholdMissedFrames= */ 1,
                         /* traceThresholdFrameTimeMillis= */ -1,
                         /* FrameTrackerListener= */ null, config));
@@ -139,7 +146,7 @@ public class FrameTrackerTest {
         sendFirstWindowFrame(tracker, 100, JANK_APP_DEADLINE_MISSED, 100L);
 
         // send another frame with a short duration - should not be considered janky
-        sendFirstWindowFrame(tracker, 5, JANK_NONE, 101L);
+        sendFrame(tracker, 5, JANK_NONE, 101L);
 
         // end the trace session, the last janky frame is after the end() so is discarded.
         when(mChoreographer.getVsyncId()).thenReturn(102L);
@@ -149,6 +156,13 @@ public class FrameTrackerTest {
 
         verify(tracker).removeObservers();
         verify(tracker, never()).triggerPerfetto();
+        verify(mStatsLog).write(eq(UI_INTERACTION_FRAME_INFO_REPORTED),
+                eq(CUJ_TO_STATSD_INTERACTION_TYPE[CUJ_NOTIFICATION_SHADE_EXPAND_COLLAPSE]),
+                eq(2L) /* totalFrames */,
+                eq(0L) /* missedFrames */,
+                eq(5000000L) /* maxFrameTimeNanos */,
+                eq(0L) /* missedSfFramesCount */,
+                eq(0L) /* missedAppFramesCount */);
     }
 
     @Test
@@ -175,6 +189,14 @@ public class FrameTrackerTest {
 
         // We detected a janky frame - trigger Perfetto
         verify(tracker).triggerPerfetto();
+
+        verify(mStatsLog).write(eq(UI_INTERACTION_FRAME_INFO_REPORTED),
+                eq(CUJ_TO_STATSD_INTERACTION_TYPE[CUJ_NOTIFICATION_SHADE_EXPAND_COLLAPSE]),
+                eq(2L) /* totalFrames */,
+                eq(1L) /* missedFrames */,
+                eq(40000000L) /* maxFrameTimeNanos */,
+                eq(1L) /* missedSfFramesCount */,
+                eq(0L) /* missedAppFramesCount */);
     }
 
     @Test
@@ -201,6 +223,14 @@ public class FrameTrackerTest {
 
         // We detected a janky frame - trigger Perfetto
         verify(tracker, never()).triggerPerfetto();
+
+        verify(mStatsLog).write(eq(UI_INTERACTION_FRAME_INFO_REPORTED),
+                eq(CUJ_TO_STATSD_INTERACTION_TYPE[CUJ_NOTIFICATION_SHADE_EXPAND_COLLAPSE]),
+                eq(2L) /* totalFrames */,
+                eq(0L) /* missedFrames */,
+                eq(4000000L) /* maxFrameTimeNanos */,
+                eq(0L) /* missedSfFramesCount */,
+                eq(0L) /* missedAppFramesCount */);
     }
 
     @Test
@@ -227,6 +257,14 @@ public class FrameTrackerTest {
 
         // We detected a janky frame - trigger Perfetto
         verify(tracker).triggerPerfetto();
+
+        verify(mStatsLog).write(eq(UI_INTERACTION_FRAME_INFO_REPORTED),
+                eq(CUJ_TO_STATSD_INTERACTION_TYPE[CUJ_NOTIFICATION_SHADE_EXPAND_COLLAPSE]),
+                eq(2L) /* totalFrames */,
+                eq(1L) /* missedFrames */,
+                eq(40000000L) /* maxFrameTimeNanos */,
+                eq(0L) /* missedSfFramesCount */,
+                eq(1L) /* missedAppFramesCount */);
     }
 
     @Test
@@ -256,6 +294,53 @@ public class FrameTrackerTest {
 
         // We detected a janky frame - trigger Perfetto
         verify(tracker).triggerPerfetto();
+
+        verify(mStatsLog).write(eq(UI_INTERACTION_FRAME_INFO_REPORTED),
+                eq(CUJ_TO_STATSD_INTERACTION_TYPE[CUJ_NOTIFICATION_SHADE_EXPAND_COLLAPSE]),
+                eq(2L) /* totalFrames */,
+                eq(1L) /* missedFrames */,
+                eq(50000000L) /* maxFrameTimeNanos */,
+                eq(0L) /* missedSfFramesCount */,
+                eq(1L) /* missedAppFramesCount */);
+    }
+
+    /**
+     * b/223787365
+     */
+    @Test
+    public void testNoOvercountingAfterEnd() {
+        FrameTracker tracker = spyFrameTracker(
+                CUJ_NOTIFICATION_SHADE_EXPAND_COLLAPSE, CUJ_POSTFIX, /* surfaceOnly= */ false);
+
+        when(mChoreographer.getVsyncId()).thenReturn(100L);
+        tracker.begin();
+        verify(mRenderer, only()).addObserver(any());
+
+        // send first frame - not janky
+        sendFrame(tracker, 4, JANK_NONE, 100L);
+
+        // send another frame - not janky
+        sendFrame(tracker, 4, JANK_NONE, 101L);
+
+        // end the trace session, simulate one more valid callback came after the end call.
+        when(mChoreographer.getVsyncId()).thenReturn(102L);
+        tracker.end(FrameTracker.REASON_END_NORMAL);
+
+        // Send incomplete callback for 102L
+        sendSfFrame(102L, JANK_NONE);
+
+        // Send janky but complete callbck fo 103L
+        sendFrame(tracker, 50, JANK_APP_DEADLINE_MISSED, 103L);
+
+        verify(tracker).removeObservers();
+        verify(tracker, never()).triggerPerfetto();
+        verify(mStatsLog).write(eq(UI_INTERACTION_FRAME_INFO_REPORTED),
+                eq(CUJ_TO_STATSD_INTERACTION_TYPE[CUJ_NOTIFICATION_SHADE_EXPAND_COLLAPSE]),
+                eq(2L) /* totalFrames */,
+                eq(0L) /* missedFrames */,
+                eq(4000000L) /* maxFrameTimeNanos */,
+                eq(0L) /* missedSfFramesCount */,
+                eq(0L) /* missedAppFramesCount */);
     }
 
     @Test
@@ -370,6 +455,14 @@ public class FrameTrackerTest {
 
         verify(mSurfaceControlWrapper).removeJankStatsListener(any());
         verify(tracker).triggerPerfetto();
+
+        verify(mStatsLog).write(eq(UI_INTERACTION_FRAME_INFO_REPORTED),
+                eq(CUJ_TO_STATSD_INTERACTION_TYPE[CUJ_WALLPAPER_TRANSITION]),
+                eq(2L) /* totalFrames */,
+                eq(1L) /* missedFrames */,
+                eq(0L) /* maxFrameTimeNanos */,
+                eq(0L) /* missedSfFramesCount */,
+                eq(1L) /* missedAppFramesCount */);
     }
 
     @Test
@@ -396,6 +489,14 @@ public class FrameTrackerTest {
 
         verify(mSurfaceControlWrapper).removeJankStatsListener(any());
         verify(tracker, never()).triggerPerfetto();
+
+        verify(mStatsLog).write(eq(UI_INTERACTION_FRAME_INFO_REPORTED),
+                eq(CUJ_TO_STATSD_INTERACTION_TYPE[CUJ_WALLPAPER_TRANSITION]),
+                eq(2L) /* totalFrames */,
+                eq(0L) /* missedFrames */,
+                eq(0L) /* maxFrameTimeNanos */,
+                eq(0L) /* missedSfFramesCount */,
+                eq(0L) /* missedAppFramesCount */);
     }
 
     @Test
@@ -422,6 +523,14 @@ public class FrameTrackerTest {
 
         verify(mSurfaceControlWrapper).removeJankStatsListener(any());
         verify(tracker, never()).triggerPerfetto();
+
+        verify(mStatsLog).write(eq(UI_INTERACTION_FRAME_INFO_REPORTED),
+                eq(CUJ_TO_STATSD_INTERACTION_TYPE[CUJ_WALLPAPER_TRANSITION]),
+                eq(2L) /* totalFrames */,
+                eq(0L) /* missedFrames */,
+                eq(0L) /* maxFrameTimeNanos */,
+                eq(0L) /* missedSfFramesCount */,
+                eq(0L) /* missedAppFramesCount */);
     }
 
     private void sendFirstWindowFrame(FrameTracker tracker, long durationMillis,
@@ -445,13 +554,22 @@ public class FrameTrackerTest {
     private void sendFrame(FrameTracker tracker, long durationMillis,
             @JankType int jankType, long vsyncId, boolean firstWindowFrame) {
         if (!tracker.mSurfaceOnly) {
-            when(mWrapper.getTiming()).thenReturn(new long[]{0, vsyncId});
+            sendHwuiFrame(tracker, durationMillis, vsyncId, firstWindowFrame);
-            doReturn(firstWindowFrame ? 1L : 0L).when(mWrapper)
-                    .getMetric(FrameMetrics.FIRST_DRAW_FRAME);
-            doReturn(TimeUnit.MILLISECONDS.toNanos(durationMillis))
-                    .when(mWrapper).getMetric(FrameMetrics.TOTAL_DURATION);
-            tracker.onFrameMetricsAvailable(0);
         }
+        sendSfFrame(vsyncId, jankType);
+    }
+
+    private void sendHwuiFrame(FrameTracker tracker, long durationMillis, long vsyncId,
+            boolean firstWindowFrame) {
+        when(mWrapper.getTiming()).thenReturn(new long[]{0, vsyncId});
+        doReturn(firstWindowFrame ? 1L : 0L).when(mWrapper)
+                .getMetric(FrameMetrics.FIRST_DRAW_FRAME);
+        doReturn(TimeUnit.MILLISECONDS.toNanos(durationMillis))
+                .when(mWrapper).getMetric(FrameMetrics.TOTAL_DURATION);
+        tracker.onFrameMetricsAvailable(0);
+    }
+
+    private void sendSfFrame(long vsyncId, @JankType int jankType) {
         mListenerCapture.getValue().onJankDataAvailable(new JankData[] {
                 new JankData(vsyncId, jankType)
         });

core/tests/coretests/src/com/android/internal/jank/InteractionJankMonitorTest.java

@@ -46,6 +46,7 @@ import androidx.test.rule.ActivityTestRule;
 
 import com.android.internal.jank.FrameTracker.ChoreographerWrapper;
 import com.android.internal.jank.FrameTracker.FrameMetricsWrapper;
+import com.android.internal.jank.FrameTracker.StatsLogWrapper;
 import com.android.internal.jank.FrameTracker.SurfaceControlWrapper;
 import com.android.internal.jank.FrameTracker.ThreadedRendererWrapper;
 import com.android.internal.jank.FrameTracker.ViewRootWrapper;
@@ -202,7 +203,8 @@ public class InteractionJankMonitorTest {
 
         FrameTracker tracker = spy(new FrameTracker(session, mWorker.getThreadHandler(),
                 threadedRenderer, viewRoot, surfaceControl, choreographer,
-                new FrameMetricsWrapper(), /* traceThresholdMissedFrames= */ 1,
+                new FrameMetricsWrapper(), new StatsLogWrapper(),
+                /* traceThresholdMissedFrames= */ 1,
                 /* traceThresholdFrameTimeMillis= */ -1, listener, configuration));
 
         doNothing().when(tracker).postTraceStartMarker();