diff options
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 06bc4b56901a..4f51a5ba1bd1 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; + } + if (!hasReceivedCallbacksAfterEnd()) { return; } - finish(indexOnOrAfterEnd); + 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 5947e66b2d30..3da37f89f83e 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 7cd8197ce1e4..0f48465e0bdd 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<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}); - 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 a4091294aa70..5a6fd5317bbc 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(); |