Merge "Fix overcounting after end in case of incomplete callbacks" into tm-dev (cd106a5a) · Commits · e / os / android_frameworks_base

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

+33 −25

Original line number	Diff line number	Diff line
		@@ -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.
		*/

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

+2 −1

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

+126 −8

Original line number	Diff line number	Diff line
		@@ -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,6 +554,13 @@ public class FrameTrackerTest {
		private void sendFrame(FrameTracker tracker, long durationMillis,
		@JankType int jankType, long vsyncId, boolean firstWindowFrame) {
		if (!tracker.mSurfaceOnly) {
		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);
		@@ -452,6 +568,8 @@ public class FrameTrackerTest {
		.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

+3 −1

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