Merge "Report per-interaction frame statistics to statsd" (d64cb948) · Commits · e / os / android_frameworks_base

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

+33 −44

Original line number	Diff line number	Diff line
		@@ -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;
		}
		}

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

+22 −0

Original line number	Diff line number	Diff line
		@@ -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<String, FrameTracker> 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 + ">";
		}

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

+88 −34

Original line number	Diff line number	Diff line
		@@ -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();
		public void testIgnoresSecondBegin() {
		// Observer should be only added once in continuous calls.
		mTracker.begin();
		mTracker.begin();
		verify(mRenderer, only()).addObserver(any());
		}

		// 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();
		@Test
		public void testOnlyFirstFrameOverThreshold() {
		// Just provide current timestamp anytime mWrapper asked for VSYNC_TIMESTAMP
		when(mWrapper.getMetric(FrameMetrics.VSYNC_TIMESTAMP))
		.then(unusedInvocation -> System.nanoTime());

		// Should be safe.
		doReturn(TimeUnit.MILLISECONDS.toNanos(10L))
		.when(mWrapper).getMetric(FrameMetrics.TOTAL_DURATION);
		assertThat(mTracker.isJankyFrame(mWrapper)).isFalse();
		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);

		// 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();
		setupOtherFrameMockWithDuration(500);
		mTracker.onFrameMetricsAvailable(0);

		verify(mRenderer).removeObserver(any());
		verify(mTracker, never()).triggerPerfetto();
		}

		@Test
		public void testBeginEnd() {
		// assert the initial values
		assertThat(mTracker.mBeginTime).isEqualTo(FrameTracker.UNKNOWN_TIMESTAMP);
		assertThat(mTracker.mEndTime).isEqualTo(FrameTracker.UNKNOWN_TIMESTAMP);

		// Observer should be only added once in continuous calls.
		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());

		// assert the values after begin call.
		assertThat(mTracker.mBeginTime).isNotEqualTo(FrameTracker.UNKNOWN_TIMESTAMP);
		assertThat(mTracker.mEndTime).isEqualTo(FrameTracker.UNKNOWN_TIMESTAMP);
		// send first frame - not janky
		setupFirstFrameMockWithDuration(4);
		mTracker.onFrameMetricsAvailable(0);

		// 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());
		// send another frame - not janky
		setupOtherFrameMockWithDuration(4);
		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.
		// 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();
		doReturn(System.nanoTime()).when(mWrapper).getMetric(FrameMetrics.VSYNC_TIMESTAMP);
		assertThat(mTracker.mEndTime).isNotEqualTo(FrameTracker.UNKNOWN_TIMESTAMP);
		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);
		}
		}