Add logs and traces when draw doesn't run
Add additional traces and logs that will provide more info on when a
draw doesn't proceed due to screen being turned off, content not
visible, or if draw is canceled.
Bug: 284687313
Bug: 305595315
Test: Logcat and perfetto traces
Change-Id: Ieacc78332716aa6628d67ca3227b6995ec7bb49e
diff --git a/core/java/android/view/ViewRootImpl.java b/core/java/android/view/ViewRootImpl.java
index 52b7cb1..7cee4cb 100644
--- a/core/java/android/view/ViewRootImpl.java
+++ b/core/java/android/view/ViewRootImpl.java
@@ -661,6 +661,10 @@
*/
private boolean mCheckIfCanDraw = false;
+ private boolean mWasLastDrawCanceled;
+ private boolean mLastTraversalWasVisible = true;
+ private boolean mLastDrawScreenOff;
+
private boolean mDrewOnceForSync = false;
int mSyncSeqId = 0;
@@ -1925,12 +1929,19 @@
}
void handleAppVisibility(boolean visible) {
+ if (Trace.isTagEnabled(Trace.TRACE_TAG_VIEW)) {
+ Trace.instant(Trace.TRACE_TAG_VIEW, TextUtils.formatSimple(
+ "%s visibilityChanged oldVisibility=%b newVisibility=%b", mTag,
+ mAppVisible, visible));
+ }
if (mAppVisible != visible) {
final boolean previousVisible = getHostVisibility() == View.VISIBLE;
mAppVisible = visible;
final boolean currentVisible = getHostVisibility() == View.VISIBLE;
// Root view only cares about whether it is visible or not.
if (previousVisible != currentVisible) {
+ Log.d(mTag, "visibilityChanged oldVisibility=" + previousVisible + " newVisibility="
+ + currentVisible);
mAppVisibilityChanged = true;
scheduleTraversals();
}
@@ -3287,8 +3298,8 @@
|| mForceNextWindowRelayout) {
if (Trace.isTagEnabled(Trace.TRACE_TAG_VIEW)) {
Trace.traceBegin(Trace.TRACE_TAG_VIEW,
- TextUtils.formatSimple("relayoutWindow#"
- + "first=%b/resize=%b/vis=%b/params=%b/force=%b",
+ TextUtils.formatSimple("%s-relayoutWindow#"
+ + "first=%b/resize=%b/vis=%b/params=%b/force=%b", mTag,
mFirst, windowShouldResize, viewVisibilityChanged, params != null,
mForceNextWindowRelayout));
}
@@ -3877,11 +3888,7 @@
boolean cancelDueToPreDrawListener = mAttachInfo.mTreeObserver.dispatchOnPreDraw();
boolean cancelAndRedraw = cancelDueToPreDrawListener
|| (cancelDraw && mDrewOnceForSync);
- if (cancelAndRedraw) {
- Log.d(mTag, "Cancelling draw."
- + " cancelDueToPreDrawListener=" + cancelDueToPreDrawListener
- + " cancelDueToSync=" + (cancelDraw && mDrewOnceForSync));
- }
+
if (!cancelAndRedraw) {
// A sync was already requested before the WMS requested sync. This means we need to
// sync the buffer, regardless if WMS wants to sync the buffer.
@@ -3905,6 +3912,9 @@
}
if (!isViewVisible) {
+ if (mLastTraversalWasVisible) {
+ logAndTrace("Not drawing due to not visible");
+ }
mLastPerformTraversalsSkipDrawReason = "view_not_visible";
if (mPendingTransitions != null && mPendingTransitions.size() > 0) {
for (int i = 0; i < mPendingTransitions.size(); ++i) {
@@ -3916,12 +3926,23 @@
handleSyncRequestWhenNoAsyncDraw(mActiveSurfaceSyncGroup, mHasPendingTransactions,
mPendingTransaction, "view not visible");
} else if (cancelAndRedraw) {
+ if (!mWasLastDrawCanceled) {
+ logAndTrace("Canceling draw."
+ + " cancelDueToPreDrawListener=" + cancelDueToPreDrawListener
+ + " cancelDueToSync=" + (cancelDraw && mDrewOnceForSync));
+ }
mLastPerformTraversalsSkipDrawReason = cancelDueToPreDrawListener
? "predraw_" + mAttachInfo.mTreeObserver.getLastDispatchOnPreDrawCanceledReason()
: "cancel_" + cancelReason;
// Try again
scheduleTraversals();
} else {
+ if (mWasLastDrawCanceled) {
+ logAndTrace("Draw frame after cancel");
+ }
+ if (!mLastTraversalWasVisible) {
+ logAndTrace("Start draw after previous draw not visible");
+ }
if (mPendingTransitions != null && mPendingTransitions.size() > 0) {
for (int i = 0; i < mPendingTransitions.size(); ++i) {
mPendingTransitions.get(i).startChangingAnimations();
@@ -3933,6 +3954,8 @@
mPendingTransaction, mLastPerformDrawSkippedReason);
}
}
+ mWasLastDrawCanceled = cancelAndRedraw;
+ mLastTraversalWasVisible = isViewVisible;
if (mAttachInfo.mContentCaptureEvents != null) {
notifyContentCaptureEvents();
@@ -4728,10 +4751,7 @@
return didProduceBuffer -> {
if (!didProduceBuffer) {
- Trace.instant(Trace.TRACE_TAG_VIEW,
- "Transaction not synced due to no frame drawn-" + mTag);
- Log.d(mTag, "Pending transaction will not be applied in sync with a draw "
- + "because there was nothing new to draw");
+ logAndTrace("Transaction not synced due to no frame drawn");
mBlastBufferQueue.applyPendingTransactions(frame);
}
};
@@ -4748,17 +4768,26 @@
mLastPerformDrawSkippedReason = null;
if (mAttachInfo.mDisplayState == Display.STATE_OFF && !mReportNextDraw) {
mLastPerformDrawSkippedReason = "screen_off";
+ if (!mLastDrawScreenOff) {
+ logAndTrace("Not drawing due to screen off");
+ }
+ mLastDrawScreenOff = true;
return false;
} else if (mView == null) {
mLastPerformDrawSkippedReason = "no_root_view";
return false;
}
+ if (mLastDrawScreenOff) {
+ logAndTrace("Resumed drawing after screen turned on");
+ mLastDrawScreenOff = false;
+ }
+
final boolean fullRedrawNeeded = mFullRedrawNeeded || surfaceSyncGroup != null;
mFullRedrawNeeded = false;
mIsDrawing = true;
- Trace.traceBegin(Trace.TRACE_TAG_VIEW, "draw");
+ Trace.traceBegin(Trace.TRACE_TAG_VIEW, mTag + "-draw");
addFrameCommitCallbackIfNeeded();
@@ -11512,8 +11541,7 @@
@Override
public boolean applyTransactionOnDraw(@NonNull SurfaceControl.Transaction t) {
if (mRemoved || !isHardwareEnabled()) {
- Trace.instant(Trace.TRACE_TAG_VIEW, "applyTransactionOnDraw applyImmediately-" + mTag);
- Log.d(mTag, "applyTransactionOnDraw: Applying transaction immediately");
+ logAndTrace("applyTransactionOnDraw applyImmediately");
t.apply();
} else {
Trace.instant(Trace.TRACE_TAG_VIEW, "applyTransactionOnDraw-" + mTag);
@@ -11990,4 +12018,11 @@
public float getPreferredFrameRate() {
return mPreferredFrameRate;
}
+
+ private void logAndTrace(String msg) {
+ if (Trace.isTagEnabled(Trace.TRACE_TAG_VIEW)) {
+ Trace.instant(Trace.TRACE_TAG_VIEW, mTag + "-" + msg);
+ }
+ Log.d(mTag, msg);
+ }
}