Repository navigation
Slow frame during startup after the first frame is hard to capture and causes bi-modal worst frame metrics #64781
Description
The slow frame could be as slow as 1.7s as noticed in these plots. It is first noticed in #60559 (comment) because the newly added host-independent (e2e) perf tests have such low overhead that it captures them with a high probability before the engine sends out the batch of FrameTiming with such slow frame.
By looking at the e2e_perf_summary.json, such slow frame is not the first frame so it's not captured by the timeToFirstFrameRasterizedMicros metric. (It's often the second frame captured.)
Our normal flutter_driver perf tests usually have too much overhead that it won't be able to see such frame in the timeline. But sometimes (maybe 10%-20% of the time) they see it which causes the worst frame time to be bi-modal.
On the other hand, flutter run --profile --start-paused won't be able to capture the slow frame trace so that frame presumably happens before the pause kicks in.
We should have a way to get a full trace for app startup to investigate this slow frame. The --trace-startup flag currently only prints out a short summary without a full timeline trace.
Activity
liyuqian commentedon Aug 28, 2020
CC @Hixie @zanderso @CareF
zanderso commentedon Aug 28, 2020
This seems like a big blind spot in our understanding of startup performance. Do we know whether this only impacts artificial benchmarks? Can it also impact real apps? I'm marking this P2 with
customer: product, and will work with @liyuqian on finding the right assignee to investigate.jonahwilliams commentedon Aug 28, 2020
there is some deferred work that gets created on startup, like the asset manifest parse (utf8/json), it wouldn't surprise me if this is showing up later on.
zanderso commentedon Aug 28, 2020
The first action item on this issue is:
@liyuqian
--trace-startupis an engine flag that is plumbed directly to it by the same flag of the Flutter tool. Do you know if the behavior to extend here would be the behavior of the engine or the behavior of the tool?When we have the full trace we can check if @jonahwilliams' theory is correct.
jonahwilliams commentedon Aug 28, 2020
we could also add timeline trace events to the decoding/asset bundle loading to see if they show up during the frame in question
liyuqian commentedon Aug 29, 2020
I should be able to find some time before the end of next Tuesday to check
--trace-startupfrom the engine side, and see if there's any action we can do there.chinmaygarde commentedon Aug 31, 2020
@zanderso says Yuqian is currently working on this but he already seems to be overloaded with other issues. Working on figuring out an appropriate milestone for this.
11 remaining items
liyuqian commentedon Sep 3, 2020
I did similar things locally as #65143, but I have to also modify L129 to allow
waitForAppToFinisheven with--trace-startup. Then I used Observatory to check later frames' trace events so not dumping those in files is Ok. @jonahwilliams : can you please confirm if #65143 would still keep the app running (without--no-resident) and the the trace events are available through Observatory?liyuqian commentedon Sep 3, 2020
I finally captured a trace that includes that 1.7s long frame:
e2e_timeline.json.zip
It suggests that our tracing is fine, and this 1.7s slow frame seems to never happen with a normal
flutter runof gallery (see start_up_timeline_gallery_run.json.zip).In the 1.7s frame tracing, the majority of time is spent on
IOSSurface::SubmitFramewhich I believe is for Skia to flush the canvas. Unfortunately,--trace-skiais not available forflutter driveso I'm not sure what Skia function calls are slow there. But I suspect that there are some shader compilation involved as I can see multiplePersistentCacheStoreevents on the IO thread during that period.To further investigate the issue, @flar 's work to persist the timeline of each devicelab perf test would be helpful. It allows us to compare the 1.7s frame tracing of a normal flutter_driver test (which happens very infrequently) and the 1.7s frame tracing of an e2e test.
In the end, if this issue only happens with
flutter drivebut not normalflutter run, maybe the slow frame is not impacting our customers. And because we've already removed most of those slow frames from our test measurements in #64780, it's also not impacting our team much.zanderso commentedon Sep 9, 2020
Should we add this? Do we already have this on
flutter run?@jonahwilliams are there any differences in the way the tool starts up an app in these two cases?
Lowering the priority to P4 since it sounds like this issue is mitigated by #64780. However, it would be good to complete the work on #65118. @jonahwilliams could you provide @liyuqian a little more guidance on writing a unit test there? Thanks!
jonahwilliams commentedon Sep 9, 2020
When running via flutter drive we start all isolates paused, and then resume the main isolate at the start. This could definitely tweak the perf of the first rendered frame.
I'll take a look at #65118 today
jonahwilliams commentedon Sep 9, 2020
opened #65490 to add unit tests/remove globals. That should give @liyuqian an easy pattern to copy paste
Save startup timeline
liyuqian commentedon Sep 10, 2020
@jason-simmons recently noticed that flutter_gallery__transition_perf_e2e 99th_percentile_frame_build_time_millis and worst_frame_build_time_millis regressed after #64432. This seems to further support @jonahwilliams 's conjecture in #64781 (comment) that our metrics, especially the 99th and wrost metric, can be easily affected by how flutter drive pause and resume the isolate.
Save startup timeline (#65118)