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