From 4465d8dc2aabf2539082b890fcbac23a18e47b5b Mon Sep 17 00:00:00 2001 From: Nicolo' Mazzucato Date: Thu, 19 Jan 2023 17:43:32 +0000 Subject: [PATCH] Introduce a way to debug relayouts and slow measures/layout This cl introduces a way to debug 2 different but related things: (1) Which classes suffer from long measure and layout pass (2) What caused those classes to be re-measured/re-layout In the current form, only sysui sets the flags to enable the above based on some sysprop. (1) is enabled by `adb shell setprop persist.debug.trace_layouts 1` for all classes in sysui process (note: the process needs to restart). The ideal workflow is to first enable this to spot which are the main classes have long measure/layout slices. Once those are identified (e.g. class X) (2) `adb shell setprop persist.debug.trace_request_layout_class X` enables requestLayout tracing for class X. At this point, every time requestLayout is called on that class, both an instant event (visible in perfetto) and the stacktrace (in logcat) is output. After recording at perfetto trace with (2) enabled, it's possible to aggregate data with an SQL query in ui.perfetto.dev: For example, with the following we can have the most common relayout reasons: ``` SELECT count(*) cnt, msg FROM android_logs WHERE msg LIKE "requestLayout %" GROUP BY msg ORDER BY cnt DESC ``` The following helper bash function makes the above more efficient: trace_class_layouts() { adb shell setprop persist.debug.trace_layouts 1 adb shell setprop persist.debug.trace_request_layout_class $1 adb shell am force-stop com.google.android.apps.nexuslauncher adb shell am force-stop com.android.systemui } Then, use `trace_class_layouts X` and record a perfetto trace. To reduce the overhead, several strings are cached when the view is attached to the window. However, it should be noted that enabling this can have an impact on performance and should only be used for debugging purposes. Test: record a trace after enabling options Bug: 266090955 Merged-In: I89a518d4f3c69c13cdced0f70d8a1e2793bc923a Change-Id: I89a518d4f3c69c13cdced0f70d8a1e2793bc923a --- core/java/android/os/Trace.java | 3 +- core/java/android/view/View.java | 153 +++++++++++++++++- .../view/ViewTraversalTracingStrings.java | 63 ++++++++ .../android/systemui/SystemUIApplication.java | 6 + 4 files changed, 219 insertions(+), 6 deletions(-) create mode 100644 core/java/android/view/ViewTraversalTracingStrings.java diff --git a/core/java/android/os/Trace.java b/core/java/android/os/Trace.java index ac2156e9e46ef..ca34337643081 100644 --- a/core/java/android/os/Trace.java +++ b/core/java/android/os/Trace.java @@ -109,7 +109,8 @@ public final class Trace { public static final long TRACE_TAG_THERMAL = 1L << 27; private static final long TRACE_TAG_NOT_READY = 1L << 63; - private static final int MAX_SECTION_NAME_LEN = 127; + /** @hide **/ + public static final int MAX_SECTION_NAME_LEN = 127; // Must be volatile to avoid word tearing. // This is only kept in case any apps get this by reflection but do not diff --git a/core/java/android/view/View.java b/core/java/android/view/View.java index 333efad2c4c86..d7480e5037f4e 100644 --- a/core/java/android/view/View.java +++ b/core/java/android/view/View.java @@ -17,6 +17,7 @@ package android.view; import static android.content.res.Resources.ID_NULL; +import static android.os.Trace.TRACE_TAG_APP; import static android.view.ContentInfo.SOURCE_DRAG_AND_DROP; import static android.view.accessibility.AccessibilityEvent.CONTENT_CHANGE_TYPE_UNDEFINED; import static android.view.displayhash.DisplayHashResultCallback.DISPLAY_HASH_ERROR_INVALID_BOUNDS; @@ -984,6 +985,22 @@ public class View implements Drawable.Callback, KeyEvent.Callback, */ private static boolean sAcceptZeroSizeDragShadow; + /** + * When true, measure and layout passes of all the newly attached views will be logged with + * {@link Trace}, so we can better debug jank due to complex view hierarchies. + */ + private static boolean sTraceLayoutSteps; + + /** + * When not null, emits a {@link Trace} instant event and the stacktrace every time a relayout + * of a class having this name happens. + */ + private static String sTraceRequestLayoutClass; + + /** Used to avoid computing the full strings each time when layout tracing is enabled. */ + @Nullable + private ViewTraversalTracingStrings mTracingStrings; + /** * Prior to R, {@link #dispatchApplyWindowInsets} had an issue: *

The modified insets changed by {@link #onApplyWindowInsets} were passed to the @@ -3532,6 +3549,8 @@ public class View implements Drawable.Callback, KeyEvent.Callback, * 1 PFLAG4_HAS_TRANSLATION_TRANSIENT_STATE * 1 PFLAG4_DRAG_A11Y_STARTED * 1 PFLAG4_AUTO_HANDWRITING_INITIATION_ENABLED + * 1 PFLAG4_TRAVERSAL_TRACING_ENABLED + * 1 PFLAG4_RELAYOUT_TRACING_ENABLED * |-------|-------|-------|-------| */ @@ -3612,6 +3631,19 @@ public class View implements Drawable.Callback, KeyEvent.Callback, * Indicates that the view enables auto handwriting initiation. */ private static final int PFLAG4_AUTO_HANDWRITING_ENABLED = 0x000010000; + + /** + * When set, measure and layout passes of this view will be logged with {@link Trace}, so we + * can better debug jank due to complex view hierarchies. + */ + private static final int PFLAG4_TRAVERSAL_TRACING_ENABLED = 0x000040000; + + /** + * When set, emits a {@link Trace} instant event and stacktrace every time a requestLayout of + * this class happens. + */ + private static final int PFLAG4_RELAYOUT_TRACING_ENABLED = 0x000080000; + /* End of masks for mPrivateFlags4 */ /** @hide */ @@ -6537,6 +6569,15 @@ public class View implements Drawable.Callback, KeyEvent.Callback, out.append(mRight); out.append(','); out.append(mBottom); + appendId(out); + if (mAutofillId != null) { + out.append(" aid="); out.append(mAutofillId); + } + out.append("}"); + return out.toString(); + } + + void appendId(StringBuilder out) { final int id = getId(); if (id != NO_ID) { out.append(" #"); @@ -6568,11 +6609,6 @@ public class View implements Drawable.Callback, KeyEvent.Callback, } } } - if (mAutofillId != null) { - out.append(" aid="); out.append(mAutofillId); - } - out.append("}"); - return out.toString(); } /** @@ -20767,6 +20803,14 @@ public class View implements Drawable.Callback, KeyEvent.Callback, if (isFocused()) { notifyFocusChangeToImeFocusController(true /* hasFocus */); } + + if (sTraceLayoutSteps) { + setTraversalTracingEnabled(true); + } + if (sTraceRequestLayoutClass != null + && sTraceRequestLayoutClass.equals(getClass().getSimpleName())) { + setRelayoutTracingEnabled(true); + } } /** @@ -23666,6 +23710,30 @@ public class View implements Drawable.Callback, KeyEvent.Callback, return o instanceof ViewGroup && ((ViewGroup) o).isLayoutModeOptical(); } + /** + * Enable measure/layout debugging on traces. + * + * @see Trace + * @hide + */ + public static void setTraceLayoutSteps(boolean traceLayoutSteps) { + sTraceLayoutSteps = traceLayoutSteps; + } + + /** + * Enable request layout tracing classes with {@code s} simple name. + *

+ * When set, a {@link Trace} instant event and a log with the stacktrace is emitted every + * time a requestLayout of a class matching {@code s} name happens. + * This applies only to views attached from this point onwards. + * + * @see Trace#instant(long, String) + * @hide + */ + public static void setTracedRequestLayoutClassClass(String s) { + sTraceRequestLayoutClass = s; + } + private boolean setOpticalFrame(int left, int top, int right, int bottom) { Insets parentInsets = mParent instanceof View ? ((View) mParent).getOpticalInsets() : Insets.NONE; @@ -23700,7 +23768,13 @@ public class View implements Drawable.Callback, KeyEvent.Callback, @SuppressWarnings({"unchecked"}) public void layout(int l, int t, int r, int b) { if ((mPrivateFlags3 & PFLAG3_MEASURE_NEEDED_BEFORE_LAYOUT) != 0) { + if (isTraversalTracingEnabled()) { + Trace.beginSection(mTracingStrings.onMeasureBeforeLayout); + } onMeasure(mOldWidthMeasureSpec, mOldHeightMeasureSpec); + if (isTraversalTracingEnabled()) { + Trace.endSection(); + } mPrivateFlags3 &= ~PFLAG3_MEASURE_NEEDED_BEFORE_LAYOUT; } @@ -23713,7 +23787,13 @@ public class View implements Drawable.Callback, KeyEvent.Callback, setOpticalFrame(l, t, r, b) : setFrame(l, t, r, b); if (changed || (mPrivateFlags & PFLAG_LAYOUT_REQUIRED) == PFLAG_LAYOUT_REQUIRED) { + if (isTraversalTracingEnabled()) { + Trace.beginSection(mTracingStrings.onLayout); + } onLayout(changed, l, t, r, b); + if (isTraversalTracingEnabled()) { + Trace.endSection(); + } if (shouldDrawRoundScrollbar()) { if(mRoundScrollbarRenderer == null) { @@ -26270,6 +26350,25 @@ public class View implements Drawable.Callback, KeyEvent.Callback, return (viewRoot != null && viewRoot.isInLayout()); } + /** To be used only for debugging purposes. */ + private void printStackStrace(String name) { + Log.d(VIEW_LOG_TAG, "---- ST:" + name); + + StringBuilder sb = new StringBuilder(); + StackTraceElement[] stackTraceElements = Thread.currentThread().getStackTrace(); + int startIndex = 1; + int endIndex = Math.min(stackTraceElements.length, startIndex + 20); // max 20 entries. + for (int i = startIndex; i < endIndex; i++) { + StackTraceElement s = stackTraceElements[i]; + sb.append(s.getMethodName()) + .append("(") + .append(s.getFileName()) + .append(":") + .append(s.getLineNumber()) + .append(") <- "); + } + Log.d(VIEW_LOG_TAG, name + ": " + sb); + } /** * Call this when something has changed which has invalidated the * layout of this view. This will schedule a layout pass of the view @@ -26283,6 +26382,12 @@ public class View implements Drawable.Callback, KeyEvent.Callback, */ @CallSuper public void requestLayout() { + if (isRelayoutTracingEnabled()) { + Trace.instantForTrack(TRACE_TAG_APP, "requestLayoutTracing", + mTracingStrings.classSimpleName); + printStackStrace(mTracingStrings.requestLayoutStacktracePrefix); + } + if (mMeasureCache != null) mMeasureCache.clear(); if (mAttachInfo != null && mAttachInfo.mViewRequestingLayout == null) { @@ -26376,8 +26481,14 @@ public class View implements Drawable.Callback, KeyEvent.Callback, int cacheIndex = forceLayout ? -1 : mMeasureCache.indexOfKey(key); if (cacheIndex < 0 || sIgnoreMeasureCache) { + if (isTraversalTracingEnabled()) { + Trace.beginSection(mTracingStrings.onMeasure); + } // measure ourselves, this should set the measured dimension flag back onMeasure(widthMeasureSpec, heightMeasureSpec); + if (isTraversalTracingEnabled()) { + Trace.endSection(); + } mPrivateFlags3 &= ~PFLAG3_MEASURE_NEEDED_BEFORE_LAYOUT; } else { long value = mMeasureCache.valueAt(cacheIndex); @@ -31547,6 +31658,38 @@ public class View implements Drawable.Callback, KeyEvent.Callback, == PFLAG4_AUTO_HANDWRITING_ENABLED; } + private void setTraversalTracingEnabled(boolean enabled) { + if (enabled) { + if (mTracingStrings == null) { + mTracingStrings = new ViewTraversalTracingStrings(this); + } + mPrivateFlags4 |= PFLAG4_TRAVERSAL_TRACING_ENABLED; + } else { + mPrivateFlags4 &= ~PFLAG4_TRAVERSAL_TRACING_ENABLED; + } + } + + private boolean isTraversalTracingEnabled() { + return (mPrivateFlags4 & PFLAG4_TRAVERSAL_TRACING_ENABLED) + == PFLAG4_TRAVERSAL_TRACING_ENABLED; + } + + private void setRelayoutTracingEnabled(boolean enabled) { + if (enabled) { + if (mTracingStrings == null) { + mTracingStrings = new ViewTraversalTracingStrings(this); + } + mPrivateFlags4 |= PFLAG4_RELAYOUT_TRACING_ENABLED; + } else { + mPrivateFlags4 &= ~PFLAG4_RELAYOUT_TRACING_ENABLED; + } + } + + private boolean isRelayoutTracingEnabled() { + return (mPrivateFlags4 & PFLAG4_RELAYOUT_TRACING_ENABLED) + == PFLAG4_RELAYOUT_TRACING_ENABLED; + } + /** * Collects a {@link ViewTranslationRequest} which represents the content to be translated in * the view. diff --git a/core/java/android/view/ViewTraversalTracingStrings.java b/core/java/android/view/ViewTraversalTracingStrings.java new file mode 100644 index 0000000000000..7dde87bad26e3 --- /dev/null +++ b/core/java/android/view/ViewTraversalTracingStrings.java @@ -0,0 +1,63 @@ +/* + * Copyright (C) 2023 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package android.view; + +import android.os.Trace; + +/** + * Keeps and caches strings used to trace {@link View} traversals. + *

+ * This is done to avoid expensive computations of them every time, which can improve performance. + */ +class ViewTraversalTracingStrings { + + /** {@link Trace} tag used to mark {@link View#onMeasure(int, int)}. */ + public final String onMeasure; + + /** {@link Trace} tag used to mark {@link View#onLayout(boolean, int, int, int, int)}. */ + public final String onLayout; + + /** Caches the view simple name to avoid re-computations. */ + public final String classSimpleName; + + /** Prefix for request layout stacktraces output in logs. */ + public final String requestLayoutStacktracePrefix; + + /** {@link Trace} tag used to mark {@link View#onMeasure(int, int)} happening before layout. */ + public final String onMeasureBeforeLayout; + + /** + * @param v {@link View} from where to get the class name. + */ + ViewTraversalTracingStrings(View v) { + String className = v.getClass().getSimpleName(); + classSimpleName = className; + onMeasureBeforeLayout = getTraceName("onMeasureBeforeLayout", className, v); + onMeasure = getTraceName("onMeasure", className, v); + onLayout = getTraceName("onLayout", className, v); + requestLayoutStacktracePrefix = "requestLayout " + className; + } + + private String getTraceName(String sectionName, String className, View v) { + StringBuilder out = new StringBuilder(); + out.append(sectionName); + out.append(" "); + out.append(className); + v.appendId(out); + return out.substring(0, Math.min(out.length() - 1, Trace.MAX_SECTION_NAME_LEN - 1)); + } +} diff --git a/packages/SystemUI/src/com/android/systemui/SystemUIApplication.java b/packages/SystemUI/src/com/android/systemui/SystemUIApplication.java index 191ac76753bbc..b62217f11132a 100644 --- a/packages/SystemUI/src/com/android/systemui/SystemUIApplication.java +++ b/packages/SystemUI/src/com/android/systemui/SystemUIApplication.java @@ -40,6 +40,7 @@ import android.util.Log; import android.util.TimingsTraceLog; import android.view.SurfaceControl; import android.view.ThreadedRenderer; +import android.view.View; import com.android.internal.protolog.common.ProtoLog; import com.android.systemui.dagger.GlobalRootComponent; @@ -114,6 +115,11 @@ public class SystemUIApplication extends Application implements // the theme set there. setTheme(R.style.Theme_SystemUI); + View.setTraceLayoutSteps( + SystemProperties.getBoolean("persist.debug.trace_layouts", false)); + View.setTracedRequestLayoutClassClass( + SystemProperties.get("persist.debug.trace_request_layout_class", null)); + if (Process.myUserHandle().equals(UserHandle.SYSTEM)) { IntentFilter bootCompletedFilter = new IntentFilter(Intent.ACTION_LOCKED_BOOT_COMPLETED);