From d4430329bcc11602a8dbca6eb3fba69957e8bdb0 Mon Sep 17 00:00:00 2001 From: Marcin Oczeretko Date: Fri, 28 Aug 2020 14:25:50 +0100 Subject: [PATCH] Report per-interaction frame statistics to statsd Also reorganized the FrameTrackerTest a bit Bug: 162927074 Test: manual - statsd_testdrive to verify statsd logging + run FrameTrackerTest Change-Id: Iec1fcafcd6c8373ebdeebbbd829eb94967c2bfb8 --- .../android/internal/jank/FrameTracker.java | 77 +++++------ .../internal/jank/InteractionJankMonitor.java | 22 +++ .../internal/jank/FrameTrackerTest.java | 130 +++++++++++++----- 3 files changed, 147 insertions(+), 82 deletions(-) diff --git a/core/java/com/android/internal/jank/FrameTracker.java b/core/java/com/android/internal/jank/FrameTracker.java index f9a2ecc10dc83..e5c845059a0dd 100644 --- a/core/java/com/android/internal/jank/FrameTracker.java +++ b/core/java/com/android/internal/jank/FrameTracker.java @@ -26,6 +26,7 @@ import android.view.ThreadedRenderer; import com.android.internal.annotations.VisibleForTesting; import com.android.internal.jank.InteractionJankMonitor.Session; +import com.android.internal.util.FrameworkStatsLog; /** * @hide @@ -34,18 +35,19 @@ public class FrameTracker implements HardwareRendererObserver.OnFrameMetricsAvai private static final String TAG = FrameTracker.class.getSimpleName(); private static final boolean DEBUG = false; //TODO (163431584): need also consider other refresh rates. - private static final long CRITERIA = 1000000000 / 60; - @VisibleForTesting - public static final long UNKNOWN_TIMESTAMP = -1; + private static final long JANK_THRESHOLD_NANOS = 1000000000 / 60; + private static final long UNKNOWN_TIMESTAMP = -1; - @VisibleForTesting - public long mBeginTime = UNKNOWN_TIMESTAMP; - @VisibleForTesting - public long mEndTime = UNKNOWN_TIMESTAMP; - public boolean mShouldTriggerTrace; - public HardwareRendererObserver mObserver; - public ThreadedRendererWrapper mRendererWrapper; - public FrameMetricsWrapper mMetricsWrapper; + private final HardwareRendererObserver mObserver; + private final ThreadedRendererWrapper mRendererWrapper; + private final FrameMetricsWrapper mMetricsWrapper; + + private long mBeginTime = UNKNOWN_TIMESTAMP; + private long mEndTime = UNKNOWN_TIMESTAMP; + private boolean mShouldTriggerTrace; + private long mTotalFramesCount = 0; + private long mMissedFramesCount = 0; + private long mMaxFrameTimeNanos = 0; private Session mSession; @@ -108,37 +110,6 @@ public class FrameTracker implements HardwareRendererObserver.OnFrameMetricsAvai Trace.endAsyncSection(mSession.getName(), (int) mBeginTime); } - /** - * Check if we had a janky frame according to the metrics. - * @param metrics frame metrics - * @return true if it is a janky frame - */ - @VisibleForTesting - public boolean isJankyFrame(FrameMetricsWrapper metrics) { - long totalDurationMs = metrics.getMetric(FrameMetrics.TOTAL_DURATION); - boolean isFirstFrame = metrics.getMetric(FrameMetrics.FIRST_DRAW_FRAME) == 1; - boolean isJanky = !isFirstFrame && totalDurationMs - CRITERIA > 0; - - if (DEBUG) { - StringBuilder sb = new StringBuilder(); - sb.append(isJanky).append(","); - sb.append(metrics.getMetric(FrameMetrics.FIRST_DRAW_FRAME)).append(","); - sb.append(metrics.getMetric(FrameMetrics.INPUT_HANDLING_DURATION)).append(","); - sb.append(metrics.getMetric(FrameMetrics.ANIMATION_DURATION)).append(","); - sb.append(metrics.getMetric(FrameMetrics.LAYOUT_MEASURE_DURATION)).append(","); - sb.append(metrics.getMetric(FrameMetrics.DRAW_DURATION)).append(","); - sb.append(metrics.getMetric(FrameMetrics.SYNC_DURATION)).append(","); - sb.append(metrics.getMetric(FrameMetrics.COMMAND_ISSUE_DURATION)).append(","); - sb.append(metrics.getMetric(FrameMetrics.SWAP_BUFFERS_DURATION)).append(","); - sb.append(totalDurationMs).append(","); - sb.append(metrics.getMetric(FrameMetrics.INTENDED_VSYNC_TIMESTAMP)).append(","); - sb.append(metrics.getMetric(FrameMetrics.VSYNC_TIMESTAMP)).append(","); - Log.v(TAG, "metrics=" + sb.toString()); - } - - return isJanky; - } - @Override public void onFrameMetricsAvailable(int dropCountSinceLastInvocation) { // Since this callback might come a little bit late after the end() call. @@ -160,11 +131,29 @@ public class FrameTracker implements HardwareRendererObserver.OnFrameMetricsAvai } triggerPerfetto(); } + if (mSession.logToStatsd()) { + FrameworkStatsLog.write( + FrameworkStatsLog.UI_INTERACTION_FRAME_INFO_REPORTED, + mSession.getStatsdInteractionType(), + mTotalFramesCount, + mMissedFramesCount, + mMaxFrameTimeNanos); + } return; } - // The frame is in the duration of the CUJ, check if it catches the deadline. - if (isJankyFrame(mMetricsWrapper)) { + long totalDurationNanos = mMetricsWrapper.getMetric(FrameMetrics.TOTAL_DURATION); + boolean isFirstFrame = mMetricsWrapper.getMetric(FrameMetrics.FIRST_DRAW_FRAME) == 1; + boolean isJankyFrame = !isFirstFrame && totalDurationNanos > JANK_THRESHOLD_NANOS; + + mTotalFramesCount += 1; + + if (!isFirstFrame) { + mMaxFrameTimeNanos = Math.max(totalDurationNanos, mMaxFrameTimeNanos); + } + + if (isJankyFrame) { + mMissedFramesCount += 1; mShouldTriggerTrace = true; } } diff --git a/core/java/com/android/internal/jank/InteractionJankMonitor.java b/core/java/com/android/internal/jank/InteractionJankMonitor.java index 6bfb178bc1022..5a0cbf9e93e41 100644 --- a/core/java/com/android/internal/jank/InteractionJankMonitor.java +++ b/core/java/com/android/internal/jank/InteractionJankMonitor.java @@ -16,6 +16,8 @@ package com.android.internal.jank; +import static com.android.internal.util.FrameworkStatsLog.UIINTERACTION_FRAME_INFO_REPORTED__INTERACTION_TYPE__NOTIFICATION_SHADE_SWIPE; + import android.annotation.IntDef; import android.annotation.NonNull; import android.os.HandlerThread; @@ -37,9 +39,20 @@ public class InteractionJankMonitor { private static final String TAG = InteractionJankMonitor.class.getSimpleName(); private static final boolean DEBUG = false; private static final Object LOCK = new Object(); + + // Every value must have a corresponding entry in CUJ_STATSD_INTERACTION_TYPE. public static final int CUJ_NOTIFICATION_SHADE_MOTION = 0; public static final int CUJ_NOTIFICATION_SHADE_GESTURE = 1; + private static final int NO_STATSD_LOGGING = -1; + + // Used to convert CujType to InteractionType enum value for statsd logging. + // Use NO_STATSD_LOGGING in case the measurement for a given CUJ should not be logged to statsd. + private static final int[] CUJ_TO_STATSD_INTERACTION_TYPE = { + NO_STATSD_LOGGING, + UIINTERACTION_FRAME_INFO_REPORTED__INTERACTION_TYPE__NOTIFICATION_SHADE_SWIPE, + }; + private static ThreadedRenderer sRenderer; private static Map sRunningTracker; private static HandlerThread sWorker; @@ -173,6 +186,15 @@ public class InteractionJankMonitor { return mId; } + public int getStatsdInteractionType() { + return CUJ_TO_STATSD_INTERACTION_TYPE[mId]; + } + + /** Describes whether the measurement from this session should be written to statsd. */ + public boolean logToStatsd() { + return getStatsdInteractionType() != NO_STATSD_LOGGING; + } + public String getName() { return "CujType<" + mId + ">"; } 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 7480a200ee4e1..ece5037de15fc 100644 --- a/core/tests/coretests/src/com/android/internal/jank/FrameTrackerTest.java +++ b/core/tests/coretests/src/com/android/internal/jank/FrameTrackerTest.java @@ -23,8 +23,10 @@ import static com.google.common.truth.Truth.assertThat; import static org.mockito.ArgumentMatchers.any; import static org.mockito.Mockito.doNothing; import static org.mockito.Mockito.doReturn; +import static org.mockito.Mockito.never; import static org.mockito.Mockito.only; import static org.mockito.Mockito.verify; +import static org.mockito.Mockito.when; import android.os.Handler; import android.view.FrameMetrics; @@ -66,6 +68,9 @@ public class FrameTrackerTest { Handler handler = mRule.getActivity().getMainThreadHandler(); mWrapper = Mockito.spy(new FrameMetricsWrapper()); + // For simplicity - provide current timestamp anytime mWrapper asked for VSYNC_TIMESTAMP + when(mWrapper.getMetric(FrameMetrics.VSYNC_TIMESTAMP)) + .then(unusedInvocation -> System.nanoTime()); mRenderer = Mockito.spy(new ThreadedRendererWrapper(view.getThreadedRenderer())); doNothing().when(mRenderer).addObserver(any()); doNothing().when(mRenderer).removeObserver(any()); @@ -76,55 +81,104 @@ public class FrameTrackerTest { } @Test - public void testIsJankyFrame() { - // We skip the first frame. - doReturn(1L).when(mWrapper).getMetric(FrameMetrics.FIRST_DRAW_FRAME); - doReturn(TimeUnit.MILLISECONDS.toNanos(20L)) - .when(mWrapper).getMetric(FrameMetrics.TOTAL_DURATION); - assertThat(mTracker.isJankyFrame(mWrapper)).isFalse(); - - // Should exceed the criteria. - doReturn(0L).when(mWrapper).getMetric(FrameMetrics.FIRST_DRAW_FRAME); - doReturn(TimeUnit.MILLISECONDS.toNanos(20L)) - .when(mWrapper).getMetric(FrameMetrics.TOTAL_DURATION); - assertThat(mTracker.isJankyFrame(mWrapper)).isTrue(); - - // Should be safe. - doReturn(TimeUnit.MILLISECONDS.toNanos(10L)) - .when(mWrapper).getMetric(FrameMetrics.TOTAL_DURATION); - assertThat(mTracker.isJankyFrame(mWrapper)).isFalse(); - } - - @Test - public void testBeginEnd() { - // assert the initial values - assertThat(mTracker.mBeginTime).isEqualTo(FrameTracker.UNKNOWN_TIMESTAMP); - assertThat(mTracker.mEndTime).isEqualTo(FrameTracker.UNKNOWN_TIMESTAMP); - + public void testIgnoresSecondBegin() { // Observer should be only added once in continuous calls. mTracker.begin(); mTracker.begin(); verify(mRenderer, only()).addObserver(any()); + } - // assert the values after begin call. - assertThat(mTracker.mBeginTime).isNotEqualTo(FrameTracker.UNKNOWN_TIMESTAMP); - assertThat(mTracker.mEndTime).isEqualTo(FrameTracker.UNKNOWN_TIMESTAMP); + @Test + public void testOnlyFirstFrameOverThreshold() { + // Just provide current timestamp anytime mWrapper asked for VSYNC_TIMESTAMP + when(mWrapper.getMetric(FrameMetrics.VSYNC_TIMESTAMP)) + .then(unusedInvocation -> System.nanoTime()); - // simulate the callback during trace session - // assert the isJankyFrame should be invoked as well. - doReturn(System.nanoTime()).when(mWrapper).getMetric(FrameMetrics.VSYNC_TIMESTAMP); - doReturn(true).when(mTracker).isJankyFrame(any()); + mTracker.begin(); + verify(mRenderer, only()).addObserver(any()); + + // send first frame with a long duration - should not be taken into account + setupFirstFrameMockWithDuration(100); mTracker.onFrameMetricsAvailable(0); - verify(mTracker).isJankyFrame(any()); - // end the trace session, simulate a callback came after the end call. - // assert the end time should be set, the observer should be removed. - // triggerPerfetto should be invoked as well. + // send another frame with a short duration - should not be considered janky + setupOtherFrameMockWithDuration(5); + mTracker.onFrameMetricsAvailable(0); + + // end the trace session, the last janky frame is after the end() so is discarded. mTracker.end(); - doReturn(System.nanoTime()).when(mWrapper).getMetric(FrameMetrics.VSYNC_TIMESTAMP); - assertThat(mTracker.mEndTime).isNotEqualTo(FrameTracker.UNKNOWN_TIMESTAMP); + setupOtherFrameMockWithDuration(500); mTracker.onFrameMetricsAvailable(0); + verify(mRenderer).removeObserver(any()); + verify(mTracker, never()).triggerPerfetto(); + } + + @Test + public void testOtherFrameOverThreshold() { + mTracker.begin(); + verify(mRenderer, only()).addObserver(any()); + + // send first frame - not janky + setupFirstFrameMockWithDuration(4); + mTracker.onFrameMetricsAvailable(0); + + // send another frame - should be considered janky + setupOtherFrameMockWithDuration(40); + mTracker.onFrameMetricsAvailable(0); + + // end the trace session + mTracker.end(); + setupOtherFrameMockWithDuration(5); + mTracker.onFrameMetricsAvailable(0); + + verify(mRenderer).removeObserver(any()); + + // We detected a janky frame - trigger Perfetto verify(mTracker).triggerPerfetto(); } + + @Test + public void testLastFrameOverThresholdBeforeEnd() { + mTracker.begin(); + verify(mRenderer, only()).addObserver(any()); + + // send first frame - not janky + setupFirstFrameMockWithDuration(4); + mTracker.onFrameMetricsAvailable(0); + + // send another frame - not janky + setupOtherFrameMockWithDuration(4); + mTracker.onFrameMetricsAvailable(0); + + // end the trace session, simulate one more valid callback came after the end call. + when(mWrapper.getMetric(FrameMetrics.VSYNC_TIMESTAMP)) + .thenReturn(System.nanoTime()); + setupOtherFrameMockWithDuration(50); + mTracker.end(); + mTracker.onFrameMetricsAvailable(0); + + // One more callback with VSYNC after the end() timestamp. + when(mWrapper.getMetric(FrameMetrics.VSYNC_TIMESTAMP)) + .thenReturn(System.nanoTime()); + setupOtherFrameMockWithDuration(5); + mTracker.onFrameMetricsAvailable(0); + + verify(mRenderer).removeObserver(any()); + + // We detected a janky frame - trigger Perfetto + verify(mTracker).triggerPerfetto(); + } + + private void setupFirstFrameMockWithDuration(long durationMillis) { + doReturn(1L).when(mWrapper).getMetric(FrameMetrics.FIRST_DRAW_FRAME); + doReturn(TimeUnit.MILLISECONDS.toNanos(durationMillis)) + .when(mWrapper).getMetric(FrameMetrics.TOTAL_DURATION); + } + + private void setupOtherFrameMockWithDuration(long durationMillis) { + doReturn(0L).when(mWrapper).getMetric(FrameMetrics.FIRST_DRAW_FRAME); + doReturn(TimeUnit.MILLISECONDS.toNanos(durationMillis)) + .when(mWrapper).getMetric(FrameMetrics.TOTAL_DURATION); + } }