diff options
| author | 2022-07-14 20:45:08 +0000 | |
|---|---|---|
| committer | 2022-07-14 20:45:08 +0000 | |
| commit | de8e7777c89fe40780ea7c38d0f2138a188be239 (patch) | |
| tree | d89c1ae04781b77f2aa8b6dd8dac5c286c45e0bf | |
| parent | 092ed67e62e03c07f944fab3d3c49c4c72511a91 (diff) | |
| parent | 91a0bbdddf6d06626235b6f186c9950d165ae4fa (diff) | |
Merge "Ensure all FrameTracker invocation run on either main or ui thread" into tm-qpr-dev am: 91a0bbdddf
Original change: https://googleplex-android-review.googlesource.com/c/platform/frameworks/base/+/18654746
Change-Id: I2b159823f2952f1de43f11bdbeadfe6971767471
Signed-off-by: Automerger Merge Worker <android-build-automerger-merge-worker@system.gserviceaccount.com>
4 files changed, 375 insertions, 210 deletions
diff --git a/core/java/com/android/internal/jank/FrameTracker.java b/core/java/com/android/internal/jank/FrameTracker.java index 825b486d0635..dbfa4d35974b 100644 --- a/core/java/com/android/internal/jank/FrameTracker.java +++ b/core/java/com/android/internal/jank/FrameTracker.java @@ -26,10 +26,12 @@ import static android.view.SurfaceControl.JankData.SURFACE_FLINGER_SCHEDULING; import static com.android.internal.jank.InteractionJankMonitor.ACTION_SESSION_CANCEL; import static com.android.internal.jank.InteractionJankMonitor.ACTION_SESSION_END; +import static com.android.internal.jank.InteractionJankMonitor.EXECUTOR_TASK_TIMEOUT; import android.annotation.IntDef; import android.annotation.NonNull; import android.annotation.Nullable; +import android.annotation.UiThread; import android.graphics.HardwareRendererObserver; import android.os.Handler; import android.os.Trace; @@ -85,8 +87,9 @@ public class FrameTracker extends SurfaceControl.OnJankDataListener public @interface Reasons { } + @VisibleForTesting + public final InteractionJankMonitor mMonitor; private final HardwareRendererObserver mObserver; - private SurfaceControl mSurfaceControl; private final int mTraceThresholdMissedFrames; private final int mTraceThresholdFrameTimeMillis; private final ThreadedRendererWrapper mRendererWrapper; @@ -99,17 +102,17 @@ public class FrameTracker extends SurfaceControl.OnJankDataListener private final Handler mHandler; private final ChoreographerWrapper mChoreographer; private final StatsLogWrapper mStatsLog; - private final Object mLock = InteractionJankMonitor.getInstance().getLock(); private final boolean mDeferMonitoring; + private final FrameTrackerListener mListener; @VisibleForTesting public final boolean mSurfaceOnly; + private SurfaceControl mSurfaceControl; private long mBeginVsyncId = INVALID_ID; private long mEndVsyncId = INVALID_ID; private boolean mMetricsFinalized; private boolean mCancelled = false; - private FrameTrackerListener mListener; private boolean mTracingStarted = false; private Runnable mWaitForFinishTimedOut; @@ -142,16 +145,52 @@ public class FrameTracker extends SurfaceControl.OnJankDataListener this.jankType = jankType; this.isFirstFrame = isFirstFrame; } + + @Override + public String toString() { + StringBuilder str = new StringBuilder(); + switch (jankType) { + case JANK_NONE: + str.append("JANK_NONE"); + break; + case JANK_APP_DEADLINE_MISSED: + str.append("JANK_APP_DEADLINE_MISSED"); + break; + case JANK_SURFACEFLINGER_DEADLINE_MISSED: + str.append("JANK_SURFACEFLINGER_DEADLINE_MISSED"); + break; + case JANK_SURFACEFLINGER_GPU_DEADLINE_MISSED: + str.append("JANK_SURFACEFLINGER_GPU_DEADLINE_MISSED"); + break; + case DISPLAY_HAL: + str.append("DISPLAY_HAL"); + break; + case PREDICTION_ERROR: + str.append("PREDICTION_ERROR"); + break; + case SURFACE_FLINGER_SCHEDULING: + str.append("SURFACE_FLINGER_SCHEDULING"); + break; + default: + str.append("UNKNOWN: ").append(jankType); + break; + } + str.append(", ").append(frameVsyncId); + str.append(", ").append(totalDurationNanos); + return str.toString(); + } } - public FrameTracker(@NonNull Session session, @NonNull Handler handler, - @Nullable ThreadedRendererWrapper renderer, @Nullable ViewRootWrapper viewRootWrapper, + public FrameTracker(@NonNull InteractionJankMonitor monitor, @NonNull Session session, + @NonNull Handler handler, @Nullable ThreadedRendererWrapper renderer, + @Nullable ViewRootWrapper viewRootWrapper, @NonNull SurfaceControlWrapper surfaceControlWrapper, @NonNull ChoreographerWrapper choreographer, @Nullable FrameMetricsWrapper metrics, @NonNull StatsLogWrapper statsLog, int traceThresholdMissedFrames, int traceThresholdFrameTimeMillis, @Nullable FrameTrackerListener listener, @NonNull Configuration config) { + mMonitor = monitor; mSurfaceOnly = config.isSurfaceOnly(); mSession = session; mHandler = handler; @@ -186,17 +225,15 @@ public class FrameTracker extends SurfaceControl.OnJankDataListener mSurfaceChangedCallback = new ViewRootImpl.SurfaceChangedCallback() { @Override public void surfaceCreated(SurfaceControl.Transaction t) { - synchronized (mLock) { + getHandler().runWithScissors(() -> { if (mSurfaceControl == null) { mSurfaceControl = mViewRoot.getSurfaceControl(); if (mBeginVsyncId != INVALID_ID) { - mSurfaceControlWrapper.addJankStatsListener( - FrameTracker.this, mSurfaceControl); - markEvent("FT#deferMonitoring"); - postTraceStartMarker(); + // Previous begin invocation is not successfully, begin it again. + begin(); } } - } + }, EXECUTOR_TASK_TIMEOUT); } @Override @@ -208,18 +245,16 @@ public class FrameTracker extends SurfaceControl.OnJankDataListener // Wait a while to give the system a chance for the remaining // frames to arrive, then force finish the session. - mHandler.postDelayed(() -> { - synchronized (mLock) { - if (DEBUG) { - Log.d(TAG, "surfaceDestroyed: " + mSession.getName() - + ", finalized=" + mMetricsFinalized - + ", info=" + mJankInfos.size() - + ", vsync=" + mBeginVsyncId); - } - if (!mMetricsFinalized) { - end(REASON_END_SURFACE_DESTROYED); - finish(); - } + getHandler().postDelayed(() -> { + if (DEBUG) { + Log.d(TAG, "surfaceDestroyed: " + mSession.getName() + + ", finalized=" + mMetricsFinalized + + ", info=" + mJankInfos.size() + + ", vsync=" + mBeginVsyncId); + } + if (!mMetricsFinalized) { + end(REASON_END_SURFACE_DESTROYED); + finish(); } }, 50); } @@ -230,35 +265,42 @@ public class FrameTracker extends SurfaceControl.OnJankDataListener } } + @VisibleForTesting + public Handler getHandler() { + return mHandler; + } + /** * Begin a trace session of the CUJ. */ + @UiThread public void begin() { - synchronized (mLock) { - final long currentVsync = mChoreographer.getVsyncId(); - // In normal case, we should begin at the next frame, - // the id of the next frame is not simply increased by 1, - // but we can exclude the current frame at least. + final long currentVsync = mChoreographer.getVsyncId(); + // In normal case, we should begin at the next frame, + // the id of the next frame is not simply increased by 1, + // but we can exclude the current frame at least. + if (mBeginVsyncId == INVALID_ID) { mBeginVsyncId = mDeferMonitoring ? currentVsync + 1 : currentVsync; + } + if (mSurfaceControl != null) { if (DEBUG) { Log.d(TAG, "begin: " + mSession.getName() + ", begin=" + mBeginVsyncId - + ", defer=" + mDeferMonitoring); + + ", defer=" + mDeferMonitoring + ", current=" + currentVsync); } - if (mSurfaceControl != null) { - if (mDeferMonitoring) { - markEvent("FT#deferMonitoring"); - // Normal case, we begin the instrument from the very beginning, - // will exclude the first frame. - postTraceStartMarker(); - } else { - // If we don't begin the instrument from the very beginning, - // there is no need to skip the frame where the begin invocation happens. - beginInternal(); - } - mSurfaceControlWrapper.addJankStatsListener(this, mSurfaceControl); + if (mDeferMonitoring && currentVsync < mBeginVsyncId) { + markEvent("FT#deferMonitoring"); + // Normal case, we begin the instrument from the very beginning, + // will exclude the first frame. + postTraceStartMarker(this::beginInternal); + } else { + // If we don't begin the instrument from the very beginning, + // there is no need to skip the frame where the begin invocation happens. + beginInternal(); } - if (!mSurfaceOnly) { - mRendererWrapper.addObserver(mObserver); + } else { + if (DEBUG) { + Log.d(TAG, "begin: defer beginning since the surface is not ready for CUJ=" + + mSession.getName()); } } } @@ -267,89 +309,89 @@ public class FrameTracker extends SurfaceControl.OnJankDataListener * Start trace section at appropriate time. */ @VisibleForTesting - public void postTraceStartMarker() { - mChoreographer.mChoreographer.postCallback( - Choreographer.CALLBACK_INPUT, this::beginInternal, null); + public void postTraceStartMarker(Runnable action) { + mChoreographer.mChoreographer.postCallback(Choreographer.CALLBACK_INPUT, action, null); } + @UiThread private void beginInternal() { - synchronized (mLock) { - if (mCancelled || mEndVsyncId != INVALID_ID) { - return; - } - mTracingStarted = true; - markEvent("FT#begin"); - Trace.beginAsyncSection(mSession.getName(), (int) mBeginVsyncId); + if (mCancelled || mEndVsyncId != INVALID_ID) { + return; + } + mTracingStarted = true; + markEvent("FT#begin"); + Trace.beginAsyncSection(mSession.getName(), (int) mBeginVsyncId); + mSurfaceControlWrapper.addJankStatsListener(this, mSurfaceControl); + if (!mSurfaceOnly) { + mRendererWrapper.addObserver(mObserver); } } /** * End the trace session of the CUJ. */ + @UiThread public boolean end(@Reasons int reason) { - synchronized (mLock) { - if (mCancelled || mEndVsyncId != INVALID_ID) return false; - mEndVsyncId = mChoreographer.getVsyncId(); - // Cancel the session if: - // 1. The session begins and ends at the same vsync id. - // 2. The session never begun. - if (mBeginVsyncId == INVALID_ID) { - return cancel(REASON_CANCEL_NOT_BEGUN); - } else if (mEndVsyncId <= mBeginVsyncId) { - return cancel(REASON_CANCEL_SAME_VSYNC); - } else { - if (DEBUG) { - Log.d(TAG, "end: " + mSession.getName() - + ", end=" + mEndVsyncId + ", reason=" + reason); - } - markEvent("FT#end#" + reason); - Trace.endAsyncSection(mSession.getName(), (int) mBeginVsyncId); - mSession.setReason(reason); - - // We don't remove observer here, - // will remove it when all the frame metrics in this duration are called back. - // See onFrameMetricsAvailable for the logic of removing the observer. - // Waiting at most 10 seconds for all callbacks to finish. - mWaitForFinishTimedOut = () -> { - Log.e(TAG, "force finish cuj because of time out:" + mSession.getName()); - finish(); - }; - mHandler.postDelayed(mWaitForFinishTimedOut, TimeUnit.SECONDS.toMillis(10)); - notifyCujEvent(ACTION_SESSION_END); - return true; + if (mCancelled || mEndVsyncId != INVALID_ID) return false; + mEndVsyncId = mChoreographer.getVsyncId(); + // Cancel the session if: + // 1. The session begins and ends at the same vsync id. + // 2. The session never begun. + if (mBeginVsyncId == INVALID_ID) { + return cancel(REASON_CANCEL_NOT_BEGUN); + } else if (mEndVsyncId <= mBeginVsyncId) { + return cancel(REASON_CANCEL_SAME_VSYNC); + } else { + if (DEBUG) { + Log.d(TAG, "end: " + mSession.getName() + + ", end=" + mEndVsyncId + ", reason=" + reason); } + markEvent("FT#end#" + reason); + Trace.endAsyncSection(mSession.getName(), (int) mBeginVsyncId); + mSession.setReason(reason); + + // We don't remove observer here, + // will remove it when all the frame metrics in this duration are called back. + // See onFrameMetricsAvailable for the logic of removing the observer. + // Waiting at most 10 seconds for all callbacks to finish. + mWaitForFinishTimedOut = () -> { + Log.e(TAG, "force finish cuj because of time out:" + mSession.getName()); + finish(); + }; + getHandler().postDelayed(mWaitForFinishTimedOut, TimeUnit.SECONDS.toMillis(10)); + notifyCujEvent(ACTION_SESSION_END); + return true; } } /** * Cancel the trace session of the CUJ. */ + @UiThread public boolean cancel(@Reasons int reason) { - synchronized (mLock) { - final boolean cancelFromEnd = - reason == REASON_CANCEL_NOT_BEGUN || reason == REASON_CANCEL_SAME_VSYNC; - if (mCancelled || (mEndVsyncId != INVALID_ID && !cancelFromEnd)) return false; - mCancelled = true; - markEvent("FT#cancel#" + reason); - // We don't need to end the trace section if it never begun. - if (mTracingStarted) { - Trace.endAsyncSection(mSession.getName(), (int) mBeginVsyncId); - } - - // Always remove the observers in cancel call to avoid leakage. - removeObservers(); + final boolean cancelFromEnd = + reason == REASON_CANCEL_NOT_BEGUN || reason == REASON_CANCEL_SAME_VSYNC; + if (mCancelled || (mEndVsyncId != INVALID_ID && !cancelFromEnd)) return false; + mCancelled = true; + markEvent("FT#cancel#" + reason); + // We don't need to end the trace section if it has never begun. + if (mTracingStarted) { + Trace.endAsyncSection(mSession.getName(), (int) mBeginVsyncId); + } - if (DEBUG) { - Log.d(TAG, "cancel: " + mSession.getName() + ", begin=" + mBeginVsyncId - + ", end=" + mEndVsyncId + ", reason=" + reason); - } + // Always remove the observers in cancel call to avoid leakage. + removeObservers(); - mSession.setReason(reason); - // Notify the listener the session has been cancelled. - // We don't notify the listeners if the session never begun. - notifyCujEvent(ACTION_SESSION_CANCEL); - return true; + 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. + notifyCujEvent(ACTION_SESSION_CANCEL); + return true; } private void markEvent(String desc) { @@ -364,8 +406,8 @@ public class FrameTracker extends SurfaceControl.OnJankDataListener @Override public void onJankDataAvailable(SurfaceControl.JankData[] jankData) { - synchronized (mLock) { - if (mCancelled) { + postCallback(() -> { + if (mCancelled || mMetricsFinalized) { return; } @@ -384,10 +426,19 @@ public class FrameTracker extends SurfaceControl.OnJankDataListener } } processJankInfos(); - } + }); } - private @Nullable JankInfo findJankInfo(long frameVsyncId) { + /** + * For easier argument capture. + */ + @VisibleForTesting + public void postCallback(Runnable callback) { + getHandler().post(callback); + } + + @Nullable + private JankInfo findJankInfo(long frameVsyncId) { return mJankInfos.get((int) frameVsyncId); } @@ -400,8 +451,8 @@ public class FrameTracker extends SurfaceControl.OnJankDataListener @Override public void onFrameMetricsAvailable(int dropCountSinceLastInvocation) { - synchronized (mLock) { - if (mCancelled) { + postCallback(() -> { + if (mCancelled || mMetricsFinalized) { return; } @@ -426,9 +477,10 @@ public class FrameTracker extends SurfaceControl.OnJankDataListener frameVsyncId, totalDurationNanos, isFirstFrame)); } processJankInfos(); - } + }); } + @UiThread private boolean hasReceivedCallbacksAfterEnd() { if (mEndVsyncId == INVALID_ID) { return false; @@ -451,6 +503,7 @@ public class FrameTracker extends SurfaceControl.OnJankDataListener return false; } + @UiThread private void processJankInfos() { if (mMetricsFinalized) { return; @@ -467,9 +520,12 @@ public class FrameTracker extends SurfaceControl.OnJankDataListener : info.hwuiCallbackFired && info.surfaceControlCallbackFired; } + @UiThread private void finish() { - mHandler.removeCallbacks(mWaitForFinishTimedOut); + getHandler().removeCallbacks(mWaitForFinishTimedOut); mWaitForFinishTimedOut = null; + if (mMetricsFinalized || mCancelled) return; + markEvent("FT#finish#" + mJankInfos.size()); mMetricsFinalized = true; // The tracing has been ended, remove the observer, see if need to trigger perfetto. @@ -496,7 +552,7 @@ public class FrameTracker extends SurfaceControl.OnJankDataListener totalFramesCount++; boolean missedFrame = false; if ((info.jankType & JANK_APP_DEADLINE_MISSED) != 0) { - Log.w(TAG, "Missed App frame:" + info.jankType); + Log.w(TAG, "Missed App frame:" + info + ", CUJ=" + mSession.getName()); missedAppFramesCount++; missedFrame = true; } @@ -505,7 +561,7 @@ public class FrameTracker extends SurfaceControl.OnJankDataListener || (info.jankType & JANK_SURFACEFLINGER_GPU_DEADLINE_MISSED) != 0 || (info.jankType & SURFACE_FLINGER_SCHEDULING) != 0 || (info.jankType & PREDICTION_ERROR) != 0) { - Log.w(TAG, "Missed SF frame:" + info.jankType); + Log.w(TAG, "Missed SF frame:" + info + ", CUJ=" + mSession.getName()); missedSfFramesCount++; missedFrame = true; } @@ -520,13 +576,15 @@ public class FrameTracker extends SurfaceControl.OnJankDataListener // TODO (b/174755489): Early latch currently gets fired way too often, so we have // to ignore it for now. if (!mSurfaceOnly && !info.hwuiCallbackFired) { - Log.w(TAG, "Missing HWUI jank callback for vsyncId: " + info.frameVsyncId); + Log.w(TAG, "Missing HWUI jank callback for vsyncId: " + info.frameVsyncId + + ", CUJ=" + mSession.getName()); } } if (!mSurfaceOnly && info.hwuiCallbackFired) { maxFrameTimeNanos = Math.max(info.totalDurationNanos, maxFrameTimeNanos); if (!info.surfaceControlCallbackFired) { - Log.w(TAG, "Missing SF jank callback for vsyncId: " + info.frameVsyncId); + Log.w(TAG, "Missing SF jank callback for vsyncId: " + info.frameVsyncId + + ", CUJ=" + mSession.getName()); } } } @@ -586,6 +644,7 @@ public class FrameTracker extends SurfaceControl.OnJankDataListener * Remove all the registered listeners, observers and callbacks. */ @VisibleForTesting + @UiThread public void removeObservers() { mSurfaceControlWrapper.removeJankStatsListener(this); if (!mSurfaceOnly) { @@ -601,7 +660,7 @@ public class FrameTracker extends SurfaceControl.OnJankDataListener * Trigger the prefetto daemon. */ public void triggerPerfetto() { - InteractionJankMonitor.getInstance().trigger(mSession); + mMonitor.trigger(mSession); } /** @@ -666,10 +725,18 @@ public class FrameTracker extends SurfaceControl.OnJankDataListener mViewRoot = viewRoot; } + /** + * {@link ViewRootImpl#addSurfaceChangedCallback(ViewRootImpl.SurfaceChangedCallback)} + * @param callback {@link ViewRootImpl.SurfaceChangedCallback} + */ public void addSurfaceChangedCallback(ViewRootImpl.SurfaceChangedCallback callback) { mViewRoot.addSurfaceChangedCallback(callback); } + /** + * {@link ViewRootImpl#removeSurfaceChangedCallback(ViewRootImpl.SurfaceChangedCallback)} + * @param callback {@link ViewRootImpl.SurfaceChangedCallback} + */ public void removeSurfaceChangedCallback(ViewRootImpl.SurfaceChangedCallback callback) { mViewRoot.removeSurfaceChangedCallback(callback); } diff --git a/core/java/com/android/internal/jank/InteractionJankMonitor.java b/core/java/com/android/internal/jank/InteractionJankMonitor.java index 2d669ab58473..8f10a5e3f049 100644 --- a/core/java/com/android/internal/jank/InteractionJankMonitor.java +++ b/core/java/com/android/internal/jank/InteractionJankMonitor.java @@ -86,8 +86,11 @@ import static com.android.internal.util.FrameworkStatsLog.UIINTERACTION_FRAME_IN import android.annotation.IntDef; import android.annotation.NonNull; +import android.annotation.UiThread; +import android.annotation.WorkerThread; import android.content.Context; import android.os.Build; +import android.os.Handler; import android.os.HandlerExecutor; import android.os.HandlerThread; import android.provider.DeviceConfig; @@ -98,6 +101,7 @@ import android.view.Choreographer; import android.view.SurfaceControl; import android.view.View; +import com.android.internal.annotations.GuardedBy; import com.android.internal.annotations.VisibleForTesting; import com.android.internal.jank.FrameTracker.ChoreographerWrapper; import com.android.internal.jank.FrameTracker.FrameMetricsWrapper; @@ -131,6 +135,7 @@ public class InteractionJankMonitor { private static final String DEFAULT_WORKER_NAME = TAG + "-Worker"; private static final long DEFAULT_TIMEOUT_MS = TimeUnit.SECONDS.toMillis(2L); + static final long EXECUTOR_TASK_TIMEOUT = 500; private static final String SETTINGS_ENABLED_KEY = "enabled"; private static final String SETTINGS_SAMPLING_INTERVAL_KEY = "sampling_interval"; private static final String SETTINGS_THRESHOLD_MISSED_FRAMES_KEY = @@ -290,13 +295,14 @@ public class InteractionJankMonitor { private final DeviceConfig.OnPropertiesChangedListener mPropertiesChangedListener = this::updateProperties; - private final FrameMetricsWrapper mMetrics; + @GuardedBy("mLock") private final SparseArray<FrameTracker> mRunningTrackers; + @GuardedBy("mLock") private final SparseArray<Runnable> mTimeoutActions; private final HandlerThread mWorker; private final Object mLock = new Object(); - private boolean mEnabled = DEFAULT_ENABLED; + private volatile boolean mEnabled = DEFAULT_ENABLED; private int mSamplingInterval = DEFAULT_SAMPLING_INTERVAL; private int mTraceThresholdMissedFrames = DEFAULT_TRACE_THRESHOLD_MISSED_FRAMES; private int mTraceThresholdFrameTimeMillis = DEFAULT_TRACE_THRESHOLD_FRAME_TIME_MILLIS; @@ -398,9 +404,7 @@ public class InteractionJankMonitor { mRunningTrackers = new SparseArray<>(); mTimeoutActions = new SparseArray<>(); mWorker = worker; - mMetrics = new FrameMetricsWrapper(); mWorker.start(); - mEnabled = DEFAULT_ENABLED; mSamplingInterval = DEFAULT_SAMPLING_INTERVAL; // Post initialization to the background in case we're running on the main @@ -413,10 +417,7 @@ public class InteractionJankMonitor { DeviceConfig.NAMESPACE_INTERACTION_JANK_MONITOR, new HandlerExecutor(mWorker.getThreadHandler()), mPropertiesChangedListener); - } - - Object getLock() { - return mLock; + mEnabled = DEFAULT_ENABLED; } /** @@ -433,27 +434,27 @@ public class InteractionJankMonitor { view == null ? null : new ThreadedRendererWrapper(view.getThreadedRenderer()); final ViewRootWrapper viewRoot = view == null ? null : new ViewRootWrapper(view.getViewRootImpl()); - final SurfaceControlWrapper surfaceControl = new SurfaceControlWrapper(); final ChoreographerWrapper choreographer = new ChoreographerWrapper(Choreographer.getInstance()); + final FrameTrackerListener eventsListener = (s, act) -> handleCujEvents(act, s); + final FrameMetricsWrapper frameMetrics = new FrameMetricsWrapper(); - synchronized (mLock) { - FrameTrackerListener eventsListener = (s, act) -> handleCujEvents(act, s); - return new FrameTracker(session, mWorker.getThreadHandler(), - threadedRenderer, viewRoot, surfaceControl, choreographer, - mMetrics, new FrameTracker.StatsLogWrapper(), - mTraceThresholdMissedFrames, mTraceThresholdFrameTimeMillis, - eventsListener, config); - } + return new FrameTracker(this, session, config.getHandler(), threadedRenderer, viewRoot, + surfaceControl, choreographer, frameMetrics, new FrameTracker.StatsLogWrapper(), + mTraceThresholdMissedFrames, mTraceThresholdFrameTimeMillis, + eventsListener, config); } + @UiThread private void handleCujEvents(String action, Session session) { // Clear the running and timeout tasks if the end / cancel was fired within the tracker. // Or we might have memory leaks. if (needRemoveTasks(action, session)) { - removeTimeout(session.getCuj()); - removeTracker(session.getCuj()); + getTracker(session.getCuj()).getHandler().runWithScissors(() -> { + removeTimeout(session.getCuj()); + removeTracker(session.getCuj()); + }, EXECUTOR_TASK_TIMEOUT); } } @@ -470,7 +471,7 @@ public class InteractionJankMonitor { synchronized (mLock) { Runnable timeout = mTimeoutActions.get(cujType); if (timeout != null) { - mWorker.getThreadHandler().removeCallbacks(timeout); + getTracker(cujType).getHandler().removeCallbacks(timeout); mTimeoutActions.remove(cujType); } } @@ -495,9 +496,7 @@ public class InteractionJankMonitor { */ public boolean begin(View v, @CujType int cujType) { try { - return beginInternal( - Configuration.Builder.withView(cujType, v) - .build()); + return begin(Configuration.Builder.withView(cujType, v)); } catch (IllegalArgumentException ex) { Log.d(TAG, "Build configuration failed!", ex); return false; @@ -508,35 +507,42 @@ public class InteractionJankMonitor { * Begins a trace session. * * @param builder the builder of the configurations for instrumenting the CUJ. - * @return boolean true if the tracker is started successfully, false otherwise. + * @return boolean true if the tracker is begun successfully, false otherwise. */ public boolean begin(@NonNull Configuration.Builder builder) { try { - return beginInternal(builder.build()); + final Configuration config = builder.build(); + final TrackerResult result = new TrackerResult(); + final boolean success = config.getHandler().runWithScissors( + () -> result.mResult = beginInternal(config), EXECUTOR_TASK_TIMEOUT); + if (!success) { + Log.d(TAG, "begin failed due to timeout, CUJ=" + getNameOfCuj(config.mCujType)); + return false; + } + return result.mResult; } catch (IllegalArgumentException ex) { Log.d(TAG, "Build configuration failed!", ex); return false; } } + @UiThread private boolean beginInternal(@NonNull Configuration conf) { - synchronized (mLock) { - int cujType = conf.mCujType; - if (!shouldMonitor(cujType)) return false; - FrameTracker tracker = getTracker(cujType); - // Skip subsequent calls if we already have an ongoing tracing. - if (tracker != null) return false; - - // begin a new trace session. - tracker = createFrameTracker(conf, new Session(cujType, conf.mTag)); - mRunningTrackers.put(cujType, tracker); - tracker.begin(); - - // Cancel the trace if we don't get an end() call in specified duration. - scheduleTimeoutAction( - cujType, conf.mTimeout, () -> cancel(cujType, REASON_CANCEL_TIMEOUT)); - return true; - } + int cujType = conf.mCujType; + if (!shouldMonitor(cujType)) return false; + FrameTracker tracker = getTracker(cujType); + // Skip subsequent calls if we already have an ongoing tracing. + if (tracker != null) return false; + + // begin a new trace session. + tracker = createFrameTracker(conf, new Session(cujType, conf.mTag)); + putTracker(cujType, tracker); + tracker.begin(); + + // Cancel the trace if we don't get an end() call in specified duration. + scheduleTimeoutAction( + cujType, conf.mTimeout, () -> cancel(cujType, REASON_CANCEL_TIMEOUT)); + return true; } /** @@ -565,8 +571,10 @@ public class InteractionJankMonitor { */ @VisibleForTesting public void scheduleTimeoutAction(@CujType int cuj, long timeout, Runnable action) { - mTimeoutActions.put(cuj, action); - mWorker.getThreadHandler().postDelayed(action, timeout); + synchronized (mLock) { + mTimeoutActions.put(cuj, action); + getTracker(cuj).getHandler().postDelayed(action, timeout); + } } /** @@ -576,18 +584,35 @@ public class InteractionJankMonitor { * @return boolean true if the tracker is ended successfully, false otherwise. */ public boolean end(@CujType int cujType) { - synchronized (mLock) { - // remove the timeout action first. - removeTimeout(cujType); - FrameTracker tracker = getTracker(cujType); - // Skip this call since we haven't started a trace yet. - if (tracker == null) return false; - // if the end call doesn't return true, another thread is handling end of the cuj. - if (tracker.end(REASON_END_NORMAL)) { - removeTracker(cujType); + FrameTracker tracker = getTracker(cujType); + // Skip this call since we haven't started a trace yet. + if (tracker == null) return false; + try { + final TrackerResult result = new TrackerResult(); + final boolean success = tracker.getHandler().runWithScissors( + () -> result.mResult = endInternal(cujType), EXECUTOR_TASK_TIMEOUT); + if (!success) { + Log.d(TAG, "end failed due to timeout, CUJ=" + getNameOfCuj(cujType)); + return false; } - return true; + return result.mResult; + } catch (IllegalArgumentException ex) { + Log.d(TAG, "Execute end task failed!", ex); + return false; + } + } + + @UiThread + private boolean endInternal(@CujType int cujType) { + // remove the timeout action first. + removeTimeout(cujType); + FrameTracker tracker = getTracker(cujType); + if (tracker == null) return false; + // if the end call doesn't return true, another thread is handling end of the cuj. + if (tracker.end(REASON_END_NORMAL)) { + removeTracker(cujType); } + return true; } /** @@ -606,39 +631,66 @@ public class InteractionJankMonitor { */ @VisibleForTesting public boolean cancel(@CujType int cujType, @Reasons int reason) { - synchronized (mLock) { - // remove the timeout action first. - removeTimeout(cujType); - FrameTracker tracker = getTracker(cujType); - // Skip this call since we haven't started a trace yet. - if (tracker == null) return false; - // if the cancel call doesn't return true, another thread is handling cancel of the cuj. - if (tracker.cancel(reason)) { - removeTracker(cujType); + FrameTracker tracker = getTracker(cujType); + // Skip this call since we haven't started a trace yet. + if (tracker == null) return false; + try { + final TrackerResult result = new TrackerResult(); + final boolean success = tracker.getHandler().runWithScissors( + () -> result.mResult = cancelInternal(cujType, reason), EXECUTOR_TASK_TIMEOUT); + if (!success) { + Log.d(TAG, "cancel failed due to timeout, CUJ=" + getNameOfCuj(cujType)); + return false; } - return true; + return result.mResult; + } catch (IllegalArgumentException ex) { + Log.d(TAG, "Execute cancel task failed!", ex); + return false; + } + } + + @UiThread + private boolean cancelInternal(@CujType int cujType, @Reasons int reason) { + // remove the timeout action first. + removeTimeout(cujType); + FrameTracker tracker = getTracker(cujType); + if (tracker == null) return false; + // if the cancel call doesn't return true, another thread is handling cancel of the cuj. + if (tracker.cancel(reason)) { + removeTracker(cujType); + } + return true; + } + + private void putTracker(@CujType int cuj, @NonNull FrameTracker tracker) { + synchronized (mLock) { + mRunningTrackers.put(cuj, tracker); } } private FrameTracker getTracker(@CujType int cuj) { - return mRunningTrackers.get(cuj); + synchronized (mLock) { + return mRunningTrackers.get(cuj); + } } private void removeTracker(@CujType int cuj) { - mRunningTrackers.remove(cuj); + synchronized (mLock) { + mRunningTrackers.remove(cuj); + } } + @WorkerThread private void updateProperties(DeviceConfig.Properties properties) { - synchronized (mLock) { - mSamplingInterval = properties.getInt(SETTINGS_SAMPLING_INTERVAL_KEY, - DEFAULT_SAMPLING_INTERVAL); - mEnabled = properties.getBoolean(SETTINGS_ENABLED_KEY, DEFAULT_ENABLED); - mTraceThresholdMissedFrames = properties.getInt(SETTINGS_THRESHOLD_MISSED_FRAMES_KEY, - DEFAULT_TRACE_THRESHOLD_MISSED_FRAMES); - mTraceThresholdFrameTimeMillis = properties.getInt( - SETTINGS_THRESHOLD_FRAME_TIME_MILLIS_KEY, - DEFAULT_TRACE_THRESHOLD_FRAME_TIME_MILLIS); - } + mSamplingInterval = properties.getInt(SETTINGS_SAMPLING_INTERVAL_KEY, + DEFAULT_SAMPLING_INTERVAL); + mTraceThresholdMissedFrames = properties.getInt(SETTINGS_THRESHOLD_MISSED_FRAMES_KEY, + DEFAULT_TRACE_THRESHOLD_MISSED_FRAMES); + mTraceThresholdFrameTimeMillis = properties.getInt( + SETTINGS_THRESHOLD_FRAME_TIME_MILLIS_KEY, + DEFAULT_TRACE_THRESHOLD_FRAME_TIME_MILLIS); + // The memory visibility is powered by the volatile field, mEnabled. + mEnabled = properties.getBoolean(SETTINGS_ENABLED_KEY, DEFAULT_ENABLED); } @VisibleForTesting @@ -814,6 +866,10 @@ public class InteractionJankMonitor { return "UNKNOWN"; } + private static class TrackerResult { + private boolean mResult; + } + /** * Configurations used while instrumenting the CUJ. <br/> * <b>It may refer to an attached view, don't use static reference for any purpose.</b> @@ -827,6 +883,7 @@ public class InteractionJankMonitor { private final SurfaceControl mSurfaceControl; private final @CujType int mCujType; private final boolean mDeferMonitor; + private final Handler mHandler; /** * A builder for building Configuration. {@link #setView(View)} is essential @@ -970,6 +1027,7 @@ public class InteractionJankMonitor { mSurfaceControl = surfaceControl; mDeferMonitor = deferMonitor; validate(); + mHandler = mSurfaceOnly ? mContext.getMainThreadHandler() : mView.getHandler(); } private void validate() { @@ -1018,20 +1076,25 @@ public class InteractionJankMonitor { return mSurfaceControl; } - View getView() { + @VisibleForTesting + /** + * @return a view which is attached to the view tree. + */ + public View getView() { return mView; } - Context getContext() { - return mContext; - } - /** * @return true if the monitoring should be deferred to the next frame, false otherwise. */ public boolean shouldDeferMonitor() { return mDeferMonitor; } + + @VisibleForTesting + public Handler getHandler() { + return mHandler; + } } /** @@ -1084,7 +1147,8 @@ public class InteractionJankMonitor { mReason = reason; } - public @Reasons int getReason() { + @Reasons + public int getReason() { return mReason; } } 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 09fc7ea6fffd..e068730e9bda 100644 --- a/core/tests/coretests/src/com/android/internal/jank/FrameTrackerTest.java +++ b/core/tests/coretests/src/com/android/internal/jank/FrameTrackerTest.java @@ -36,6 +36,7 @@ import static org.mockito.Mockito.doReturn; import static org.mockito.Mockito.mock; import static org.mockito.Mockito.never; import static org.mockito.Mockito.only; +import static org.mockito.Mockito.spy; import static org.mockito.Mockito.verify; import static org.mockito.Mockito.when; @@ -83,6 +84,7 @@ public class FrameTrackerTest { private StatsLogWrapper mStatsLog; private ArgumentCaptor<OnJankDataListener> mListenerCapture; private SurfaceControl mSurfaceControl; + private ArgumentCaptor<Runnable> mRunnableArgumentCaptor; @Before public void setup() { @@ -99,6 +101,8 @@ public class FrameTrackerTest { mSurfaceControl = new SurfaceControl.Builder().setName("Surface").build(); mViewRootWrapper = mock(ViewRootWrapper.class); when(mViewRootWrapper.getSurfaceControl()).thenReturn(mSurfaceControl); + doNothing().when(mViewRootWrapper).addSurfaceChangedCallback(any()); + doNothing().when(mViewRootWrapper).removeSurfaceChangedCallback(any()); mSurfaceControlWrapper = mock(SurfaceControlWrapper.class); mListenerCapture = ArgumentCaptor.forClass(OnJankDataListener.class); @@ -109,23 +113,29 @@ public class FrameTrackerTest { mChoreographer = mock(ChoreographerWrapper.class); mStatsLog = mock(StatsLogWrapper.class); + mRunnableArgumentCaptor = ArgumentCaptor.forClass(Runnable.class); } private FrameTracker spyFrameTracker(int cuj, String postfix, boolean surfaceOnly) { + InteractionJankMonitor monitor = mock(InteractionJankMonitor.class); Handler handler = mRule.getActivity().getMainThreadHandler(); Session session = new Session(cuj, postfix); Configuration config = mock(Configuration.class); when(config.isSurfaceOnly()).thenReturn(surfaceOnly); when(config.getSurfaceControl()).thenReturn(mSurfaceControl); when(config.shouldDeferMonitor()).thenReturn(true); + View view = mRule.getActivity().getWindow().getDecorView(); + Handler spyHandler = spy(new Handler(handler.getLooper())); + when(config.getView()).thenReturn(surfaceOnly ? null : view); + when(config.getHandler()).thenReturn(spyHandler); FrameTracker frameTracker = Mockito.spy( - new FrameTracker(session, handler, mRenderer, mViewRootWrapper, + new FrameTracker(monitor, session, spyHandler, mRenderer, mViewRootWrapper, mSurfaceControlWrapper, mChoreographer, mWrapper, mStatsLog, /* traceThresholdMissedFrames= */ 1, /* traceThresholdFrameTimeMillis= */ -1, /* FrameTrackerListener= */ null, config)); doNothing().when(frameTracker).triggerPerfetto(); - doNothing().when(frameTracker).postTraceStartMarker(); + doNothing().when(frameTracker).postTraceStartMarker(mRunnableArgumentCaptor.capture()); return frameTracker; } @@ -140,6 +150,7 @@ public class FrameTrackerTest { when(mChoreographer.getVsyncId()).thenReturn(100L); tracker.begin(); + mRunnableArgumentCaptor.getValue().run(); verify(mRenderer, only()).addObserver(any()); // send first frame with a long duration - should not be taken into account @@ -173,6 +184,7 @@ public class FrameTrackerTest { when(mChoreographer.getVsyncId()).thenReturn(100L); tracker.begin(); + mRunnableArgumentCaptor.getValue().run(); verify(mRenderer, only()).addObserver(any()); // send first frame - not janky @@ -208,6 +220,7 @@ public class FrameTrackerTest { when(mChoreographer.getVsyncId()).thenReturn(100L); tracker.begin(); + mRunnableArgumentCaptor.getValue().run(); verify(mRenderer, only()).addObserver(any()); // send first frame - janky @@ -243,6 +256,7 @@ public class FrameTrackerTest { when(mChoreographer.getVsyncId()).thenReturn(100L); tracker.begin(); + mRunnableArgumentCaptor.getValue().run(); verify(mRenderer, only()).addObserver(any()); // send first frame - not janky @@ -278,6 +292,7 @@ public class FrameTrackerTest { when(mChoreographer.getVsyncId()).thenReturn(100L); tracker.begin(); + mRunnableArgumentCaptor.getValue().run(); verify(mRenderer, only()).addObserver(any()); // send first frame - not janky @@ -319,6 +334,7 @@ public class FrameTrackerTest { when(mChoreographer.getVsyncId()).thenReturn(100L); tracker.begin(); + mRunnableArgumentCaptor.getValue().run(); verify(mRenderer, only()).addObserver(any()); // send first frame - not janky @@ -332,7 +348,7 @@ public class FrameTrackerTest { tracker.end(FrameTracker.REASON_END_NORMAL); // Send incomplete callback for 102L - sendSfFrame(102L, JANK_NONE); + sendSfFrame(tracker, 102L, JANK_NONE); // Send janky but complete callbck fo 103L sendFrame(tracker, 50, JANK_APP_DEADLINE_MISSED, 103L); @@ -356,6 +372,7 @@ public class FrameTrackerTest { when(mChoreographer.getVsyncId()).thenReturn(100L); tracker.begin(); + mRunnableArgumentCaptor.getValue().run(); verify(mRenderer).addObserver(any()); // First frame - not janky @@ -380,6 +397,7 @@ public class FrameTrackerTest { when(mChoreographer.getVsyncId()).thenReturn(100L); tracker.begin(); + mRunnableArgumentCaptor.getValue().run(); verify(mRenderer, only()).addObserver(any()); // end the trace session @@ -403,6 +421,7 @@ public class FrameTrackerTest { when(mChoreographer.getVsyncId()).thenReturn(100L); tracker.begin(); + mRunnableArgumentCaptor.getValue().run(); verify(mRenderer, only()).addObserver(any()); // end the trace session at the same vsync id, end vsync id will less than the begin one. @@ -444,6 +463,7 @@ public class FrameTrackerTest { when(mChoreographer.getVsyncId()).thenReturn(100L); tracker.begin(); + mRunnableArgumentCaptor.getValue().run(); verify(mSurfaceControlWrapper).addJankStatsListener(any(), any()); // First frame - not janky @@ -479,6 +499,7 @@ public class FrameTrackerTest { when(mChoreographer.getVsyncId()).thenReturn(100L); tracker.begin(); + mRunnableArgumentCaptor.getValue().run(); verify(mSurfaceControlWrapper).addJankStatsListener(any(), any()); // First frame - janky @@ -514,6 +535,7 @@ public class FrameTrackerTest { when(mChoreographer.getVsyncId()).thenReturn(100L); tracker.begin(); + mRunnableArgumentCaptor.getValue().run(); verify(mSurfaceControlWrapper).addJankStatsListener(any(), any()); // First frame - not janky @@ -548,6 +570,7 @@ public class FrameTrackerTest { CUJ_WALLPAPER_TRANSITION, CUJ_POSTFIX, /* surfaceOnly= */ true); when(mChoreographer.getVsyncId()).thenReturn(100L); tracker.begin(); + mRunnableArgumentCaptor.getValue().run(); verify(mSurfaceControlWrapper).addJankStatsListener(any(), any()); sendFrame(tracker, JANK_SURFACEFLINGER_DEADLINE_MISSED, 100L); sendFrame(tracker, JANK_SURFACEFLINGER_DEADLINE_MISSED, 101L); @@ -594,7 +617,7 @@ public class FrameTrackerTest { if (!tracker.mSurfaceOnly) { sendHwuiFrame(tracker, durationMillis, vsyncId, firstWindowFrame); } - sendSfFrame(vsyncId, jankType); + sendSfFrame(tracker, vsyncId, jankType); } private void sendHwuiFrame(FrameTracker tracker, long durationMillis, long vsyncId, @@ -604,12 +627,18 @@ public class FrameTrackerTest { .getMetric(FrameMetrics.FIRST_DRAW_FRAME); doReturn(TimeUnit.MILLISECONDS.toNanos(durationMillis)) .when(mWrapper).getMetric(FrameMetrics.TOTAL_DURATION); + final ArgumentCaptor<Runnable> captor = ArgumentCaptor.forClass(Runnable.class); + doNothing().when(tracker).postCallback(captor.capture()); tracker.onFrameMetricsAvailable(0); + captor.getValue().run(); } - private void sendSfFrame(long vsyncId, @JankType int jankType) { + private void sendSfFrame(FrameTracker tracker, long vsyncId, @JankType int jankType) { + final ArgumentCaptor<Runnable> captor = ArgumentCaptor.forClass(Runnable.class); + doNothing().when(tracker).postCallback(captor.capture()); mListenerCapture.getValue().onJankDataAvailable(new JankData[] { new JankData(vsyncId, jankType) }); + captor.getValue().run(); } } 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 5a6fd5317bbc..d96f041c13f8 100644 --- a/core/tests/coretests/src/com/android/internal/jank/InteractionJankMonitorTest.java +++ b/core/tests/coretests/src/com/android/internal/jank/InteractionJankMonitorTest.java @@ -93,7 +93,7 @@ public class InteractionJankMonitorTest { @Test public void testBeginEnd() { InteractionJankMonitor monitor = createMockedInteractionJankMonitor(); - FrameTracker tracker = createMockedFrameTracker(null); + FrameTracker tracker = createMockedFrameTracker(monitor, null); doReturn(tracker).when(monitor).createFrameTracker(any(), any()); doNothing().when(tracker).begin(); doReturn(true).when(tracker).end(anyInt()); @@ -134,7 +134,7 @@ public class InteractionJankMonitorTest { public void testBeginTimeout() { ArgumentCaptor<Runnable> captor = ArgumentCaptor.forClass(Runnable.class); InteractionJankMonitor monitor = createMockedInteractionJankMonitor(); - FrameTracker tracker = createMockedFrameTracker(null); + FrameTracker tracker = createMockedFrameTracker(monitor, null); doReturn(tracker).when(monitor).createFrameTracker(any(), any()); doNothing().when(tracker).begin(); doReturn(true).when(tracker).cancel(anyInt()); @@ -180,7 +180,8 @@ public class InteractionJankMonitorTest { return monitor; } - private FrameTracker createMockedFrameTracker(FrameTracker.FrameTrackerListener listener) { + private FrameTracker createMockedFrameTracker(InteractionJankMonitor monitor, + FrameTracker.FrameTrackerListener listener) { Session session = spy(new Session(CUJ_NOTIFICATION_SHADE_EXPAND_COLLAPSE, CUJ_POSTFIX)); doReturn(false).when(session).logToStatsd(); @@ -190,6 +191,7 @@ public class InteractionJankMonitorTest { ViewRootWrapper viewRoot = spy(new ViewRootWrapper(mView.getViewRootImpl())); doNothing().when(viewRoot).addSurfaceChangedCallback(any()); + doNothing().when(viewRoot).removeSurfaceChangedCallback(any()); SurfaceControlWrapper surfaceControl = mock(SurfaceControlWrapper.class); doNothing().when(surfaceControl).addJankStatsListener(any(), any()); @@ -200,15 +202,18 @@ public class InteractionJankMonitorTest { Configuration configuration = mock(Configuration.class); when(configuration.isSurfaceOnly()).thenReturn(false); + when(configuration.getView()).thenReturn(mView); + when(configuration.getHandler()).thenReturn(mView.getHandler()); - FrameTracker tracker = spy(new FrameTracker(session, mWorker.getThreadHandler(), + FrameTracker tracker = spy(new FrameTracker(monitor, session, mWorker.getThreadHandler(), threadedRenderer, viewRoot, surfaceControl, choreographer, new FrameMetricsWrapper(), new StatsLogWrapper(), /* traceThresholdMissedFrames= */ 1, /* traceThresholdFrameTimeMillis= */ -1, listener, configuration)); - doNothing().when(tracker).postTraceStartMarker(); + doNothing().when(tracker).postTraceStartMarker(any()); doNothing().when(tracker).triggerPerfetto(); + doReturn(configuration.getHandler()).when(tracker).getHandler(); return tracker; } |