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