VSYNC trace event ending prematurely

[kenzieschmoll]

The VSYNC end event is coming in out of order. Here is an example with (event name - phase - timestamp):

flutter: VSYNC - B - 667560813352
flutter: VsyncCallback - B - 667560813467
flutter: VsyncFireCallback - B - 667560813485
flutter: VsyncFireCallback - E - 667560813504
flutter: VsyncCallback - E - 667560813507
flutter: VsyncProcessCallback - B - 667560813527
flutter: Animator::BeginFrame - B - 667560813530
flutter: BUILD - B - 667560813669
flutter: SampleBlockBuffer::ProcessCompletedBlocks - X - 667560821603
flutter: SampleBlockBuffer::ProcessCompletedBlocks - X - 667560828633
flutter: VSYNC - E - 667560830019 ************************************** Problem event
flutter: SampleBlockBuffer::ProcessCompletedBlocks - X - 667560834417
flutter: SampleBlockBuffer::ProcessCompletedBlocks - X - 667560844473
flutter: SampleBlockBuffer::ProcessCompletedBlocks - X - 667560853355
flutter: SampleBlockBuffer::ProcessCompletedBlocks - X - 667560865931
flutter: BUILD - E - 667560866947

These are Synchronous events so the VSYNC event should not be finishing until all its children do. Are we missing an await somewhere?

@jonahwilliams @dnfield

[dnfield]

Possibly due to flutter/engine#36775

Are you able to try reverting that and seeing if it gets better?

[dnfield]

@fzyzcjy fyi

[kenzieschmoll]

For repro steps, I was seeing this consistently when I would turn the Performance Overlay on and off.

[fzyzcjy]

Hmm, here are possible solutions:

1. Revert the PR - then the vsync is wrong! That's why I made the PR
2. Put this synthesized vsync attached to a dummy thread id, such that no other events can interfere with it so we will not have this bug. - @dnfield do you think this is ok? if so I will PR

[dnfield]

@kenzieschmoll - what's the impact of this?

I suspect wha'ts happening here is that we're emitting past-dated vsync events sometimes. Is this causing something wrong in devtools?

[kenzieschmoll]

Yes this violates the requirements of the Chrome Trace Event Format for Duration (synchronous) events, and causes an unbalanced tree in DevTools when composing trace events into a tree format.

[kenzieschmoll]

If the VYSNC event really should finish before its children, should it be an Async event? ('b' and 'e' instead of 'B' and 'E')

[dnfield]

We should revert for now - flutter/engine#37589

[fzyzcjy]

@kenzieschmoll If the VYSNC event really should finish before its children, should it be an Async event? ('b' and 'e' instead of 'B' and 'E')

IIRC, no, unfortunately. I have tried to be async initially, and then it is not recognized by chrome://tracing at all. I have checked chrome://tracing's source code and IIRC it requires sync events.

So, shall we use the alternative approach: create that event in a dummy thread id (i.e. not-existent thread)?
I have personally done that in flutter_smooth (e.g. https://github.com/fzyzcjy/flutter_smooth/blob/master/scripts/analysis/timeline/enhance.py), s.t. I can insert fake events into timeline and visualize them. @dnfield @kenzieschmoll

[kenzieschmoll]

chrome://tracing (and the new and improved Perfetto trace viewer), and Dart DevTools all support async events for the Chrome Trace Event Format, so it is fine to use async events. The flutter framework / engine sends several async events to the timeline.

[fzyzcjy]

@kenzieschmoll Yes I know it allows async events, but have you tried whether the async VSYNC event is allowed (hope it is allowed!)? Last time (a month ago?) I tried it and it is not. In other words, the VSYNC event is there, but there is no zebra colors at all and chrome just think it is a normal event instead of the special vsync event and colorize the figure.

[dnfield]

@fzyzcjy at this point I think we'd prioritize the devtools experience over making sure that chrome://tracing looks the way we'd want...

[kenzieschmoll]

+1 to Dan's comment. @fzyzcjy what are you trying to accomplish with chrome://tracing that you can't accomplish with Flutter DevTools? (we are also actively working on improving the trace viewing experience in DevTools, if you are noticing performance or usability issues with that trace viewer)

[fzyzcjy]

@dnfield @kenzieschmoll

what are you trying to accomplish with chrome://tracing that you can't accomplish with Flutter DevTools?

1. Speed. devtools is super slow (mac with i7 12 cores, so it is not a slow computer) - even shifting/zooming is very janky. You can reproduce it by reproducing https://cjycode.com/flutter_smooth/benchmark/analyze/fps/tracing using data like https://github.com/fzyzcjy/flutter_smooth_blob/blob/master/tracing/dart_devtools_example.json.zip.
2. functionality. I have made a python script (https://github.com/fzyzcjy/flutter_smooth/blob/master/scripts/analysis/timeline/enhance.py) to create various "pseudo" events and inject them to timeline. By doing so, I no longer need to manually examine the timeline detailed data, but can instead directly observe some patterns, such as https://cjycode.com/flutter_smooth/benchmark/analyze/fps/tracing#example-how-does-a-jank-look-like

Which I guess are not solveable by devtool indeed :/

[fzyzcjy]

@dnfield @kenzieschmoll

Problem of the revert: The current revert makes the VSYNC completely wrong (which is described in my PR before). i.e. The start of VSYNC interval does not mean the vsync is at that time at all!

Therefore, it looks meaningless and confusing to look at the tracing data. For example, if something has exceeded/not-exceed the vsync timestamp but the tracing data wrongly reports the reverse, all logical reasoning will be wrong. "Does something exceed vsync" is very much needed when I develop https://github.com/fzyzcjy/flutter_smooth, because I need to check and debug whether the actual code satisfies my theoretical timeline. An example "theoretical timeline" can be seen everywhere in the doc, e.g. the colorful figure https://cjycode.com/flutter_smooth/design/infra/rasterizer-queue/remove-jank.

[fzyzcjy]

Alternative solutions to the PR:

1. As mentioned above, create sync VSYNC event attached to a never-exist thread id such as id=-100000. I have done that in my python script and it worked well.
2. rename VSYNC to something else (say, InaccurateVsync) + report real vsync start/end via a tracing parameter. therefore, at least it will not make chrome://tracing "zebra colored" (i.e. gray-and-white). Users will implicitly assume the zebra colored background means (accurate) vsync, so if we rename it (and chrome tracing do not utilize it generate zebra color), users will at least do not get confused by default. We may then add a doc telling them how to extract real VSYNC info - "please look at the arguments of InaccurateVsync, the one named "accurate_start" is the real value).

[dnfield]

I think as long as we don't break devtools we should be fine :) Ideally though, we'd avoid emitting any unnecessary events every frame - i.e. there may not be a good reason to emit both the VSYNC on a 'fake' thread ID along with some other VSYNC-like event.

[fzyzcjy]

we'd avoid emitting any unnecessary events every frame - i.e. there may not be a good reason to emit both the VSYNC on a 'fake' thread ID along with some other VSYNC-like event.

Given that, maybe the 2nd approach looks better? :)

[github-actions]

This thread has been automatically locked since there has not been any recent activity after it was closed. If you are still experiencing a similar issue, please open a new bug, including the output of flutter doctor -v and a minimal reproduction of the issue.