From 7e9b844f52b53ccbb58122f8905fa7897df08efe Mon Sep 17 00:00:00 2001 From: Jorim Jaggi Date: Fri, 25 Mar 2022 01:01:55 +0100 Subject: [PATCH] Fix overcounting after end in case of incomplete callbacks The original intent of the code was to wait until we get one frame with end vsync id or beyond end vsync id with both HWUI and SF callbacks being reported such that we can ensure that our data collection is complete. However, the logic unintentionally started janky frames after the end in case there were callbacks missing on the end vsync id, leading to skewed metrics. Also expand unit tests to verify jank number results. Test: FrameTrackerTest Fixes: 223787365 Change-Id: I90948d9ab2d44bf805e78f5611e072a7cc9ae0cd --- .../android/internal/jank/FrameTracker.java | 58 ++++---- .../internal/jank/InteractionJankMonitor.java | 3 +- .../internal/jank/FrameTrackerTest.java | 134 ++++++++++++++++-- .../jank/InteractionJankMonitorTest.java | 4 +- 4 files changed, 164 insertions(+), 35 deletions(-) diff --git a/core/java/com/android/internal/jank/FrameTracker.java b/core/java/com/android/internal/jank/FrameTracker.java index 06bc4b56901a6..4f51a5ba1bd11 100644 --- a/core/java/com/android/internal/jank/FrameTracker.java +++ b/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 } } - /** - * Finds the first index in {@link #mJankInfos} which happened on or after {@link #mEndVsyncId}, - * or -1 if the session hasn't ended yet. - */ - private int getIndexOnOrAfterEnd() { - if (mEndVsyncId == INVALID_ID || mMetricsFinalized) { - return -1; + private boolean hasReceivedCallbacksAfterEnd() { + if (mEndVsyncId == INVALID_ID) { + return false; } 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)) { - lastIndex = i; + if (callbacksReceived(info)) { + return true; } - } else { - break; } } - return lastIndex; + return false; } private void processJankInfos() { - int indexOnOrAfterEnd = getIndexOnOrAfterEnd(); - if (indexOnOrAfterEnd == -1) { + if (mMetricsFinalized) { 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. */ diff --git a/core/java/com/android/internal/jank/InteractionJankMonitor.java b/core/java/com/android/internal/jank/InteractionJankMonitor.java index 5947e66b2d307..3da37f89f83e7 100644 --- a/core/java/com/android/internal/jank/InteractionJankMonitor.java +++ b/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); } diff --git a/core/tests/coretests/src/com/android/internal/jank/FrameTrackerTest.java b/core/tests/coretests/src/com/android/internal/jank/FrameTrackerTest.java index 7cd8197ce1e4e..0f48465e0bdd3 100644 --- a/core/tests/coretests/src/com/android/internal/jank/FrameTrackerTest.java +++ b/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 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}); - 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); + sendHwuiFrame(tracker, durationMillis, vsyncId, firstWindowFrame); } + 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) }); diff --git a/core/tests/coretests/src/com/android/internal/jank/InteractionJankMonitorTest.java b/core/tests/coretests/src/com/android/internal/jank/InteractionJankMonitorTest.java index a4091294aa707..5a6fd5317bbc4 100644 --- a/core/tests/coretests/src/com/android/internal/jank/InteractionJankMonitorTest.java +++ b/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();