Merge "Remove deadlock path between InteractionJankMonitor and FrameTracker" into sc-v2-dev am: 9de009c3a5 am: d9358f6fec

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

Change-Id: I3d4c9d4e3f96c68c7aa4ebac4235a528bb78f901

2 files changed, 184 insertions, 144 deletions

diff --git a/core/java/com/android/internal/jank/FrameTracker.java b/core/java/com/android/internal/jank/FrameTracker.java
index c863292d4ea0..d14054d4f9f7 100644
--- a/core/java/com/android/internal/jank/FrameTracker.java
+++ b/core/java/com/android/internal/jank/FrameTracker.java
@@ -99,6 +99,7 @@ public class FrameTracker extends SurfaceControl.OnJankDataListener
     private final ViewRootImpl.SurfaceChangedCallback mSurfaceChangedCallback;
     private final Handler mHandler;
     private final ChoreographerWrapper mChoreographer;
+    private final Object mLock = InteractionJankMonitor.getInstance().getLock();
 
     @VisibleForTesting
     public final boolean mSurfaceOnly;
@@ -181,7 +182,7 @@ public class FrameTracker extends SurfaceControl.OnJankDataListener
             mSurfaceChangedCallback = new ViewRootImpl.SurfaceChangedCallback() {
                 @Override
                 public void surfaceCreated(SurfaceControl.Transaction t) {
-                    synchronized (FrameTracker.this) {
+                    synchronized (mLock) {
                         if (mSurfaceControl == null) {
                             mSurfaceControl = mViewRoot.getSurfaceControl();
                             if (mBeginVsyncId != INVALID_ID) {
@@ -203,12 +204,12 @@ 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 (FrameTracker.this) {
+                        synchronized (mLock) {
                             if (DEBUG) {
                                 Log.d(TAG, "surfaceDestroyed: " + mSession.getName()
                                         + ", finalized=" + mMetricsFinalized
                                         + ", info=" + mJankInfos.size()
-                                        + ", vsync=" + mBeginVsyncId + "-" + mEndVsyncId);
+                                        + ", vsync=" + mBeginVsyncId);
                             }
                             if (!mMetricsFinalized) {
                                 end(REASON_END_SURFACE_DESTROYED);
@@ -227,20 +228,20 @@ public class FrameTracker extends SurfaceControl.OnJankDataListener
     /**
      * Begin a trace session of the CUJ.
      */
-    public synchronized void begin() {
-        mBeginVsyncId = mChoreographer.getVsyncId() + 1;
-        if (DEBUG) {
-            Log.d(TAG, "begin: " + mSession.getName() + ", begin=" + mBeginVsyncId);
-        }
-        if (mSurfaceControl != null) {
-            postTraceStartMarker();
-            mSurfaceControlWrapper.addJankStatsListener(this, mSurfaceControl);
-        }
-        if (!mSurfaceOnly) {
-            mRendererWrapper.addObserver(mObserver);
-        }
-        if (mListener != null) {
-            mListener.onCujEvents(mSession, ACTION_SESSION_BEGIN);
+    public void begin() {
+        synchronized (mLock) {
+            mBeginVsyncId = mChoreographer.getVsyncId() + 1;
+            if (DEBUG) {
+                Log.d(TAG, "begin: " + mSession.getName() + ", begin=" + mBeginVsyncId);
+            }
+            if (mSurfaceControl != null) {
+                postTraceStartMarker();
+                mSurfaceControlWrapper.addJankStatsListener(this, mSurfaceControl);
+            }
+            if (!mSurfaceOnly) {
+                mRendererWrapper.addObserver(mObserver);
+            }
+            notifyCujEvent(ACTION_SESSION_BEGIN);
         }
     }
 
@@ -250,7 +251,7 @@ public class FrameTracker extends SurfaceControl.OnJankDataListener
     @VisibleForTesting
     public void postTraceStartMarker() {
         mChoreographer.mChoreographer.postCallback(Choreographer.CALLBACK_INPUT, () -> {
-            synchronized (FrameTracker.this) {
+            synchronized (mLock) {
                 if (mCancelled || mEndVsyncId != INVALID_ID) {
                     return;
                 }
@@ -263,88 +264,98 @@ public class FrameTracker extends SurfaceControl.OnJankDataListener
     /**
      * End the trace session of the CUJ.
      */
-    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 (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);
-            if (mListener != null) {
-                mListener.onCujEvents(mSession, ACTION_SESSION_END);
+    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);
+                }
+                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(mJankInfos.size() - 1);
+                };
+                mHandler.postDelayed(mWaitForFinishTimedOut, TimeUnit.SECONDS.toMillis(10));
+                notifyCujEvent(ACTION_SESSION_END);
+                return true;
             }
-
-            // 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(mJankInfos.size() - 1);
-            };
-            mHandler.postDelayed(mWaitForFinishTimedOut, TimeUnit.SECONDS.toMillis(10));
         }
     }
 
     /**
      * Cancel the trace session of the CUJ.
      */
-    public synchronized void cancel(@Reasons int reason) {
-        mCancelled = true;
+    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;
+            // We don't need to end the trace section if it never begun.
+            if (mTracingStarted) {
+                Trace.endAsyncSection(mSession.getName(), (int) mBeginVsyncId);
+            }
 
-        // 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();
 
-        // 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);
+            }
 
-        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;
         }
+    }
 
-        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) {
-            mListener.onCujEvents(mSession, ACTION_SESSION_CANCEL);
-        }
+    private void notifyCujEvent(String action) {
+        if (mListener == null) return;
+        mListener.onCujEvents(mSession, action);
     }
 
     @Override
-    public synchronized void onJankDataAvailable(SurfaceControl.JankData[] jankData) {
-        if (mCancelled) {
-            return;
-        }
-
-        for (SurfaceControl.JankData jankStat : jankData) {
-            if (!isInRange(jankStat.frameVsyncId)) {
-                continue;
+    public void onJankDataAvailable(SurfaceControl.JankData[] jankData) {
+        synchronized (mLock) {
+            if (mCancelled) {
+                return;
             }
-            JankInfo info = findJankInfo(jankStat.frameVsyncId);
-            if (info != null) {
-                info.surfaceControlCallbackFired = true;
-                info.jankType = jankStat.jankType;
-            } else {
-                mJankInfos.put((int) jankStat.frameVsyncId,
-                        JankInfo.createFromSurfaceControlCallback(
-                                jankStat.frameVsyncId, jankStat.jankType));
+
+            for (SurfaceControl.JankData jankStat : jankData) {
+                if (!isInRange(jankStat.frameVsyncId)) {
+                    continue;
+                }
+                JankInfo info = findJankInfo(jankStat.frameVsyncId);
+                if (info != null) {
+                    info.surfaceControlCallbackFired = true;
+                    info.jankType = jankStat.jankType;
+                } else {
+                    mJankInfos.put((int) jankStat.frameVsyncId,
+                            JankInfo.createFromSurfaceControlCallback(
+                                    jankStat.frameVsyncId, jankStat.jankType));
+                }
             }
+            processJankInfos();
         }
-        processJankInfos();
     }
 
     private @Nullable JankInfo findJankInfo(long frameVsyncId) {
@@ -359,31 +370,34 @@ public class FrameTracker extends SurfaceControl.OnJankDataListener
     }
 
     @Override
-    public synchronized void onFrameMetricsAvailable(int dropCountSinceLastInvocation) {
-        if (mCancelled) {
-            return;
-        }
+    public void onFrameMetricsAvailable(int dropCountSinceLastInvocation) {
+        synchronized (mLock) {
+            if (mCancelled) {
+                return;
+            }
 
-        // Since this callback might come a little bit late after the end() call.
-        // We should keep tracking the begin / end timestamp.
-        // Then compare with vsync timestamp to check if the frame is in the duration of the CUJ.
-        long totalDurationNanos = mMetricsWrapper.getMetric(FrameMetrics.TOTAL_DURATION);
-        boolean isFirstFrame = mMetricsWrapper.getMetric(FrameMetrics.FIRST_DRAW_FRAME) == 1;
-        long frameVsyncId = mMetricsWrapper.getTiming()[FrameMetrics.Index.FRAME_TIMELINE_VSYNC_ID];
+            // Since this callback might come a little bit late after the end() call.
+            // We should keep tracking the begin / end timestamp that we can compare with
+            // vsync timestamp to check if the frame is in the duration of the CUJ.
+            long totalDurationNanos = mMetricsWrapper.getMetric(FrameMetrics.TOTAL_DURATION);
+            boolean isFirstFrame = mMetricsWrapper.getMetric(FrameMetrics.FIRST_DRAW_FRAME) == 1;
+            long frameVsyncId =
+                    mMetricsWrapper.getTiming()[FrameMetrics.Index.FRAME_TIMELINE_VSYNC_ID];
 
-        if (!isInRange(frameVsyncId)) {
-            return;
-        }
-        JankInfo info = findJankInfo(frameVsyncId);
-        if (info != null) {
-            info.hwuiCallbackFired = true;
-            info.totalDurationNanos = totalDurationNanos;
-            info.isFirstFrame = isFirstFrame;
-        } else {
-            mJankInfos.put((int) frameVsyncId, JankInfo.createFromHwuiCallback(
-                    frameVsyncId, totalDurationNanos, isFirstFrame));
+            if (!isInRange(frameVsyncId)) {
+                return;
+            }
+            JankInfo info = findJankInfo(frameVsyncId);
+            if (info != null) {
+                info.hwuiCallbackFired = true;
+                info.totalDurationNanos = totalDurationNanos;
+                info.isFirstFrame = isFirstFrame;
+            } else {
+                mJankInfos.put((int) frameVsyncId, JankInfo.createFromHwuiCallback(
+                        frameVsyncId, totalDurationNanos, isFirstFrame));
+            }
+            processJankInfos();
         }
-        processJankInfos();
     }
 
     /**
@@ -497,11 +511,7 @@ public class FrameTracker extends SurfaceControl.OnJankDataListener
                 (int) (maxFrameTimeNanos / NANOS_IN_MILLISECOND));
 
         // Trigger perfetto if necessary.
-        boolean overMissedFramesThreshold = mTraceThresholdMissedFrames != -1
-                && missedFramesCount >= mTraceThresholdMissedFrames;
-        boolean overFrameTimeThreshold = !mSurfaceOnly && mTraceThresholdFrameTimeMillis != -1
-                && maxFrameTimeNanos >= mTraceThresholdFrameTimeMillis * NANOS_IN_MILLISECOND;
-        if (overMissedFramesThreshold || overFrameTimeThreshold) {
+        if (shouldTriggerPerfetto(missedFramesCount, (int) maxFrameTimeNanos)) {
             triggerPerfetto();
         }
         if (mSession.logToStatsd()) {
@@ -513,9 +523,7 @@ public class FrameTracker extends SurfaceControl.OnJankDataListener
                     maxFrameTimeNanos, /* will be 0 if mSurfaceOnly == true */
                     missedSfFramesCount,
                     missedAppFramesCount);
-            if (mListener != null) {
-                mListener.onCujEvents(mSession, ACTION_METRICS_LOGGED);
-            }
+            notifyCujEvent(ACTION_METRICS_LOGGED);
         }
         if (DEBUG) {
             Log.i(TAG, "finish: CUJ=" + mSession.getName()
@@ -528,6 +536,14 @@ public class FrameTracker extends SurfaceControl.OnJankDataListener
         }
     }
 
+    private boolean shouldTriggerPerfetto(int missedFramesCount, int maxFrameTimeNanos) {
+        boolean overMissedFramesThreshold = mTraceThresholdMissedFrames != -1
+                && missedFramesCount >= mTraceThresholdMissedFrames;
+        boolean overFrameTimeThreshold = !mSurfaceOnly && mTraceThresholdFrameTimeMillis != -1
+                && maxFrameTimeNanos >= mTraceThresholdFrameTimeMillis * NANOS_IN_MILLISECOND;
+        return overMissedFramesThreshold || overFrameTimeThreshold;
+    }
+
     /**
      * Remove all the registered listeners, observers and callbacks.
      */
diff --git a/core/java/com/android/internal/jank/InteractionJankMonitor.java b/core/java/com/android/internal/jank/InteractionJankMonitor.java
index f8eb95cbd48c..c608864c6caa 100644
--- a/core/java/com/android/internal/jank/InteractionJankMonitor.java
+++ b/core/java/com/android/internal/jank/InteractionJankMonitor.java
@@ -230,6 +230,7 @@ public class InteractionJankMonitor {
     private final SparseArray<FrameTracker> mRunningTrackers;
     private final SparseArray<Runnable> mTimeoutActions;
     private final HandlerThread mWorker;
+    private final Object mLock = new Object();
 
     private boolean mEnabled = DEFAULT_ENABLED;
     private int mSamplingInterval = DEFAULT_SAMPLING_INTERVAL;
@@ -325,6 +326,10 @@ public class InteractionJankMonitor {
                 mPropertiesChangedListener);
     }
 
+    Object getLock() {
+        return mLock;
+    }
+
     /**
      * Creates a {@link FrameTracker} instance.
      *
@@ -344,7 +349,7 @@ public class InteractionJankMonitor {
         final ChoreographerWrapper choreographer =
                 new ChoreographerWrapper(Choreographer.getInstance());
 
-        synchronized (this) {
+        synchronized (mLock) {
             FrameTrackerListener eventsListener =
                     (s, act) -> handleCujEvents(config.getContext(), act, s);
             return new FrameTracker(session, mWorker.getThreadHandler(),
@@ -372,11 +377,16 @@ public class InteractionJankMonitor {
         final boolean badEnd = action.equals(ACTION_SESSION_END)
                 && session.getReason() != REASON_END_NORMAL;
         final boolean badCancel = action.equals(ACTION_SESSION_CANCEL)
-                && session.getReason() != REASON_CANCEL_NORMAL;
+                && !(session.getReason() == REASON_CANCEL_NORMAL
+                || session.getReason() == REASON_CANCEL_TIMEOUT);
         return badEnd || badCancel;
     }
 
-    private void notifyEvents(Context context, String action, Session session) {
+    /**
+     * Notifies who may interest in some CUJ events.
+     */
+    @VisibleForTesting
+    public void notifyEvents(Context context, String action, Session session) {
         if (action.equals(ACTION_SESSION_CANCEL)
                 && session.getReason() == REASON_CANCEL_NOT_BEGUN) {
             return;
@@ -389,7 +399,7 @@ public class InteractionJankMonitor {
     }
 
     private void removeTimeout(@CujType int cujType) {
-        synchronized (this) {
+        synchronized (mLock) {
             Runnable timeout = mTimeoutActions.get(cujType);
             if (timeout != null) {
                 mWorker.getThreadHandler().removeCallbacks(timeout);
@@ -432,17 +442,9 @@ public class InteractionJankMonitor {
     }
 
     private boolean beginInternal(@NonNull Configuration conf) {
-        synchronized (this) {
+        synchronized (mLock) {
             int cujType = conf.mCujType;
-            boolean shouldSample = ThreadLocalRandom.current().nextInt() % mSamplingInterval == 0;
-            if (!mEnabled || !shouldSample) {
-                if (DEBUG) {
-                    Log.d(TAG, "Skip monitoring cuj: " + getNameOfCuj(cujType)
-                            + ", enable=" + mEnabled + ", debuggable=" + DEFAULT_ENABLED
-                            + ", sample=" + shouldSample + ", interval=" + mSamplingInterval);
-                }
-                return false;
-            }
+            if (!shouldMonitor(cujType)) return false;
             FrameTracker tracker = getTracker(cujType);
             // Skip subsequent calls if we already have an ongoing tracing.
             if (tracker != null) return false;
@@ -460,6 +462,24 @@ public class InteractionJankMonitor {
     }
 
     /**
+     * Check if the monitoring is enabled and if it should be sampled.
+     */
+    @SuppressWarnings("RandomModInteger")
+    @VisibleForTesting
+    public boolean shouldMonitor(@CujType int cujType) {
+        boolean shouldSample = ThreadLocalRandom.current().nextInt() % mSamplingInterval == 0;
+        if (!mEnabled || !shouldSample) {
+            if (DEBUG) {
+                Log.d(TAG, "Skip monitoring cuj: " + getNameOfCuj(cujType)
+                        + ", enable=" + mEnabled + ", debuggable=" + DEFAULT_ENABLED
+                        + ", sample=" + shouldSample + ", interval=" + mSamplingInterval);
+            }
+            return false;
+        }
+        return true;
+    }
+
+    /**
      * Schedules a timeout action.
      * @param cuj cuj type
      * @param timeout duration to timeout
@@ -478,14 +498,16 @@ public class InteractionJankMonitor {
      * @return boolean true if the tracker is ended successfully, false otherwise.
      */
     public boolean end(@CujType int cujType) {
-        synchronized (this) {
+        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;
-            tracker.end(REASON_END_NORMAL);
-            removeTracker(cujType);
+            // 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;
         }
     }
@@ -499,33 +521,37 @@ public class InteractionJankMonitor {
         return cancel(cujType, REASON_CANCEL_NORMAL);
     }
 
-    boolean cancel(@CujType int cujType, @Reasons int reason) {
-        synchronized (this) {
+    /**
+     * Cancels the trace session.
+     *
+     * @return boolean true if the tracker is cancelled successfully, false otherwise.
+     */
+    @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;
-            tracker.cancel(reason);
-            removeTracker(cujType);
+            // 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 FrameTracker getTracker(@CujType int cuj) {
-        synchronized (this) {
-            return mRunningTrackers.get(cuj);
-        }
+        return mRunningTrackers.get(cuj);
     }
 
     private void removeTracker(@CujType int cuj) {
-        synchronized (this) {
-            mRunningTrackers.remove(cuj);
-        }
+        mRunningTrackers.remove(cuj);
     }
 
     private void updateProperties(DeviceConfig.Properties properties) {
-        synchronized (this) {
+        synchronized (mLock) {
             mSamplingInterval = properties.getInt(SETTINGS_SAMPLING_INTERVAL_KEY,
                     DEFAULT_SAMPLING_INTERVAL);
             mEnabled = properties.getBoolean(SETTINGS_ENABLED_KEY, DEFAULT_ENABLED);
@@ -547,10 +573,8 @@ public class InteractionJankMonitor {
      */
     @VisibleForTesting
     public void trigger(Session session) {
-        synchronized (this) {
-            mWorker.getThreadHandler().post(
-                    () -> PerfettoTrigger.trigger(session.getPerfettoTrigger()));
-        }
+        mWorker.getThreadHandler().post(
+                () -> PerfettoTrigger.trigger(session.getPerfettoTrigger()));
     }
 
     /**