Android/frameworks_base
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Ensure all FrameTracker invocation run on either main or ui thread

Browse Source 
FrameTracker has some ViewRootImpl invocations that it would be better
to make FrameTracker accesses run on either main or ui thread.

Bug: 200938639
Test: atest InteractionJankMonitorTest FrameTrackerTest
Change-Id: I91e9536293a694f3d110bda583a32b5918c96c55
This commit is contained in:
Ahan Wu
2022-04-15 14:54:39 +00:00
parent aec1a526b9
commit f7bd2bc6ba
4 changed files with 375 additions and 210 deletions
Download Patch File Download Diff File Expand all files Collapse all files

307
core/java/com/android/internal/jank/FrameTracker.java
View File

@@ -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();
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;
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);
}
// 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.
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);
}

224
core/java/com/android/internal/jank/InteractionJankMonitor.java
View File

@@ -85,8 +85,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;
@@ -97,6 +100,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;
@@ -130,6 +134,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 =
@@ -287,13 +292,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;
@@ -394,9 +400,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
@@ -409,10 +413,7 @@ public class InteractionJankMonitor {
DeviceConfig.NAMESPACE_INTERACTION_JANK_MONITOR,
new HandlerExecutor(mWorker.getThreadHandler()),
mPropertiesChangedListener);
}
Object getLock() {
return mLock;
mEnabled = DEFAULT_ENABLED;
}
/**
@@ -429,27 +430,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);
}
}
@@ -466,7 +467,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);
}
}
@@ -491,9 +492,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;
@@ -504,35 +503,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;
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();
// 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;
}
// 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;
}
/**
@@ -561,8 +567,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);
}
}
/**
@@ -572,20 +580,37 @@ 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;
}
/**
* Cancels the trace session.
*
@@ -602,39 +627,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
@@ -808,6 +860,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>
@@ -821,6 +877,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
@@ -964,6 +1021,7 @@ public class InteractionJankMonitor {
mSurfaceControl = surfaceControl;
mDeferMonitor = deferMonitor;
validate();
mHandler = mSurfaceOnly ? mContext.getMainThreadHandler() : mView.getHandler();
}
private void validate() {
@@ -1012,20 +1070,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;
}
}
/**
@@ -1078,7 +1141,8 @@ public class InteractionJankMonitor {
mReason = reason;
}
public @Reasons int getReason() {
@Reasons
public int getReason() {
return mReason;
}
}

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

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

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

@@ -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;
}