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

Commit 7dbe6c19 authored by Jorim Jaggi's avatar Jorim Jaggi Committed by Automerger Merge Worker
Browse files

Merge "Fix overcounting after end in case of incomplete callbacks" into tm-dev am: cd106a5a 

Original change: https://googleplex-android-review.googlesource.com/c/platform/frameworks/base/+/17392823



Change-Id: I36d7940b25b60c68b2a5ad69233ef0cc2cc6fc7b
Signed-off-by: default avatarAutomerger Merge Worker <android-build-automerger-merge-worker@system.gserviceaccount.com>
parents 9d9beb3c cd106a5a

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