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

Commit c35810dd authored by Ahan Wu's avatar Ahan Wu
Browse files

End the trace section while the surface has destroyed 

- Also invoke end method in surfaceDestroyed.
- Add debug logs

Bug: 183348579
Test: atest FrameworksCoreTests:InteractionJankMonitorTest
Test: atest FrameworksCoreTests:FrameTrackerTest
Test: Check the pftrace file
Change-Id: Ic3ab5212bd1d5a828ef6605814dafa4ecca3df0d
parent f7923a9c

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

+58 −6
Original line number Diff line number Diff line
@@ -26,7 +26,9 @@ import static android.view.SurfaceControl.JankData.SURFACE_FLINGER_SCHEDULING; 


import static com.android.internal.jank.InteractionJankMonitor.ACTION_METRICS_LOGGED;

import static com.android.internal.jank.InteractionJankMonitor.ACTION_SESSION_BEGIN;

import static com.android.internal.jank.InteractionJankMonitor.ACTION_SESSION_CANCEL;



import android.annotation.IntDef;

import android.annotation.NonNull;

import android.annotation.Nullable;

import android.graphics.HardwareRendererObserver;
@@ -45,6 +47,9 @@ import com.android.internal.annotations.VisibleForTesting; 
import com.android.internal.jank.InteractionJankMonitor.Session;

import com.android.internal.util.FrameworkStatsLog;



import java.lang.annotation.Retention;

import java.lang.annotation.RetentionPolicy;



/**

 * A class that allows the app to get the frame metrics from HardwareRendererObserver.

 * @hide
@@ -57,6 +62,26 @@ public class FrameTracker extends SurfaceControl.OnJankDataListener 
    private static final long INVALID_ID = -1;

    public static final int NANOS_IN_MILLISECOND = 1_000_000;



    static final int REASON_END_UNKNOWN = -1;

    static final int REASON_END_NORMAL = 0;

    static final int REASON_END_SURFACE_DESTROYED = 1;

    static final int REASON_CANCEL_NORMAL = 16;

    static final int REASON_CANCEL_NOT_BEGUN = 17;

    static final int REASON_CANCEL_SAME_VSYNC = 18;



    /** @hide */

    @IntDef({

            REASON_END_UNKNOWN,

            REASON_END_NORMAL,

            REASON_END_SURFACE_DESTROYED,

            REASON_CANCEL_NORMAL,

            REASON_CANCEL_NOT_BEGUN,

            REASON_CANCEL_SAME_VSYNC,

    })

    @Retention(RetentionPolicy.SOURCE)

    public @interface Reasons {

    }



    private final HardwareRendererObserver mObserver;

    private SurfaceControl mSurfaceControl;

    private final int mTraceThresholdMissedFrames;
@@ -156,7 +181,14 @@ public class FrameTracker extends SurfaceControl.OnJankDataListener 
                // force finish the session.

                mHandler.postDelayed(() -> {

                    synchronized (FrameTracker.this) {

                        if (DEBUG) {

                            Log.d(TAG, "surfaceDestroyed: " + mSession.getName()

                                    + ", finalized=" + mMetricsFinalized

                                    + ", info=" + mJankInfos.size()

                                    + ", vsync=" + mBeginVsyncId + "-" + mEndVsyncId);

                        }

                        if (!mMetricsFinalized) {

                            end(REASON_END_SURFACE_DESTROYED);

                            finish(mJankInfos.size() - 1);

                        }

                    }
@@ -176,6 +208,9 @@ public class FrameTracker extends SurfaceControl.OnJankDataListener 
        mSession.setTimeStamp(System.nanoTime());

        Trace.beginAsyncSection(mSession.getName(), (int) mBeginVsyncId);

        mRendererWrapper.addObserver(mObserver);

        if (DEBUG) {

            Log.d(TAG, "begin: " + mSession.getName() + ", begin=" + mBeginVsyncId);

        }

        if (mSurfaceControl != null) {

            mSurfaceControlWrapper.addJankStatsListener(this, mSurfaceControl);

        }
@@ -187,15 +222,25 @@ public class FrameTracker extends SurfaceControl.OnJankDataListener 
    /**

     * End the trace session of the CUJ.

     */

    public synchronized void end() {

    public synchronized void end(@Reasons int reason) {

        if (mEndVsyncId != INVALID_ID) return;

        mEndVsyncId = mChoreographer.getVsyncId();



        // Cancel the session if:

        // 1. The session begins and ends at the same vsync id.

        // 2. The session never begun.

        if (mEndVsyncId == mBeginVsyncId || mBeginVsyncId == INVALID_ID) {

            cancel();

        if (mBeginVsyncId == INVALID_ID) {

            cancel(REASON_CANCEL_NOT_BEGUN);

        } else if (mEndVsyncId == mBeginVsyncId) {

            cancel(REASON_CANCEL_SAME_VSYNC);

        } else {

            if (DEBUG) {

                Log.d(TAG, "end: " + mSession.getName()

                        + ", end=" + mEndVsyncId + ", reason=" + reason);

            }

            Trace.endAsyncSection(mSession.getName(), (int) mBeginVsyncId);

            mSession.setReason(reason);

            InteractionJankMonitor.getInstance().removeTimeout(mSession.getCuj());

        }

        // We don't remove observer here,

        // will remove it when all the frame metrics in this duration are called back.
@@ -205,7 +250,7 @@ public class FrameTracker extends SurfaceControl.OnJankDataListener 
    /**

     * Cancel the trace session of the CUJ.

     */

    public synchronized void cancel() {

    public synchronized void cancel(@Reasons int reason) {

        // We don't need to end the trace section if it never begun.

        if (mBeginVsyncId != INVALID_ID) {

            Trace.endAsyncSection(mSession.getName(), (int) mBeginVsyncId);
@@ -215,10 +260,16 @@ public class FrameTracker extends SurfaceControl.OnJankDataListener 
        // Always remove the observers in cancel call to avoid leakage.

        removeObservers();



        if (DEBUG) {

            Log.d(TAG, "cancel: " + mSession.getName()

                    + ", begin=" + mBeginVsyncId + ", end=" + mEndVsyncId + ", reason=" + reason);

        }



        mSession.setReason(reason);

        // Notify the listener the session has been cancelled.

        // We don't notify the listeners if the session never begun.

        if (mListener != null && mBeginVsyncId != INVALID_ID) {

            mListener.onNotifyCujEvents(mSession, InteractionJankMonitor.ACTION_SESSION_CANCEL);

        if (mListener != null) {

            mListener.onNotifyCujEvents(mSession, ACTION_SESSION_CANCEL);

        }

    }
@@ -399,6 +450,7 @@ public class FrameTracker extends SurfaceControl.OnJankDataListener 
        }

        if (DEBUG) {

            Log.i(TAG, "FrameTracker: CUJ=" + mSession.getName()

                    + " (" + mBeginVsyncId + "," + mEndVsyncId + ")"

                    + " totalFrames=" + totalFramesCount

                    + " missedAppFrames=" + missedAppFramesCount

                    + " missedSfFrames=" + missedSfFramesCounts

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

+30 −15
Original line number Diff line number Diff line
@@ -19,6 +19,7 @@ package com.android.internal.jank; 
import static android.content.Intent.FLAG_RECEIVER_REGISTERED_ONLY;



import static com.android.internal.jank.FrameTracker.ChoreographerWrapper;

import static com.android.internal.jank.FrameTracker.REASON_CANCEL_NOT_BEGUN;

import static com.android.internal.jank.FrameTracker.SurfaceControlWrapper;

import static com.android.internal.util.FrameworkStatsLog.UIINTERACTION_FRAME_INFO_REPORTED__INTERACTION_TYPE__LAUNCHER_ALL_APPS_SCROLL;

import static com.android.internal.util.FrameworkStatsLog.UIINTERACTION_FRAME_INFO_REPORTED__INTERACTION_TYPE__LAUNCHER_APP_CLOSE_TO_HOME;
@@ -104,7 +105,7 @@ public class InteractionJankMonitor { 
    public static final String BUNDLE_KEY_CUJ_NAME = ACTION_PREFIX + ".CUJ_NAME";

    public static final String BUNDLE_KEY_TIMESTAMP = ACTION_PREFIX + ".TIMESTAMP";

    @VisibleForTesting

    public static final String PROP_NOTIFY_CUJ_EVENT = "debug.notify_cuj_events";

    public static final String PROP_NOTIFY_CUJ_EVENT = "debug.jank.notify_cuj_events";



    // Every value must have a corresponding entry in CUJ_STATSD_INTERACTION_TYPE.

    public static final int CUJ_NOTIFICATION_SHADE_EXPAND_COLLAPSE = 0;
@@ -287,6 +288,10 @@ public class InteractionJankMonitor { 
    }



    private void notifyEvents(Context context, String action, Session session) {

        if (action.equals(ACTION_SESSION_CANCEL)

                && session.getReason() == REASON_CANCEL_NOT_BEGUN) {

            return;

        }

        Intent intent = new Intent(action);

        intent.putExtra(BUNDLE_KEY_CUJ_NAME, getNameOfCuj(session.getCuj()));

        intent.putExtra(BUNDLE_KEY_TIMESTAMP, session.getTimeStamp());
@@ -294,6 +299,16 @@ public class InteractionJankMonitor { 
        context.sendBroadcast(intent);

    }



    void removeTimeout(@CujType int cujType) {

        synchronized (this) {

            Runnable timeout = mTimeoutActions.get(cujType);

            if (timeout != null) {

                mWorker.getThreadHandler().removeCallbacks(timeout);

                mTimeoutActions.remove(cujType);

            }

        }

    }



    /**

     * Begin a trace session.

     *
@@ -351,16 +366,11 @@ public class InteractionJankMonitor { 
        synchronized (this) {



            // remove the timeout action first.

            Runnable timeout = mTimeoutActions.get(cujType);

            if (timeout != null) {

                mWorker.getThreadHandler().removeCallbacks(timeout);

                mTimeoutActions.remove(cujType);

            }



            removeTimeout(cujType);

            FrameTracker tracker = getTracker(cujType);

            // Skip this call since we haven't started a trace yet.

            if (tracker == null) return false;

            tracker.end();

            tracker.end(FrameTracker.REASON_END_NORMAL);

            mRunningTrackers.remove(cujType);

            return true;

        }
@@ -375,16 +385,11 @@ public class InteractionJankMonitor { 
        //TODO (163505250): This should be no-op if not in droid food rom.

        synchronized (this) {

            // remove the timeout action first.

            Runnable timeout = mTimeoutActions.get(cujType);

            if (timeout != null) {

                mWorker.getThreadHandler().removeCallbacks(timeout);

                mTimeoutActions.remove(cujType);

            }



            removeTimeout(cujType);

            FrameTracker tracker = getTracker(cujType);

            // Skip this call since we haven't started a trace yet.

            if (tracker == null) return false;

            tracker.cancel();

            tracker.cancel(FrameTracker.REASON_CANCEL_NORMAL);

            mRunningTrackers.remove(cujType);

            return true;

        }
@@ -509,6 +514,8 @@ public class InteractionJankMonitor { 
        @CujType

        private int mCujType;

        private long mTimeStamp;

        @FrameTracker.Reasons

        private int mReason = FrameTracker.REASON_END_UNKNOWN;



        public Session(@CujType int cujType) {

            mCujType = cujType;
@@ -543,5 +550,13 @@ public class InteractionJankMonitor { 
        public long getTimeStamp() {

            return mTimeStamp;

        }



        public void setReason(@FrameTracker.Reasons int reason) {

            mReason = reason;

        }



        public int getReason() {

            return mReason;

        }

    }

}

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

+10 −10
Original line number Diff line number Diff line
@@ -129,7 +129,7 @@ public class FrameTrackerTest { 


        // end the trace session, the last janky frame is after the end() so is discarded.

        when(mChoreographer.getVsyncId()).thenReturn(102L);

        mTracker.end();

        mTracker.end(FrameTracker.REASON_END_NORMAL);

        sendFrame(5, JANK_NONE, 102L);

        sendFrame(500, JANK_APP_DEADLINE_MISSED, 103L);
@@ -151,7 +151,7 @@ public class FrameTrackerTest { 


        // end the trace session

        when(mChoreographer.getVsyncId()).thenReturn(102L);

        mTracker.end();

        mTracker.end(FrameTracker.REASON_END_NORMAL);

        sendFrame(4, JANK_NONE, 102L);



        verify(mTracker).removeObservers();
@@ -174,7 +174,7 @@ public class FrameTrackerTest { 


        // end the trace session

        when(mChoreographer.getVsyncId()).thenReturn(102L);

        mTracker.end();

        mTracker.end(FrameTracker.REASON_END_NORMAL);

        sendFrame(4, JANK_NONE, 102L);



        verify(mTracker).removeObservers();
@@ -197,7 +197,7 @@ public class FrameTrackerTest { 


        // end the trace session

        when(mChoreographer.getVsyncId()).thenReturn(102L);

        mTracker.end();

        mTracker.end(FrameTracker.REASON_END_NORMAL);

        sendFrame(4, JANK_NONE, 102L);



        verify(mTracker).removeObservers();
@@ -220,7 +220,7 @@ public class FrameTrackerTest { 


        // end the trace session, simulate one more valid callback came after the end call.

        when(mChoreographer.getVsyncId()).thenReturn(102L);

        mTracker.end();

        mTracker.end(FrameTracker.REASON_END_NORMAL);

        sendFrame(50, JANK_APP_DEADLINE_MISSED, 102L);



        // One more callback with VSYNC after the end() vsync id.
@@ -247,7 +247,7 @@ public class FrameTrackerTest { 
        // a janky frame

        sendFrame(50, JANK_APP_DEADLINE_MISSED, 102L);



        mTracker.cancel();

        mTracker.cancel(FrameTracker.REASON_CANCEL_NORMAL);

        verify(mTracker).removeObservers();

        // Since the tracker has been cancelled, shouldn't trigger perfetto.

        verify(mTracker, never()).triggerPerfetto();
@@ -267,11 +267,11 @@ public class FrameTrackerTest { 


        // end the trace session

        when(mChoreographer.getVsyncId()).thenReturn(101L);

        mTracker.end();

        mTracker.end(FrameTracker.REASON_END_NORMAL);

        sendFrame(4, JANK_NONE, 102L);



        // Since the begin vsync id (101) equals to the end vsync id (101), will be treat as cancel.

        verify(mTracker).cancel();

        verify(mTracker).cancel(FrameTracker.REASON_CANCEL_SAME_VSYNC);



        // Observers should be removed in this case, or FrameTracker object will be leaked.

        verify(mTracker).removeObservers();
@@ -282,13 +282,13 @@ public class FrameTrackerTest { 


    @Test

    public void testCancelWhenSessionNeverBegun() {

        mTracker.cancel();

        mTracker.cancel(FrameTracker.REASON_CANCEL_NORMAL);

        verify(mTracker).removeObservers();

    }



    @Test

    public void testEndWhenSessionNeverBegun() {

        mTracker.end();

        mTracker.end(FrameTracker.REASON_END_NORMAL);

        verify(mTracker).removeObservers();

    }

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

+2 −2
Original line number Diff line number Diff line
@@ -103,7 +103,7 @@ public class InteractionJankMonitorTest { 
        assertThat(monitor.begin(mView, session.getCuj())).isTrue();

        verify(tracker).begin();

        assertThat(monitor.end(session.getCuj())).isTrue();

        verify(tracker).end();

        verify(tracker).end(FrameTracker.REASON_END_NORMAL);

    }



    @Test
@@ -154,7 +154,7 @@ public class InteractionJankMonitorTest { 
        assertThat(runnable).isNotNull();

        mWorker.getThreadHandler().removeCallbacks(runnable);

        runnable.run();

        verify(tracker).cancel();

        verify(tracker).cancel(FrameTracker.REASON_CANCEL_NORMAL);

    }



    @Test