Reland 5: Multiview pipeline

[dkwingsmt]

This relands #50931.

Nothing has changed. The crash that caused the previous revert has been fixed by flutter/flutter#144212.

[jonahwilliams]

This caused some odd changes in various benchmarks when it landed (and those returned to previous values when it was reverted)

https://flutter-flutter-perf.skia.org/e/?begin=1708982750&end=1709069150&keys=Xd2656b08b4961c84affb7d07f7eb4c29&selected=commit%3D39546%26name%3D%252Carch%253Dintel%252Cbranch%253Dmaster%252Cconfig%253Ddefault%252Cdevice_type%253DMoto_G__4_%252Cdevice_version%253Dnone%252Chost_type%253Dlinux%252Csub_result%253Dworst_frame_build_time_millis%252Ctest%253Dandroid_picture_cache_complexity_scoring_perf__timeline_summary%252C&xbaroffset=39546

Do we understand why this changed? My understanding of this patch is that for single view it should be more or less a no-op.

[jonahwilliams]

Lets hold until we understand why the benchmarks changed?

[goderbauer]

This caused some odd changes in various benchmarks

Wait, do I understand this right: worst_frame_build_time went DOWN when this landed last time and went back up when it was reverted? It's showing a performance improvement with this change? It's also curious, that it effects BUILD time at all since that's all framework-side work which this patch doesn't change?

[jonahwilliams]

Is it showing a performance improvement, or are we measuring things differently? The build time measurement is collected by the FrameTimingsRecorder which is impacted by this patch.

[goderbauer]

I thought BUILD time is measured on the framework side here: https://github.com/flutter/flutter/blob/82ffde7ddfa265b96b94b16c2bddb1f43d01cb57/packages/flutter/lib/src/scheduler/binding.dart#L1200, at least that's the event the benchmarks are parsing for that metric: https://github.com/flutter/flutter/blob/82ffde7ddfa265b96b94b16c2bddb1f43d01cb57/packages/flutter_driver/lib/src/driver/timeline_summary.dart#L44C37-L44C44

How does FrameTimingsRecorder get into that mix?

[jonahwilliams]

Its measured by the frame timings recorder for the e2e, but if I look through the list I don't see any e2e tests so 🤷‍♂️

[goderbauer]

Looks like the same pattern is visible in the benchmark data the last time this landed/reverted: https://flutter-flutter-perf.skia.org/e/?keys=Xd2656b08b4961c84affb7d07f7eb4c29&requestType=0&selected=commit%3D38492%26name%3D%252Carch%253Dintel%252Cbranch%253Dmaster%252Cconfig%253Ddefault%252Cdevice_type%253DMoto_G__4_%252Cdevice_version%253Dnone%252Chost_type%253Dlinux%252Csub_result%253Dworst_frame_build_time_millis%252Ctest%253Dandroid_picture_cache_complexity_scoring_perf__timeline_summary%252C&xbaroffset=39546

So, doesn't look like this is a fluke.

[jonahwilliams]

It looks the most pronounce on the moto g4, which is a pretty slow device. Dropping the slowest frame could cause the rest of the metrics to improve as well.

[dkwingsmt]

Similar patterns also appeared for the last few attempts, notably the 2nd attempt (which didn't implement the warm up frame fixes at all):
https://flutter-flutter-perf.skia.org/e/?begin=1697098041&end=1704321377&keys=Xf021d0633030e39e51042d1718f4b6bc&requestType=0&selected=commit%3D37590%26name%3D%252Carch%253Dintel%252Cbranch%253Dmaster%252Cconfig%253Ddefault%252Cdevice_type%253DMoto_G__4_%252Cdevice_version%253Dnone%252Chost_type%253Dlinux%252Csub_result%253Daverage_frame_build_time_millis%252Ctest%253Dtiles_scroll_perf__timeline_summary%252C&xbaroffset=37590

[chinmaygarde]

Triage: It seems like we are trying to explain an apparent performance improvement where we didn't expect any and are now wondering if we are measuring the right things or if there is a correctness issue. Can we grab timelines from a local run with this patch applied to see if we can explain our observations?

[chinmaygarde]

If this fixes an unrelated performance issue, thats awesome. But we should still understand the observation.

[jonahwilliams]

Some potential pointers here:

Consider looking at the timeline traces before/after. Perhaps there is an expensive frame that is missing now, or the frame is there but being measured differently?

You can profile this locally, or look for the existing traces in CI. For example: https://ci.chromium.org/ui/p/flutter/builders/prod/Linux_android%20android_picture_cache_complexity_scoring_perf__timeline_summary/11955/overview

Look in the "log links" section, save the timeline trace (not the summary) and open in about://tracing

[dkwingsmt]

I've did some device tests on a local Moto G4. I still have no idea what happened, but here's my result for now.

First of all, the metric change is consistently reproducible. The app seem to run fine on the device with no noticeable dropped frames or other smoothness problems. The frame count stay the same as well, swaying within 677~683 before and after the change.

Second, the following chart shows the frame build time against frame start time before and after the change.

It seems that build time got a global reduction and got much more consistent, instead of having one or two spikes chopped.

Third, I tried to apply changes little by little and do device test for each revision, and found the change that will trigger the build time drop. A large portion of the PR does not affect the build time, then the revision
a8c0dc3 does, then there are a few changes remaining that seem to not affect the build time.

|-----------------------------------------|---|---------|
^ Current head                                          ^  After PR
                                              ^ culprit revision (a8c0dc)
                                          ^ rev before the culprit revision
Build time
~900                                    ~900  ~550       ~550

To explain what the culprit revision does, the following is the series of events that take place when a view is rendered before the culprit commit:

1. A LayerTreeTask is created and stored.
2. frame_timings_recorder_->RecordBuildEnd() and update vsync target time
3. The frame's layer tree is pushed to the pipeline.
4. The pipeline is given to the rasterizer.
5. The framework performs clean-up, such as scene.dispose().
6. Potentially notify idle.

After the culprit commit, the codepath becomes 1->2->5->3->4->6
So, the work between BuildStart and BuildEnd has not changed at all, but the measured build time decreases from ~900 to ~550.

(More mysteriously, if I change the code path to 1->2->3->5->4->6, then the app is stuck before the first frame.)

As I said, I still have no idea what caused the change. Maybe it's because the garbage collection can be done earlier to not disrupt the next frame?

[goderbauer]

A theory: Prior to this change, did the FlutterView.render call block while (3) and (4) happened? This could mean that prior to this change that work was (maybe incorrectly?) counted towards BUILD time (as measured from the start of the PlatformDispatcher.onBeginFrame call to the end of the PlatformDispatcher.onDrawFrame call). After this change, do (3) and (4) happen after the end of the PlatformDispatcher.onDrawFrame call and hence don't count into BUILD times anymore?

In other words, is FlutterView.render now faster because the work is delayed until after the PlatformDispatcher.onDrawFrame call ends? This should be fairly easy to validate by instrumenting the FlutterView.render call in the framework before and after this change.

[dkwingsmt]

@goderbauer The list of actions I mentioned here already splits of the work done by FlutterView.render.
Before the change, the FlutterView.render call is action 1, 2, 3, and 4. And yes, they're blocked since they all run on the UI thread.
Action 3 and 4 are never counted towards the build time, since the build time ends at action 2.

(Note that I'm talking about before and after the culprit revision, which is enough to trigger the build time drop. For the entire PR, yes, the build time includes more actions than the current main, a necessary change, but isn't related to the metrics change apparently.)

Also, if we suspect that the metric difference is work being included into/excluded from the build time, then this difference should be counted towards the raster time. The following chart is the raster time vs raster begin time:

The chart does not show significant changes.

[goderbauer]

Before the change, the FlutterView.render call is action 1, 2, 3, and 4. And yes, they're blocked since they all run on the UI thread.
Action 3 and 4 are never counted towards the build time, since the build time ends at action 2.

I don't understand this. If 3 and 4 are part of FlutterView.render they will count towards the BUILD time as measured by the benchmark because that time ends here (after FlutterView.render completes, which is part of the persistent frame callback handling a few lines above): https://github.com/flutter/flutter/blob/1a0dc8f1e11892f8f2365ffb6a9617abc39d4b15/packages/flutter/lib/src/scheduler/binding.dart#L1331

[goderbauer]

Maybe the confusion is coming from what the benchmark is measuring as BUILD time. As stated in #51019 (comment) I believe it is measured on the framework side from [1] to [2]. It is not measured engine-side by the frame_timings_recorder (unless I am misunderstanding something...)

[1] https://github.com/flutter/flutter/blob/1a0dc8f1e11892f8f2365ffb6a9617abc39d4b15/packages/flutter/lib/src/scheduler/binding.dart#L1200
[2] https://github.com/flutter/flutter/blob/1a0dc8f1e11892f8f2365ffb6a9617abc39d4b15/packages/flutter/lib/src/scheduler/binding.dart#L1331

[dkwingsmt]

I'm creating a new PR since this PR was created on the flutter/engine repo by mistake.
Let's move to #51186