Improve tracing #93086

Hixie · 2021-11-04T23:48:43Z

Add a test for tracing the framework.
Add a DiagnosticsNode.toTimelineArguments() that can be used easily with Timeline.startSync.
Rename some of the timeline events for clarity: hot reload dirtying now says "Hot Reload" for example, and the phases are in all caps (BUILD, LAYOUT, etc).
Always flag intrinsic and dry layout logic in debug and profile builds. Normally this only flags one event; when debugProfileLayoutsEnabled is true it shows the entire path. Might be good to have this flagged in the DevTools. Fixes Surface cost of intrinsics calculations in traces #93031.
Fix a broken link by pointing to our official documentation instead of Fuchsia documentation. Fixes Broken link in the API docs of debugProfileLayoutsEnabled and other debug flags #92044.
Change how painting is traced when debugProfilePaintsEnabled is on to be more comprehensive.
Add some details to the top-level timeline events, e.g. what nodes are dirty, when the relevant debugProfile*Enabled flags are on.
Include the Diagnosticable information about a RenderObject or a Widget in the information logged when debugProfileLayoutsEnabled, debugProfilePaintsEnabled, or debugProfileBuildsEnabled are on. Fixes debugProfileBuildsEnabled and other equivalents should include arguments #93009
Refactor how tracing is done in the widgets library so that RenderObjectWidgets are included in the timeline when debugProfileBuildsEnabled is on. Fixes debugProfileBuildsEnabled doesn't show RenderObjectWidgets #93007.
Guard all Timeline.startSync calls with !kReleaseMode.

Also:

Fix a minor error we introduced with the null safety migration: DiagnosticsNode.toDescription should return non-null. (Most of the logic either assumed that or already enforced it.)
Implement debugFillProperties for Placeholder and RenderCustomPaint, to help with the tests that were added.
Remove a TODO in objects.dart that we're never going to get to.
Improve some docs on BuildContext.
Cache _dirtyElements[index] in buildScope.
Improve docs for operator == on Widget. Fixes Document why Widget.operator== is marked as non-virtual #49490.
Remove some code duplication in framework.dart.
Clean up _NullWidget a bit.

Hixie · 2021-11-05T02:23:14Z

Errors are because I added properties to Placeholder / RenderCustomPaint so the tests that dump things got messed up.

goderbauer

nit: analyzer task is complaining about some whitespace.

goderbauer · 2021-11-09T18:21:32Z

packages/flutter/lib/src/widgets/framework.dart

-  /// Returns a description of an [Element] from the current build context.
+  /// Returns a description of the [Element] associated with the current build context.
+  ///
+  /// The `name` is typically something like "The element being rebuilt was".


nit (and not really related to this PR): name seems like an unfortunate naming choice for a parameter that contains a string like that...

yeah, it's inherited from the superclass where it makes more sense.

goderbauer · 2021-11-09T18:27:04Z

packages/flutter/lib/src/widgets/framework.dart

+        if (!kReleaseMode && debugProfileBuildsEnabled) {
+          Timeline.startSync(
+            '${element.widget.runtimeType}',
+            arguments: element.widget.toDiagnosticsNode().toTimelineArguments(),


Is there a performance cost associated with including all this information? Will this make it harder to compare relative performance of two widget builds if one widget includes a lot of information and the other doesn't?

I guess, the performance overhead of this is "charged" to the overall "BUILD" task and not the individual widgets, so it shouldn't make those comparisons harder?

It's charged to the parent widget.

My perspective was that we'd mostly given up on making these traces representative of actual time. The tracing alone dramatically skews the numbers. It does go rather against #93262 though.

Can we put these extra arguments behind a flag then? While performance debugging customer:money it has been helpful to at least see relative performance differences between the individual widgets in the debugProfileBuildsEnabled mode to identify "slow widgets" (same for RenderObjects). As I said in #93262 I'd rather want make this mode faster than slower to make performance debugging even easier. Handling two traces (one with the extra profiling enabled and one without to get accurate numbers) has not been practical.

There's already a flag: --profile. The arguments aren't added in profile builds. (In debug builds the traces aren't representative anyway because of JIT/AOT differences.)

oh that said i see that i missed the case that you're commenting on, oops

ah, it looks like i missed this in all the important cases. Somehow I remembered to protect it only in the rare cases.

goderbauer · 2021-11-09T18:37:48Z

packages/flutter/lib/src/rendering/object.dart

@@ -175,8 +175,6 @@ class PaintingContext extends ClipContext {
  /// into the layer subtree associated with this painting context. Otherwise,
  /// the child will be painted into the current PictureLayer for this context.
  void paintChild(RenderObject child, Offset offset) {
-    if (!kReleaseMode && debugProfilePaintsEnabled)


Why are these getting moved into _paintWithContext? Shouldn't a child that is a repaintBoundary have the cost of being one associated with them?

Both codepaths go through _paintWithContext when they do work. Mostly I was trying to bring this closer to the code that actually calls paint(), because I couldn't understand how it worked (at first I thought that there was no paint tracing and so I added it to _paintWithContext because that felt like the logical place for it). Then I discovered actually we already had code there, but I didn't understand that it was always called, so I removed it in favour of the new location. I could have just left it in the old location, I think the effect is more or less the same.

Let me know if you prefer the old location.

The old location feels a little more appropriate to me, but I don't feel super strongly about this.

i'll move it back

oh, there is one code path that doesn't go through paintChild, though, and that's the flushPaints loop.

goderbauer · 2021-11-09T18:42:48Z

packages/flutter/lib/src/rendering/box.dart

+        return true;
+      }());
+      if (!kReleaseMode) {
+        if (debugProfileLayoutsEnabled || _debugIntrinsicsDepth == 0) {


Wondering if it is really useful to show the full path when this is enabled? It will make it look like as if every step is just contributing a tiny amount and it will also make it harder to spot this in traces.

Showing the full path would be useful if one where to optimize the intrinsics calculations itself, but that seems rare?

Mostly I was trying to show the depth of the tree being measured, just like we show the depth of the tree being built/laid out/painted.

Makes sense. We can always turn this off in the future if it turns out to not be helpful.

goderbauer

LGTM

goderbauer · 2021-11-12T17:21:21Z

packages/flutter/lib/src/rendering/object.dart

+    Map<String, String> debugTimelineArguments = timelineArgumentsIndicatingLandmarkEvent;
+    assert(() {
+      if (debugProfileLayoutsEnabled) {
+        debugTimelineArguments = <String, String>{
+          ...debugTimelineArguments,
+          'dirty count': '${_nodesNeedingLayout.length}',
+          'dirty list': '$_nodesNeedingLayout',
+        };
+      }
+      return true;
+    }());


Move these inside the if (!kReleaseMode) {?

good catch. fixed.

goderbauer · 2021-11-12T17:22:23Z

packages/flutter/lib/src/rendering/object.dart

+        };
+      }
+      return true;
+    }());


goderbauer · 2021-11-12T17:25:47Z

packages/flutter/lib/src/widgets/framework.dart

@@ -2507,14 +2515,29 @@ class BuildOwner {
    assert(context != null);
    assert(_debugStateLockLevel >= 0);
    assert(!_debugBuilding);
+    Map<String, String> debugTimelineArguments = timelineArgumentsIndicatingLandmarkEvent;


move this here as well?

goderbauer · 2021-11-12T17:28:23Z

packages/flutter/lib/src/rendering/debug.dart

+/// In debug builds, additional information is included in the trace (such as
+/// the properties of render objects being laid out). Collecting this data is
+/// expensive and further makes these traces non-representative of actual
+/// performance. This data is omitted in profile builds.


Since the first version of this PR didn't do the "This data is omitted in profile builds.": Can we add a test to ensure that we don't regress this and accidentally include this in profile builds again?

I ended up writing such a test by having test.dart compile an app in profile mode and then examining the build output for strings that would indicate that the method was incorrectly compiled in. I'm not 100% proud of the result, but it does seem to do what you want. :-)

goderbauer

Still LGTM, but some checks appear unhappy now.

CaseyHillers · 2021-11-18T20:41:29Z

.ci.yaml

@@ -402,6 +402,7 @@ targets:
          {"dependency": "clang"},
          {"dependency": "cmake"},
          {"dependency": "ninja"}
+          {"dependency": "android_sdk", "version": "version:29.0"},


ci.yaml looks good to me. Please ping me when you land this as infra will need to manually roll this to flutter/infra as the bot is broken (#93225)

FYI #93225 is fixed, and this is safe to land yourself (no infra intervention required)

Hixie · 2021-11-19T06:57:30Z

I don't understand why the LUCI presubmits aren't working anymore.

CaseyHillers · 2021-11-19T17:38:14Z

I don't understand why the LUCI presubmits aren't working anymore.

Outside of 9 AM - 5 PM PST on weekdays, there's a smaller infra pool and it takes longer for PR checks to be processed. It looks like they all got run, but if that was not the case let me know.

* Add a test for tracing the framework. * Add a `DiagnosticsNode.toTimelineArguments()` that can be used easily with `Timeline.startSync`. * Rename some of the timeline events for clarity: hot reload dirtying now says "Hot Reload" for example, and the phases are in all caps (BUILD, LAYOUT, etc). * Always flag intrinsic and dry layout logic in debug and profile builds. Normally this only flags one event; when `debugProfileLayoutsEnabled` is true it shows the entire path. Might be good to have this flagged in the DevTools. Fixes flutter#93031. * Fix a broken link by pointing to our official documentation instead of Fuchsia documentation. Fixes flutter#92044. * Change how painting is traced when `debugProfilePaintsEnabled` is on to be more comprehensive. * Add some details to the top-level timeline events, e.g. what nodes are dirty, when the relevant `debugProfile*Enabled` flags are on. * Include the Diagnosticable information about a `RenderObject` or a `Widget` in the information logged when `debugProfileLayoutsEnabled`, `debugProfilePaintsEnabled`, or `debugProfileBuildsEnabled` are on. Fixes flutter#93009 * Refactor how tracing is done in the widgets library so that `RenderObjectWidget`s are included in the timeline when `debugProfileBuildsEnabled` is on. Fixes flutter#93007. Also: * Fix a minor error we introduced with the null safety migration: `DiagnosticsNode.toDescription` should return non-null. (Most of the logic either assumed that or already enforced it.) * Implement `debugFillProperties` for `Placeholder` and `RenderCustomPaint`, to help with the tests that were added. * Remove a TODO in `objects.dart` that we're never going to get to. * Improve some docs on `BuildContext`. * Cache `_dirtyElements[index]` in `buildScope`. * Improve docs for `operator ==` on `Widget`. Fixes flutter#49490. * Remove some code duplication in `framework.dart`. * Clean up `_NullWidget` a bit.

This reverts commit 840e109.

zanderso · 2021-12-14T16:24:58Z

FYI, no action needed. This PR reduced the stack size per nesting level: https://flutter-flutter-perf.skia.org/e/?begin=1634671383&end=1639497543&keys=Xe3d1bf0024fa24f0bb55e80af0d63e4e&requestType=0&xbaroffset=26844

goderbauer · 2021-12-14T18:23:08Z

That's curious. @Hixie or @zanderso Do you understand why this would reduce nesting per level? From the code I would have expected it to stay the same...

Hixie · 2021-12-14T19:45:12Z

I did fiddle with some "inline" calls in a few places, maybe that helped.

flutter-dashboard bot added framework flutter/packages/flutter repository. See also f: labels. team Infra upgrades, team productivity, code health, technical debt. See also team: labels. labels Nov 4, 2021

google-cla bot added the cla: yes label Nov 4, 2021

Hixie force-pushed the debugProfileBuildsEnabled branch 6 times, most recently from bb46f72 to 16b86bd Compare November 9, 2021 00:40

goderbauer reviewed Nov 9, 2021

View reviewed changes

Hixie force-pushed the debugProfileBuildsEnabled branch from 16b86bd to aa57e13 Compare November 9, 2021 22:49

Hixie marked this pull request as ready for review November 9, 2021 23:55

flutter-dashboard bot added f: material design flutter/packages/flutter/material repository. f: scrolling Viewports, list views, slivers, etc. f: integration_test The flutter/packages/integration_test plugin labels Nov 9, 2021

jason-simmons mentioned this pull request Nov 10, 2021

Do not log framework timeline events in release mode #93281

Closed

Hixie force-pushed the debugProfileBuildsEnabled branch from aa57e13 to 810b932 Compare November 10, 2021 01:21

Hixie mentioned this pull request Nov 10, 2021

Make build/layout/paint profiling cheaper #93262

Open

Hixie force-pushed the debugProfileBuildsEnabled branch from 810b932 to 8103119 Compare November 11, 2021 23:30

goderbauer approved these changes Nov 12, 2021

View reviewed changes

Hixie force-pushed the debugProfileBuildsEnabled branch 2 times, most recently from 75e6286 to 76af3df Compare November 16, 2021 01:52

goderbauer approved these changes Nov 16, 2021

View reviewed changes

Hixie force-pushed the debugProfileBuildsEnabled branch 2 times, most recently from 28441a3 to bbef6f5 Compare November 18, 2021 19:24

Hixie requested review from CaseyHillers and keyonghan as code owners November 18, 2021 19:24

CaseyHillers approved these changes Nov 18, 2021

View reviewed changes

Hixie force-pushed the debugProfileBuildsEnabled branch from bbef6f5 to c2bf33f Compare November 18, 2021 22:29

Hixie force-pushed the debugProfileBuildsEnabled branch from 568f58f to caebfec Compare November 19, 2021 06:57

CaseyHillers mentioned this pull request Nov 19, 2021

ci.yaml validation failed due to github token generation failing #93923

Closed

Hixie force-pushed the debugProfileBuildsEnabled branch 4 times, most recently from 1bffdad to 8be032e Compare November 20, 2021 21:43

Hixie force-pushed the debugProfileBuildsEnabled branch 4 times, most recently from 12813a4 to 13c290e Compare December 3, 2021 21:32

Hixie force-pushed the debugProfileBuildsEnabled branch 5 times, most recently from 35a5d0c to fd34a62 Compare December 9, 2021 20:21

Hixie added the waiting for tree to go green label Dec 9, 2021

Hixie force-pushed the debugProfileBuildsEnabled branch from fd34a62 to 7ff993a Compare December 9, 2021 21:15

Hixie force-pushed the debugProfileBuildsEnabled branch from 7ff993a to c5993ae Compare December 10, 2021 01:07

fluttergithubbot merged commit 840e109 into flutter:master Dec 10, 2021

Hixie added a commit that referenced this pull request Dec 10, 2021

Revert "Improve tracing (#93086)"

338577a

This reverts commit 840e109.

This was referenced Dec 10, 2021

Revert "Improve tracing" #95034

Closed

ci.yaml changes aren't applied before tests run post-submit #95037

Closed

Fixes semantics_perf_test.dart after profile fixes #95047

Merged

kenzieschmoll mentioned this pull request Apr 7, 2022

Do not send debugTimelineArguments when debugProfileBuildsEnabled == true #101535

Closed

Improve tracing #93086

Improve tracing #93086

Conversation

Hixie commented Nov 4, 2021 • edited Loading

Hixie commented Nov 5, 2021

goderbauer left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

goderbauer left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

goderbauer left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Hixie commented Nov 19, 2021

CaseyHillers commented Nov 19, 2021

zanderso commented Dec 14, 2021

goderbauer commented Dec 14, 2021

Hixie commented Dec 14, 2021

Hixie commented Nov 4, 2021 •

edited

Loading