Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit 7e9b844f authored by Jorim Jaggi's avatar Jorim Jaggi
Browse files

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
parent 82100c9d

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();