1 /*
2  * Copyright (C) 2020 The Android Open Source Project
3  *
4  * Licensed under the Apache License, Version 2.0 (the "License");
5  * you may not use this file except in compliance with the License.
6  * You may obtain a copy of the License at
7  *
8  *      http://www.apache.org/licenses/LICENSE-2.0
9  *
10  * Unless required by applicable law or agreed to in writing, software
11  * distributed under the License is distributed on an "AS IS" BASIS,
12  * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13  * See the License for the specific language governing permissions and
14  * limitations under the License.
15  */
16 
17 package com.android.internal.jank;
18 
19 import static android.view.SurfaceControl.JankData.DISPLAY_HAL;
20 import static android.view.SurfaceControl.JankData.JANK_APP_DEADLINE_MISSED;
21 import static android.view.SurfaceControl.JankData.JANK_NONE;
22 import static android.view.SurfaceControl.JankData.JANK_SURFACEFLINGER_DEADLINE_MISSED;
23 import static android.view.SurfaceControl.JankData.JANK_SURFACEFLINGER_GPU_DEADLINE_MISSED;
24 import static android.view.SurfaceControl.JankData.PREDICTION_ERROR;
25 import static android.view.SurfaceControl.JankData.SURFACE_FLINGER_SCHEDULING;
26 
27 import static com.android.internal.jank.InteractionJankMonitor.ACTION_SESSION_CANCEL;
28 import static com.android.internal.jank.InteractionJankMonitor.ACTION_SESSION_END;
29 import static com.android.internal.jank.InteractionJankMonitor.EXECUTOR_TASK_TIMEOUT;
30 
31 import android.annotation.IntDef;
32 import android.annotation.NonNull;
33 import android.annotation.Nullable;
34 import android.annotation.UiThread;
35 import android.graphics.HardwareRendererObserver;
36 import android.os.Handler;
37 import android.os.Trace;
38 import android.text.TextUtils;
39 import android.util.DisplayMetrics;
40 import android.util.Log;
41 import android.util.SparseArray;
42 import android.view.Choreographer;
43 import android.view.FrameMetrics;
44 import android.view.SurfaceControl;
45 import android.view.SurfaceControl.JankData.JankType;
46 import android.view.ThreadedRenderer;
47 import android.view.View;
48 import android.view.ViewRootImpl;
49 import android.view.WindowCallbacks;
50 
51 import com.android.internal.annotations.VisibleForTesting;
52 import com.android.internal.jank.InteractionJankMonitor.Configuration;
53 import com.android.internal.jank.InteractionJankMonitor.Session;
54 import com.android.internal.util.FrameworkStatsLog;
55 
56 import java.lang.annotation.Retention;
57 import java.lang.annotation.RetentionPolicy;
58 import java.util.concurrent.TimeUnit;
59 
60 /**
61  * A class that allows the app to get the frame metrics from HardwareRendererObserver.
62  * @hide
63  */
64 public class FrameTracker extends SurfaceControl.OnJankDataListener
65         implements HardwareRendererObserver.OnFrameMetricsAvailableListener {
66     private static final String TAG = "FrameTracker";
67     private static final boolean DEBUG = false;
68 
69     private static final long INVALID_ID = -1;
70     public static final int NANOS_IN_MILLISECOND = 1_000_000;
71 
72     private static final int MAX_LENGTH_EVENT_DESC = 127;
73 
74     private static final int MAX_FLUSH_ATTEMPTS = 3;
75     private static final int FLUSH_DELAY_MILLISECOND = 60;
76 
77     static final int REASON_END_UNKNOWN = -1;
78     static final int REASON_END_NORMAL = 0;
79     static final int REASON_END_SURFACE_DESTROYED = 1;
80     static final int REASON_CANCEL_NORMAL = 16;
81     static final int REASON_CANCEL_NOT_BEGUN = 17;
82     static final int REASON_CANCEL_SAME_VSYNC = 18;
83     static final int REASON_CANCEL_TIMEOUT = 19;
84 
85     /** @hide */
86     @IntDef({
87             REASON_END_UNKNOWN,
88             REASON_END_NORMAL,
89             REASON_END_SURFACE_DESTROYED,
90             REASON_CANCEL_NORMAL,
91             REASON_CANCEL_NOT_BEGUN,
92             REASON_CANCEL_SAME_VSYNC,
93     })
94     @Retention(RetentionPolicy.SOURCE)
95     public @interface Reasons {
96     }
97 
98     @VisibleForTesting
99     public final InteractionJankMonitor mMonitor;
100     private final HardwareRendererObserver mObserver;
101     private final int mTraceThresholdMissedFrames;
102     private final int mTraceThresholdFrameTimeMillis;
103     private final ThreadedRendererWrapper mRendererWrapper;
104     private final FrameMetricsWrapper mMetricsWrapper;
105     private final SparseArray<JankInfo> mJankInfos = new SparseArray<>();
106     private final Session mSession;
107     private final ViewRootWrapper mViewRoot;
108     private final SurfaceControlWrapper mSurfaceControlWrapper;
109     private final int mDisplayId;
110     private final ViewRootImpl.SurfaceChangedCallback mSurfaceChangedCallback;
111     private final Handler mHandler;
112     private final ChoreographerWrapper mChoreographer;
113     private final StatsLogWrapper mStatsLog;
114     private final boolean mDeferMonitoring;
115     private final FrameTrackerListener mListener;
116 
117     @VisibleForTesting
118     public final boolean mSurfaceOnly;
119 
120     private SurfaceControl mSurfaceControl;
121     private long mBeginVsyncId = INVALID_ID;
122     private long mEndVsyncId = INVALID_ID;
123     private boolean mMetricsFinalized;
124     private boolean mCancelled = false;
125     private boolean mTracingStarted = false;
126     private Runnable mWaitForFinishTimedOut;
127 
128     private static class JankInfo {
129         long frameVsyncId;
130         long totalDurationNanos;
131         boolean isFirstFrame;
132         boolean hwuiCallbackFired;
133         boolean surfaceControlCallbackFired;
134         @JankType int jankType;
135 
createFromHwuiCallback(long frameVsyncId, long totalDurationNanos, boolean isFirstFrame)136         static JankInfo createFromHwuiCallback(long frameVsyncId, long totalDurationNanos,
137                 boolean isFirstFrame) {
138             return new JankInfo(frameVsyncId, true, false, JANK_NONE, totalDurationNanos,
139                     isFirstFrame);
140         }
141 
createFromSurfaceControlCallback(long frameVsyncId, @JankType int jankType)142         static JankInfo createFromSurfaceControlCallback(long frameVsyncId,
143                 @JankType int jankType) {
144             return new JankInfo(frameVsyncId, false, true, jankType, 0, false /* isFirstFrame */);
145         }
146 
JankInfo(long frameVsyncId, boolean hwuiCallbackFired, boolean surfaceControlCallbackFired, @JankType int jankType, long totalDurationNanos, boolean isFirstFrame)147         private JankInfo(long frameVsyncId, boolean hwuiCallbackFired,
148                 boolean surfaceControlCallbackFired, @JankType int jankType,
149                 long totalDurationNanos, boolean isFirstFrame) {
150             this.frameVsyncId = frameVsyncId;
151             this.hwuiCallbackFired = hwuiCallbackFired;
152             this.surfaceControlCallbackFired = surfaceControlCallbackFired;
153             this.totalDurationNanos = totalDurationNanos;
154             this.jankType = jankType;
155             this.isFirstFrame = isFirstFrame;
156         }
157 
158         @Override
toString()159         public String toString() {
160             StringBuilder str = new StringBuilder();
161             switch (jankType) {
162                 case JANK_NONE:
163                     str.append("JANK_NONE");
164                     break;
165                 case JANK_APP_DEADLINE_MISSED:
166                     str.append("JANK_APP_DEADLINE_MISSED");
167                     break;
168                 case JANK_SURFACEFLINGER_DEADLINE_MISSED:
169                     str.append("JANK_SURFACEFLINGER_DEADLINE_MISSED");
170                     break;
171                 case JANK_SURFACEFLINGER_GPU_DEADLINE_MISSED:
172                     str.append("JANK_SURFACEFLINGER_GPU_DEADLINE_MISSED");
173                     break;
174                 case DISPLAY_HAL:
175                     str.append("DISPLAY_HAL");
176                     break;
177                 case PREDICTION_ERROR:
178                     str.append("PREDICTION_ERROR");
179                     break;
180                 case SURFACE_FLINGER_SCHEDULING:
181                     str.append("SURFACE_FLINGER_SCHEDULING");
182                     break;
183                 default:
184                     str.append("UNKNOWN: ").append(jankType);
185                     break;
186             }
187             str.append(", ").append(frameVsyncId);
188             str.append(", ").append(totalDurationNanos);
189             return str.toString();
190         }
191     }
192 
FrameTracker(@onNull 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)193     public FrameTracker(@NonNull InteractionJankMonitor monitor, @NonNull Session session,
194             @NonNull Handler handler, @Nullable ThreadedRendererWrapper renderer,
195             @Nullable ViewRootWrapper viewRootWrapper,
196             @NonNull SurfaceControlWrapper surfaceControlWrapper,
197             @NonNull ChoreographerWrapper choreographer,
198             @Nullable FrameMetricsWrapper metrics,
199             @NonNull StatsLogWrapper statsLog,
200             int traceThresholdMissedFrames, int traceThresholdFrameTimeMillis,
201             @Nullable FrameTrackerListener listener, @NonNull Configuration config) {
202         mMonitor = monitor;
203         mSurfaceOnly = config.isSurfaceOnly();
204         mSession = session;
205         mHandler = handler;
206         mChoreographer = choreographer;
207         mSurfaceControlWrapper = surfaceControlWrapper;
208         mStatsLog = statsLog;
209         mDeferMonitoring = config.shouldDeferMonitor();
210 
211         // HWUI instrumentation init.
212         mRendererWrapper = mSurfaceOnly ? null : renderer;
213         mMetricsWrapper = mSurfaceOnly ? null : metrics;
214         mViewRoot = mSurfaceOnly ? null : viewRootWrapper;
215         mObserver = mSurfaceOnly
216                 ? null
217                 : new HardwareRendererObserver(this, mMetricsWrapper.getTiming(),
218                         handler, /* waitForPresentTime= */ false);
219 
220         mTraceThresholdMissedFrames = traceThresholdMissedFrames;
221         mTraceThresholdFrameTimeMillis = traceThresholdFrameTimeMillis;
222         mListener = listener;
223         mDisplayId = config.getDisplayId();
224 
225         if (mSurfaceOnly) {
226             mSurfaceControl = config.getSurfaceControl();
227             mSurfaceChangedCallback = null;
228         } else {
229             // HWUI instrumentation init.
230             // If the surface isn't valid yet, wait until it's created.
231             if (mViewRoot.getSurfaceControl().isValid()) {
232                 mSurfaceControl = mViewRoot.getSurfaceControl();
233             }
234 
235             mSurfaceChangedCallback = new ViewRootImpl.SurfaceChangedCallback() {
236                 @Override
237                 public void surfaceCreated(SurfaceControl.Transaction t) {
238                     getHandler().runWithScissors(() -> {
239                         if (mSurfaceControl == null) {
240                             mSurfaceControl = mViewRoot.getSurfaceControl();
241                             if (mBeginVsyncId != INVALID_ID) {
242                                 // Previous begin invocation is not successfully, begin it again.
243                                 begin();
244                             }
245                         }
246                     }, EXECUTOR_TASK_TIMEOUT);
247                 }
248 
249                 @Override
250                 public void surfaceReplaced(SurfaceControl.Transaction t) {
251                 }
252 
253                 @Override
254                 public void surfaceDestroyed() {
255 
256                     // Wait a while to give the system a chance for the remaining
257                     // frames to arrive, then force finish the session.
258                     getHandler().postDelayed(() -> {
259                         if (DEBUG) {
260                             Log.d(TAG, "surfaceDestroyed: " + mSession.getName()
261                                     + ", finalized=" + mMetricsFinalized
262                                     + ", info=" + mJankInfos.size()
263                                     + ", vsync=" + mBeginVsyncId);
264                         }
265                         if (!mMetricsFinalized) {
266                             end(REASON_END_SURFACE_DESTROYED);
267                             finish();
268                         }
269                     }, 50);
270                 }
271             };
272             // This callback has a reference to FrameTracker,
273             // remember to remove it to avoid leakage.
274             mViewRoot.addSurfaceChangedCallback(mSurfaceChangedCallback);
275         }
276     }
277 
278     @VisibleForTesting(visibility = VisibleForTesting.Visibility.PACKAGE)
getHandler()279     public Handler getHandler() {
280         return mHandler;
281     }
282 
283     /**
284      * Begin a trace session of the CUJ.
285      */
286     @UiThread
begin()287     public void begin() {
288         final long currentVsync = mChoreographer.getVsyncId();
289         // In normal case, we should begin at the next frame,
290         // the id of the next frame is not simply increased by 1,
291         // but we can exclude the current frame at least.
292         if (mBeginVsyncId == INVALID_ID) {
293             mBeginVsyncId = mDeferMonitoring ? currentVsync + 1 : currentVsync;
294         }
295         if (mSurfaceControl != null) {
296             if (DEBUG) {
297                 Log.d(TAG, "begin: " + mSession.getName() + ", begin=" + mBeginVsyncId
298                         + ", defer=" + mDeferMonitoring + ", current=" + currentVsync);
299             }
300             if (mDeferMonitoring && currentVsync < mBeginVsyncId) {
301                 markEvent("FT#deferMonitoring", 0);
302                 // Normal case, we begin the instrument from the very beginning,
303                 // will exclude the first frame.
304                 postTraceStartMarker(this::beginInternal);
305             } else {
306                 // If we don't begin the instrument from the very beginning,
307                 // there is no need to skip the frame where the begin invocation happens.
308                 beginInternal();
309             }
310         } else {
311             if (DEBUG) {
312                 Log.d(TAG, "begin: defer beginning since the surface is not ready for CUJ="
313                         + mSession.getName());
314             }
315         }
316     }
317 
318     /**
319      * Start trace section at appropriate time.
320      */
321     @VisibleForTesting
postTraceStartMarker(Runnable action)322     public void postTraceStartMarker(Runnable action) {
323         mChoreographer.mChoreographer.postCallback(Choreographer.CALLBACK_INPUT, action, null);
324     }
325 
326     @UiThread
beginInternal()327     private void beginInternal() {
328         if (mCancelled || mEndVsyncId != INVALID_ID) {
329             return;
330         }
331         mTracingStarted = true;
332         Trace.asyncTraceForTrackBegin(Trace.TRACE_TAG_APP, mSession.getName(), mSession.getName(),
333                 (int) mBeginVsyncId);
334         markEvent("FT#beginVsync", mBeginVsyncId);
335         markEvent("FT#layerId", mSurfaceControl.getLayerId());
336         mSurfaceControlWrapper.addJankStatsListener(this, mSurfaceControl);
337         if (!mSurfaceOnly) {
338             mRendererWrapper.addObserver(mObserver);
339         }
340     }
341 
342     /**
343      * End the trace session of the CUJ.
344      */
345     @UiThread
end(@easons int reason)346     public boolean end(@Reasons int reason) {
347         if (mCancelled || mEndVsyncId != INVALID_ID) return false;
348         mEndVsyncId = mChoreographer.getVsyncId();
349         // Cancel the session if:
350         // 1. The session begins and ends at the same vsync id.
351         // 2. The session never begun.
352         if (mBeginVsyncId == INVALID_ID) {
353             return cancel(REASON_CANCEL_NOT_BEGUN);
354         } else if (mEndVsyncId <= mBeginVsyncId) {
355             return cancel(REASON_CANCEL_SAME_VSYNC);
356         } else {
357             if (DEBUG) {
358                 Log.d(TAG, "end: " + mSession.getName()
359                         + ", end=" + mEndVsyncId + ", reason=" + reason);
360             }
361             markEvent("FT#end", reason);
362             markEvent("FT#endVsync", mEndVsyncId);
363             Trace.asyncTraceForTrackEnd(Trace.TRACE_TAG_APP, mSession.getName(),
364                     (int) mBeginVsyncId);
365             mSession.setReason(reason);
366 
367             // We don't remove observer here,
368             // will remove it when all the frame metrics in this duration are called back.
369             // See onFrameMetricsAvailable for the logic of removing the observer.
370             // Waiting at most 10 seconds for all callbacks to finish.
371             mWaitForFinishTimedOut = new Runnable() {
372                 private int mFlushAttempts = 0;
373 
374                 @Override
375                 public void run() {
376                     if (mWaitForFinishTimedOut == null || mMetricsFinalized) {
377                         return;
378                     }
379 
380                     // Send a flush jank data transaction.
381                     if (mSurfaceControl != null && mSurfaceControl.isValid()) {
382                         SurfaceControl.Transaction.sendSurfaceFlushJankData(mSurfaceControl);
383                     }
384 
385                     long delay;
386                     if (mFlushAttempts < MAX_FLUSH_ATTEMPTS) {
387                         delay = FLUSH_DELAY_MILLISECOND;
388                         mFlushAttempts++;
389                     } else {
390                         mWaitForFinishTimedOut = () -> {
391                             Log.e(TAG, "force finish cuj, time out: " + mSession.getName());
392                             finish();
393                         };
394                         delay = TimeUnit.SECONDS.toMillis(10);
395                     }
396                     getHandler().postDelayed(mWaitForFinishTimedOut, delay);
397                 }
398             };
399             getHandler().postDelayed(mWaitForFinishTimedOut, FLUSH_DELAY_MILLISECOND);
400             notifyCujEvent(ACTION_SESSION_END);
401             return true;
402         }
403     }
404 
405     /**
406      * Cancel the trace session of the CUJ.
407      */
408     @UiThread
cancel(@easons int reason)409     public boolean cancel(@Reasons int reason) {
410         final boolean cancelFromEnd =
411                 reason == REASON_CANCEL_NOT_BEGUN || reason == REASON_CANCEL_SAME_VSYNC;
412         if (mCancelled || (mEndVsyncId != INVALID_ID && !cancelFromEnd)) return false;
413         mCancelled = true;
414         markEvent("FT#cancel", reason);
415         // We don't need to end the trace section if it has never begun.
416         if (mTracingStarted) {
417             Trace.asyncTraceForTrackEnd(Trace.TRACE_TAG_APP, mSession.getName(),
418                     (int) mBeginVsyncId);
419         }
420 
421         // Always remove the observers in cancel call to avoid leakage.
422         removeObservers();
423 
424         if (DEBUG) {
425             Log.d(TAG, "cancel: " + mSession.getName() + ", begin=" + mBeginVsyncId
426                     + ", end=" + mEndVsyncId + ", reason=" + reason);
427         }
428 
429         mSession.setReason(reason);
430         // Notify the listener the session has been cancelled.
431         // We don't notify the listeners if the session never begun.
432         notifyCujEvent(ACTION_SESSION_CANCEL);
433         return true;
434     }
435 
436     /**
437      * Mark the FrameTracker events in the trace.
438      *
439      * @param eventName  The description of the trace event,
440      * @param eventValue The value of the related trace event
441      *                   Both shouldn't exceed {@link #MAX_LENGTH_EVENT_DESC}.
442      */
markEvent(@onNull String eventName, long eventValue)443     private void markEvent(@NonNull String eventName, long eventValue) {
444         if (Trace.isTagEnabled(Trace.TRACE_TAG_APP)) {
445             String event = TextUtils.formatSimple("%s#%s", eventName, eventValue);
446             if (event.length() > MAX_LENGTH_EVENT_DESC) {
447                 throw new IllegalArgumentException(TextUtils.formatSimple(
448                         "The length of the trace event description <%s> exceeds %d",
449                         event, MAX_LENGTH_EVENT_DESC));
450             }
451             Trace.instantForTrack(Trace.TRACE_TAG_APP, mSession.getName(), event);
452         }
453     }
454 
notifyCujEvent(String action)455     private void notifyCujEvent(String action) {
456         if (mListener == null) return;
457         mListener.onCujEvents(mSession, action);
458     }
459 
460     @Override
onJankDataAvailable(SurfaceControl.JankData[] jankData)461     public void onJankDataAvailable(SurfaceControl.JankData[] jankData) {
462         postCallback(() -> {
463             if (mCancelled || mMetricsFinalized) {
464                 return;
465             }
466 
467             for (SurfaceControl.JankData jankStat : jankData) {
468                 if (!isInRange(jankStat.frameVsyncId)) {
469                     continue;
470                 }
471                 JankInfo info = findJankInfo(jankStat.frameVsyncId);
472                 if (info != null) {
473                     info.surfaceControlCallbackFired = true;
474                     info.jankType = jankStat.jankType;
475                 } else {
476                     mJankInfos.put((int) jankStat.frameVsyncId,
477                             JankInfo.createFromSurfaceControlCallback(
478                                     jankStat.frameVsyncId, jankStat.jankType));
479                 }
480             }
481             processJankInfos();
482         });
483     }
484 
485     /**
486      * For easier argument capture.
487      */
488     @VisibleForTesting
postCallback(Runnable callback)489     public void postCallback(Runnable callback) {
490         getHandler().post(callback);
491     }
492 
493     @Nullable
findJankInfo(long frameVsyncId)494     private JankInfo findJankInfo(long frameVsyncId) {
495         return mJankInfos.get((int) frameVsyncId);
496     }
497 
isInRange(long vsyncId)498     private boolean isInRange(long vsyncId) {
499         // It's possible that we may miss a callback for the frame with vsyncId == mEndVsyncId.
500         // Because of that, we collect all frames even if they happen after the end so we eventually
501         // have a frame after the end with both callbacks present.
502         return vsyncId >= mBeginVsyncId;
503     }
504 
505     @Override
onFrameMetricsAvailable(int dropCountSinceLastInvocation)506     public void onFrameMetricsAvailable(int dropCountSinceLastInvocation) {
507         postCallback(() -> {
508             if (mCancelled || mMetricsFinalized) {
509                 return;
510             }
511 
512             // Since this callback might come a little bit late after the end() call.
513             // We should keep tracking the begin / end timestamp that we can compare with
514             // vsync timestamp to check if the frame is in the duration of the CUJ.
515             long totalDurationNanos = mMetricsWrapper.getMetric(FrameMetrics.TOTAL_DURATION);
516             boolean isFirstFrame = mMetricsWrapper.getMetric(FrameMetrics.FIRST_DRAW_FRAME) == 1;
517             long frameVsyncId =
518                     mMetricsWrapper.getTiming()[FrameMetrics.Index.FRAME_TIMELINE_VSYNC_ID];
519 
520             if (!isInRange(frameVsyncId)) {
521                 return;
522             }
523             JankInfo info = findJankInfo(frameVsyncId);
524             if (info != null) {
525                 info.hwuiCallbackFired = true;
526                 info.totalDurationNanos = totalDurationNanos;
527                 info.isFirstFrame = isFirstFrame;
528             } else {
529                 mJankInfos.put((int) frameVsyncId, JankInfo.createFromHwuiCallback(
530                         frameVsyncId, totalDurationNanos, isFirstFrame));
531             }
532             processJankInfos();
533         });
534     }
535 
536     @UiThread
hasReceivedCallbacksAfterEnd()537     private boolean hasReceivedCallbacksAfterEnd() {
538         if (mEndVsyncId == INVALID_ID) {
539             return false;
540         }
541         JankInfo last = mJankInfos.size() == 0 ? null : mJankInfos.valueAt(mJankInfos.size() - 1);
542         if (last == null) {
543             return false;
544         }
545         if (last.frameVsyncId < mEndVsyncId) {
546             return false;
547         }
548         for (int i = mJankInfos.size() - 1; i >= 0; i--) {
549             JankInfo info = mJankInfos.valueAt(i);
550             if (info.frameVsyncId >= mEndVsyncId) {
551                 if (callbacksReceived(info)) {
552                     return true;
553                 }
554             }
555         }
556         return false;
557     }
558 
559     @UiThread
processJankInfos()560     private void processJankInfos() {
561         if (mMetricsFinalized) {
562             return;
563         }
564         if (!hasReceivedCallbacksAfterEnd()) {
565             return;
566         }
567         finish();
568     }
569 
callbacksReceived(JankInfo info)570     private boolean callbacksReceived(JankInfo info) {
571         return mSurfaceOnly
572                 ? info.surfaceControlCallbackFired
573                 : info.hwuiCallbackFired && info.surfaceControlCallbackFired;
574     }
575 
576     @UiThread
finish()577     private void finish() {
578         if (mMetricsFinalized || mCancelled) return;
579         mMetricsFinalized = true;
580 
581         getHandler().removeCallbacks(mWaitForFinishTimedOut);
582         mWaitForFinishTimedOut = null;
583         markEvent("FT#finish", mJankInfos.size());
584 
585         // The tracing has been ended, remove the observer, see if need to trigger perfetto.
586         removeObservers();
587 
588         int totalFramesCount = 0;
589         long maxFrameTimeNanos = 0;
590         int missedFramesCount = 0;
591         int missedAppFramesCount = 0;
592         int missedSfFramesCount = 0;
593         int maxSuccessiveMissedFramesCount = 0;
594         int successiveMissedFramesCount = 0;
595 
596         for (int i = 0; i < mJankInfos.size(); i++) {
597             JankInfo info = mJankInfos.valueAt(i);
598             final boolean isFirstDrawn = !mSurfaceOnly && info.isFirstFrame;
599             if (isFirstDrawn) {
600                 continue;
601             }
602             if (info.frameVsyncId > mEndVsyncId) {
603                 break;
604             }
605             if (info.surfaceControlCallbackFired) {
606                 totalFramesCount++;
607                 boolean missedFrame = false;
608                 if ((info.jankType & JANK_APP_DEADLINE_MISSED) != 0) {
609                     Log.w(TAG, "Missed App frame:" + info + ", CUJ=" + mSession.getName());
610                     missedAppFramesCount++;
611                     missedFrame = true;
612                 }
613                 if ((info.jankType & DISPLAY_HAL) != 0
614                         || (info.jankType & JANK_SURFACEFLINGER_DEADLINE_MISSED) != 0
615                         || (info.jankType & JANK_SURFACEFLINGER_GPU_DEADLINE_MISSED) != 0
616                         || (info.jankType & SURFACE_FLINGER_SCHEDULING) != 0
617                         || (info.jankType & PREDICTION_ERROR) != 0) {
618                     Log.w(TAG, "Missed SF frame:" + info + ", CUJ=" + mSession.getName());
619                     missedSfFramesCount++;
620                     missedFrame = true;
621                 }
622                 if (missedFrame) {
623                     missedFramesCount++;
624                     successiveMissedFramesCount++;
625                 } else {
626                     maxSuccessiveMissedFramesCount = Math.max(
627                             maxSuccessiveMissedFramesCount, successiveMissedFramesCount);
628                     successiveMissedFramesCount = 0;
629                 }
630                 // TODO (b/174755489): Early latch currently gets fired way too often, so we have
631                 // to ignore it for now.
632                 if (!mSurfaceOnly && !info.hwuiCallbackFired) {
633                     markEvent("FT#MissedHWUICallback", info.frameVsyncId);
634                     Log.w(TAG, "Missing HWUI jank callback for vsyncId: " + info.frameVsyncId
635                             + ", CUJ=" + mSession.getName());
636                 }
637             }
638             if (!mSurfaceOnly && info.hwuiCallbackFired) {
639                 maxFrameTimeNanos = Math.max(info.totalDurationNanos, maxFrameTimeNanos);
640                 if (!info.surfaceControlCallbackFired) {
641                     markEvent("FT#MissedSFCallback", info.frameVsyncId);
642                     Log.w(TAG, "Missing SF jank callback for vsyncId: " + info.frameVsyncId
643                             + ", CUJ=" + mSession.getName());
644                 }
645             }
646         }
647         maxSuccessiveMissedFramesCount = Math.max(
648                 maxSuccessiveMissedFramesCount, successiveMissedFramesCount);
649 
650         // Log the frame stats as counters to make them easily accessible in traces.
651         Trace.traceCounter(Trace.TRACE_TAG_APP, mSession.getName() + "#missedFrames",
652                 missedFramesCount);
653         Trace.traceCounter(Trace.TRACE_TAG_APP, mSession.getName() + "#missedAppFrames",
654                 missedAppFramesCount);
655         Trace.traceCounter(Trace.TRACE_TAG_APP, mSession.getName() + "#missedSfFrames",
656                 missedSfFramesCount);
657         Trace.traceCounter(Trace.TRACE_TAG_APP, mSession.getName() + "#totalFrames",
658                 totalFramesCount);
659         Trace.traceCounter(Trace.TRACE_TAG_APP, mSession.getName() + "#maxFrameTimeMillis",
660                 (int) (maxFrameTimeNanos / NANOS_IN_MILLISECOND));
661         Trace.traceCounter(Trace.TRACE_TAG_APP, mSession.getName() + "#maxSuccessiveMissedFrames",
662                 maxSuccessiveMissedFramesCount);
663 
664         // Trigger perfetto if necessary.
665         if (shouldTriggerPerfetto(missedFramesCount, (int) maxFrameTimeNanos)) {
666             triggerPerfetto();
667         }
668         if (mSession.logToStatsd()) {
669             mStatsLog.write(
670                     FrameworkStatsLog.UI_INTERACTION_FRAME_INFO_REPORTED,
671                     mDisplayId,
672                     mSession.getStatsdInteractionType(),
673                     totalFramesCount,
674                     missedFramesCount,
675                     maxFrameTimeNanos, /* will be 0 if mSurfaceOnly == true */
676                     missedSfFramesCount,
677                     missedAppFramesCount,
678                     maxSuccessiveMissedFramesCount);
679         }
680         if (DEBUG) {
681             Log.i(TAG, "finish: CUJ=" + mSession.getName()
682                     + " (" + mBeginVsyncId + "," + mEndVsyncId + ")"
683                     + " totalFrames=" + totalFramesCount
684                     + " missedAppFrames=" + missedAppFramesCount
685                     + " missedSfFrames=" + missedSfFramesCount
686                     + " missedFrames=" + missedFramesCount
687                     + " maxFrameTimeMillis=" + maxFrameTimeNanos / NANOS_IN_MILLISECOND
688                     + " maxSuccessiveMissedFramesCount=" + maxSuccessiveMissedFramesCount);
689         }
690     }
691 
getThreadedRenderer()692     ThreadedRendererWrapper getThreadedRenderer() {
693         return mRendererWrapper;
694     }
695 
getViewRoot()696     ViewRootWrapper getViewRoot() {
697         return mViewRoot;
698     }
699 
shouldTriggerPerfetto(int missedFramesCount, int maxFrameTimeNanos)700     private boolean shouldTriggerPerfetto(int missedFramesCount, int maxFrameTimeNanos) {
701         boolean overMissedFramesThreshold = mTraceThresholdMissedFrames != -1
702                 && missedFramesCount >= mTraceThresholdMissedFrames;
703         boolean overFrameTimeThreshold = !mSurfaceOnly && mTraceThresholdFrameTimeMillis != -1
704                 && maxFrameTimeNanos >= mTraceThresholdFrameTimeMillis * NANOS_IN_MILLISECOND;
705         return overMissedFramesThreshold || overFrameTimeThreshold;
706     }
707 
708     /**
709      * Remove all the registered listeners, observers and callbacks.
710      */
711     @VisibleForTesting
712     @UiThread
removeObservers()713     public void removeObservers() {
714         mSurfaceControlWrapper.removeJankStatsListener(this);
715         if (!mSurfaceOnly) {
716             // HWUI part.
717             mRendererWrapper.removeObserver(mObserver);
718             if (mSurfaceChangedCallback != null) {
719                 mViewRoot.removeSurfaceChangedCallback(mSurfaceChangedCallback);
720             }
721         }
722     }
723 
724     /**
725      * Trigger the prefetto daemon.
726      */
triggerPerfetto()727     public void triggerPerfetto() {
728         mMonitor.trigger(mSession);
729     }
730 
731     /**
732      * A wrapper class that we can spy FrameMetrics (a final class) in unit tests.
733      */
734     public static class FrameMetricsWrapper {
735         private final FrameMetrics mFrameMetrics;
736 
FrameMetricsWrapper()737         public FrameMetricsWrapper() {
738             mFrameMetrics = new FrameMetrics();
739         }
740 
741         /**
742          * Wrapper method.
743          * @return timing data of the metrics
744          */
getTiming()745         public long[] getTiming() {
746             return mFrameMetrics.mTimingData;
747         }
748 
749         /**
750          * Wrapper method.
751          * @param index specific index of the timing data
752          * @return the timing data of the specified index
753          */
getMetric(int index)754         public long getMetric(int index) {
755             return mFrameMetrics.getMetric(index);
756         }
757     }
758 
759     /**
760      * A wrapper class that we can spy ThreadedRenderer (a final class) in unit tests.
761      */
762     public static class ThreadedRendererWrapper {
763         private final ThreadedRenderer mRenderer;
764 
ThreadedRendererWrapper(ThreadedRenderer renderer)765         public ThreadedRendererWrapper(ThreadedRenderer renderer) {
766             mRenderer = renderer;
767         }
768 
769         /**
770          * Wrapper method.
771          * @param observer observer
772          */
addObserver(HardwareRendererObserver observer)773         public void addObserver(HardwareRendererObserver observer) {
774             mRenderer.addObserver(observer);
775         }
776 
777         /**
778          * Wrapper method.
779          * @param observer observer
780          */
removeObserver(HardwareRendererObserver observer)781         public void removeObserver(HardwareRendererObserver observer) {
782             mRenderer.removeObserver(observer);
783         }
784     }
785 
786     public static class ViewRootWrapper {
787         private final ViewRootImpl mViewRoot;
788 
ViewRootWrapper(ViewRootImpl viewRoot)789         public ViewRootWrapper(ViewRootImpl viewRoot) {
790             mViewRoot = viewRoot;
791         }
792 
793         /**
794          * {@link ViewRootImpl#addSurfaceChangedCallback(ViewRootImpl.SurfaceChangedCallback)}
795          * @param callback {@link ViewRootImpl.SurfaceChangedCallback}
796          */
addSurfaceChangedCallback(ViewRootImpl.SurfaceChangedCallback callback)797         public void addSurfaceChangedCallback(ViewRootImpl.SurfaceChangedCallback callback) {
798             mViewRoot.addSurfaceChangedCallback(callback);
799         }
800 
801         /**
802          * {@link ViewRootImpl#removeSurfaceChangedCallback(ViewRootImpl.SurfaceChangedCallback)}
803          * @param callback {@link ViewRootImpl.SurfaceChangedCallback}
804          */
removeSurfaceChangedCallback(ViewRootImpl.SurfaceChangedCallback callback)805         public void removeSurfaceChangedCallback(ViewRootImpl.SurfaceChangedCallback callback) {
806             mViewRoot.removeSurfaceChangedCallback(callback);
807         }
808 
getSurfaceControl()809         public SurfaceControl getSurfaceControl() {
810             return mViewRoot.getSurfaceControl();
811         }
812 
requestInvalidateRootRenderNode()813         void requestInvalidateRootRenderNode() {
814             mViewRoot.requestInvalidateRootRenderNode();
815         }
816 
addWindowCallbacks(WindowCallbacks windowCallbacks)817         void addWindowCallbacks(WindowCallbacks windowCallbacks) {
818             mViewRoot.addWindowCallbacks(windowCallbacks);
819         }
820 
removeWindowCallbacks(WindowCallbacks windowCallbacks)821         void removeWindowCallbacks(WindowCallbacks windowCallbacks) {
822             mViewRoot.removeWindowCallbacks(windowCallbacks);
823         }
824 
getView()825         View getView() {
826             return mViewRoot.getView();
827         }
828 
dipToPx(int dip)829         int dipToPx(int dip) {
830             final DisplayMetrics displayMetrics =
831                     mViewRoot.mContext.getResources().getDisplayMetrics();
832             return (int) (displayMetrics.density * dip + 0.5f);
833         }
834     }
835 
836     public static class SurfaceControlWrapper {
837 
addJankStatsListener(SurfaceControl.OnJankDataListener listener, SurfaceControl surfaceControl)838         public void addJankStatsListener(SurfaceControl.OnJankDataListener listener,
839                 SurfaceControl surfaceControl) {
840             SurfaceControl.addJankDataListener(listener, surfaceControl);
841         }
842 
removeJankStatsListener(SurfaceControl.OnJankDataListener listener)843         public void removeJankStatsListener(SurfaceControl.OnJankDataListener listener) {
844             SurfaceControl.removeJankDataListener(listener);
845         }
846     }
847 
848     public static class ChoreographerWrapper {
849 
850         private final Choreographer mChoreographer;
851 
ChoreographerWrapper(Choreographer choreographer)852         public ChoreographerWrapper(Choreographer choreographer) {
853             mChoreographer = choreographer;
854         }
855 
getVsyncId()856         public long getVsyncId() {
857             return mChoreographer.getVsyncId();
858         }
859     }
860 
861     public static class StatsLogWrapper {
862         private final DisplayResolutionTracker mDisplayResolutionTracker;
863 
StatsLogWrapper(DisplayResolutionTracker displayResolutionTracker)864         public StatsLogWrapper(DisplayResolutionTracker displayResolutionTracker) {
865             mDisplayResolutionTracker = displayResolutionTracker;
866         }
867 
868         /** {@see FrameworkStatsLog#write) */
write(int code, int displayId, int arg1, long arg2, long arg3, long arg4, long arg5, long arg6, long arg7)869         public void write(int code, int displayId,
870                 int arg1, long arg2, long arg3, long arg4, long arg5, long arg6, long arg7) {
871             FrameworkStatsLog.write(code, arg1, arg2, arg3, arg4, arg5, arg6, arg7,
872                     mDisplayResolutionTracker.getResolution(displayId));
873         }
874     }
875 
876     /**
877      * A listener that notifies cuj events.
878      */
879     public interface FrameTrackerListener {
880         /**
881          * Notify that the CUJ session was created.
882          *
883          * @param session the CUJ session
884          * @param action the specific action
885          */
onCujEvents(Session session, String action)886         void onCujEvents(Session session, String action);
887     }
888 }
889