Note, I'm working on adding unittests for this, wanted to give you a chance to leave any early comments.

Not sure about the need for a specific utility method in fml/time that has nothing to do with working on timing related functionality. I think you could just move the thing to two ivars in Shell or at least make it more generic. If you are going to add more stuff to it though, that changes things. Other stuff is just nits. Functionality seems fine to me and useful.

fml doesn't seem like a good place for this. I will move the ivars to shell for now. Also for the reader-writer lock, I wasn't too worried about the contention on this since the guarded code isn't expensive (it's updating / getting an integer in both cases).

@chinmaygarde , i've addressed the comments and updated a test to account for this change.

PTAL

The value being reported here will be an important user-experience metric in that it reports how "late" the user saw the frame. This metric can only be measured in full frames.

A related app-performance metric would be "by how much was the processing late". Such a lag would be measured by "time we made the call to schedule the completed frame for display compared to our deadline". This doesn't translate into the user experience, but it lets us measure how close we were in performing the work. There may be regressions in this metric before they appear as regressions in the UX metric that we might want to track because if we let enough of these "sub-frame" lags add up, they result in another whole frame lag.

Which of these metrics do we need, or both, or can we define a reporting metric that can serve both purposes. Note that the UX metric is actually the processing metric rounded up to a whole frame, essentially.

For example, we can report both and let the tools focus on what they need to know. (A UX tool might care about #frames lag, but a regression tracking tool might focus on processing time over budget, for instance.)

We could report the times of "target vs now" but include an optional piece of data that is the total number of user-visible lag frames...?

Thoughts and suggestions?

A related app-performance metric would be "by how much was the processing late".

Thanks @flar , I like this suggestion. So the revised trace event would look like this (pseudo code):

{
  "name": "SceneDisplayLag",
  "start_time": "<target time of the frame>",
  "end_time": "<now, i.e, time when rasterization has ended>",
  "metadata" : {
    "frame_target_time" : "<time at which this layer tree was scheduled to be shown>",
    "current_frame_target_time" : "<time at which the latest vsync pulse indicated that a frame will end>",
    "num_frames_lag" : "current_frame_target_time - frame_target_time / refresh_rate"
  }
}

I'm definitely open to other name suggestions for the fields mentioned here. Thoughts on this?

cc: @chinmaygarde , @liyuqian

For naming, it seems to me

1. "target_time" is probably better than "start_time"
2. "rasterized_time" is probably better than "end_time" as it's more specific.
3. "num_frames_lag" seems to be very similar to "num_frames_missed"
4. It's unclear to me how <target time of the frame> is different from <time at which this layer tree was scheduled to be shown>
5. lag and latency sound like the same thing. I'm not sure if someone would be confused to see both lag and latency in our metrics, and they mean different things.

I should've been clearer. There weren't going to be separate fields for start_time and end_time, I listed them there for completeness. They mark the start and end of the trace event on the dart timeline.

For naming, it seems to me

Keep in mind that this is the structure of an observatory trace timeline event. The first two fields are the begin and end time that all events have, their names are simply the timestamps for the range of time the event shows on the timeline, not "names" for the things that happened at those times.

1. "target_time" is probably better than "start_time"
2. "rasterized_time" is probably better than "end_time" as it's more specific.

The proposal is that this events duration on the timeline plot will go from when it was supposed to be seen until when it was submitted to the platform. In truth, it won't really be seen until the next vsync transition makes it visible on the hardware screen, but we need something more precise than that to track how much we overshot. For example if we overshot by 1ms then the developer might be able to do something to simplify their scene and get it back under time budget. If we overshot by 10ms there is likely not much to do. Both will appear exactly one vsync interval later than we planned, though.

3. "num_frames_lag" seems to be very similar to "num_frames_missed"

I feel that there is an ambiguity with the name "frame". It can be used to refer to the interval between vsync transitions, as in "this layer_tree will take too long to render so it will not show on the screen until the next frame".

It also is used sometimes to refer to "the Dart code computed the current frame and represented it with this layer_tree".

It can be either an interval between vsyncs or a thing to be rendered depending on context. And so "number of frames" can either be the number of intervals or the number of renderable things. This property wants to be the count of "extra vsync intervals before this layer_tree became visible".

What is a less ambiguous name?
"vsync_transitions_missed"? (sounds a bit too technical)
??

4. It's unclear to me how <target time of the frame> is different from <time at which this layer tree was scheduled to be shown>

They are the same. The first mention of it was not a property, though, it was just the starting timestamp of the event. How much value does it have as both the start time of the event and also a named property on the event? Will the tools make it easier to extract one or the other for tracking purposes?

5. lag and latency sound like the same thing. I'm not sure if someone would be confused to see both lag and latency in our metrics, and they mean different things.

Where else do they see these terms? Is this a suggestion to name the "num_frames_lag" to "something_something_latency"?

What is a less ambiguous name?
"vsync_transitions_missed"? (sounds a bit too technical)

I actually like this. Though it is more technical, I think it captures the metric quite well.

They are the same. The first mention of it was not a property, though, it was just the starting timestamp of the event. How much value does it have as both the start time of the event and also a named property on the event? Will the tools make it easier to extract one or the other for tracking purposes?

The reason I listed frame_target_time and current_frame_target_time as properties, though the former is captured as the start_time for the trace event is so when we manually look at the event, it makes it easier to compare 2 numbers as opposed to one number and the other on the timeline. If we are using a tool it shouldn't really matter.

Thanks @iskakaushik and @flar for correcting my misunderstandings! In addition to vsync_transitions_missed , may I also propose num_frames_lag -> frame_vsync_interval? For a fast frame, this will be 1. For slow frames, it could be 2, 3, 4, .... The vsync_interval clearly indicates that this is an integer value that's associated with vsync signals.

Thanks @iskakaushik and @flar for correcting my misunderstandings! In addition to vsync_transitions_missed , may I also propose num_frames_lag -> frame_vsync_interval? For a fast frame, this will be 1. For slow frames, it could be 2, 3, 4, .... The vsync_interval clearly indicates that this is an integer value that's associated with vsync signals.

A note about this value being "1 for a fast frame"...

I don't believe the event will be posted for events that don't lag or have latency. One issue is that there is no such thing as a "negative time event" and that is even enforced by the TRACE macros which will fix the ordering of their timestamps assuming you meant the event to have a positive duration.

So, we can't post "on time" renderings as this event in the ordinary way (because "now" is less than "target_time"), and according to the way the code is written here, they would just be omitted for those frames (i.e. you don't want these events in your timeline as they appear when things go wrong). But, we could potentially post a "zero lag" event with both timestamps being the target time?

Or do we just let it reorder the timestamps and have the event interval go from start=now to end=target? The problem with that is if we want a tool to find the average "latency" then it would have to interpret the events for fast frames differently, otherwise the accounting may add their timeliness to the tardiness statistic.

Another option is to rename the event to something indicating "how early the rendering completed" for the case where we got it in on time?

With respect to the name of the field, I'm not a big fan of "interval" by itself since that is usually the duration of a single vsync window, isn't it? But perhaps "interval_count" instead? So, "frame_vsync_interval_count" as in the count of the number of intervals that its processing lasted? That gets long, but is it less ambiguous? Or "..._interval_duration"?

The reason I listed frame_target_time and current_frame_target_time as properties, though the former is captured as the start_time for the trace event is so when we manually look at the event, it makes it easier to compare 2 numbers as opposed to one number and the other on the timeline. If we are using a tool it shouldn't really matter.

That makes sense.

With respect to the name of the field, I'm not a big fan of "interval" by itself since that is usually the duration of a single vsync window, isn't it? But perhaps "interval_count" instead? So, "frame_vsync_interval_count" as in the count of the number of intervals that its processing lasted? That gets long, but is it less ambiguous? Or "..._interval_duration"?

Ah, yes. This makes me think that either vsync_transitions_missed or vsync_missed_count might be a better name :)

With respect to the name of the field, I'm not a big fan of "interval" by itself since that is usually the duration of a single vsync window, isn't it? But perhaps "interval_count" instead? So, "frame_vsync_interval_count" as in the count of the number of intervals that its processing lasted? That gets long, but is it less ambiguous? Or "..._interval_duration"?

Ah, yes. This makes me think that either vsync_transitions_missed or vsync_missed_count might be a better name :)

Or "vsync_interval_count"? I don't think we don't need to prepend "frame" there. "missed" would be 0 based and "interval" would be 1 based.

I was thinking to restrict these events to only when we encounter a lag as a first step. I will add some benchmarks and evaluate the proposal in go/flutter-pipeline-improvements. We can add additional traces to capture how well we are doing as a next step. Given this, I decided to call it vsync_transitions_missed as it accurately captures the metric I want.

PTAL.

I have a curious question that shouldn't block the landing of this PR: do we have any trace event unit tests? Fuchsia sometimes depends on our tracing events, so it might be nice to have some unit tests to guard the changes.

This pull request is not suitable for automatic merging in its current state.

• The status or check suite format_and_dart_test has failed. Please fix the issues identified (or deflake) before re-applying this label.

x-ref: flutter/flutter#54117