FrameTiming build start timestamp fix and add vsync start timestamp (#20229)

common/settings.h

@@ -22,10 +22,17 @@ namespace flutter {
 
 class FrameTiming {
  public:
-  enum Phase { kBuildStart, kBuildFinish, kRasterStart, kRasterFinish, kCount };
-
-  static constexpr Phase kPhases[kCount] = {kBuildStart, kBuildFinish,
-                                            kRasterStart, kRasterFinish};
+  enum Phase {
+    kVsyncStart,
+    kBuildStart,
+    kBuildFinish,
+    kRasterStart,
+    kRasterFinish,
+    kCount
+  };
+
+  static constexpr Phase kPhases[kCount] = {
+      kVsyncStart, kBuildStart, kBuildFinish, kRasterStart, kRasterFinish};
 
   fml::TimePoint Get(Phase phase) const { return data_[phase]; }
   fml::TimePoint Set(Phase phase, fml::TimePoint value) {

flow/layers/layer_tree.cc

@@ -21,8 +21,10 @@ LayerTree::LayerTree(const SkISize& frame_size,
       checkerboard_raster_cache_images_(false),
       checkerboard_offscreen_layers_(false) {}
 
-void LayerTree::RecordBuildTime(fml::TimePoint build_start,
+void LayerTree::RecordBuildTime(fml::TimePoint vsync_start,
+                                fml::TimePoint build_start,
                                 fml::TimePoint target_time) {
+  vsync_start_ = vsync_start;
   build_start_ = build_start;
   target_time_ = target_time;
   build_finish_ = fml::TimePoint::Now();

flow/layers/layer_tree.h

@@ -54,7 +54,11 @@ class LayerTree {
   float frame_physical_depth() const { return frame_physical_depth_; }
   float frame_device_pixel_ratio() const { return frame_device_pixel_ratio_; }
 
-  void RecordBuildTime(fml::TimePoint build_start, fml::TimePoint target_time);
+  void RecordBuildTime(fml::TimePoint vsync_start,
+                       fml::TimePoint build_start,
+                       fml::TimePoint target_time);
+  fml::TimePoint vsync_start() const { return vsync_start_; }
+  fml::TimeDelta vsync_overhead() const { return build_start_ - vsync_start_; }
   fml::TimePoint build_start() const { return build_start_; }
   fml::TimePoint build_finish() const { return build_finish_; }
   fml::TimeDelta build_time() const { return build_finish_ - build_start_; }
@@ -83,6 +87,7 @@ class LayerTree {
 
  private:
   std::shared_ptr<Layer> root_layer_;
+  fml::TimePoint vsync_start_;
   fml::TimePoint build_start_;
   fml::TimePoint build_finish_;
   fml::TimePoint target_time_;

lib/ui/hooks.dart

@@ -200,7 +200,7 @@ void _reportTimings(List<int> timings) {
   assert(timings.length % FramePhase.values.length == 0);
   final List<FrameTiming> frameTimings = <FrameTiming>[];
   for (int i = 0; i < timings.length; i += FramePhase.values.length) {
-    frameTimings.add(FrameTiming(timings.sublist(i, i + FramePhase.values.length)));
+    frameTimings.add(FrameTiming._(timings.sublist(i, i + FramePhase.values.length)));
   }
   _invoke1(window.onReportTimings, window._onReportTimingsZone, frameTimings);
 }

lib/ui/window.dart

@@ -47,6 +47,11 @@ typedef _SetNeedsReportTimingsFunc = void Function(bool value);
 ///
 /// [FrameTiming] records a timestamp of each phase for performance analysis.
 enum FramePhase {
+  /// The timestamp of the vsync signal given by the operating system.
+  ///
+  /// See also [FrameTiming.vsyncOverhead].
+  vsyncStart,
+
   /// When the UI thread starts building a frame.
   ///
   /// See also [FrameTiming.buildDuration].
@@ -82,6 +87,26 @@ enum FramePhase {
 /// Therefore it's recommended to only monitor and analyze performance metrics
 /// in profile and release modes.
 class FrameTiming {
+  /// Construct [FrameTiming] with raw timestamps in microseconds.
+  ///
+  /// This constructor is used for unit test only. Real [FrameTiming]s should
+  /// be retrieved from [Window.onReportTimings].
+  factory FrameTiming({
+    required int vsyncStart,
+    required int buildStart,
+    required int buildFinish,
+    required int rasterStart,
+    required int rasterFinish,
+  }) {
+    return FrameTiming._(<int>[
+      vsyncStart,
+      buildStart,
+      buildFinish,
+      rasterStart,
+      rasterFinish
+    ]);
+  }
+
   /// Construct [FrameTiming] with raw timestamps in microseconds.
   ///
   /// List [timestamps] must have the same number of elements as
@@ -89,7 +114,7 @@ class FrameTiming {
   ///
   /// This constructor is usually only called by the Flutter engine, or a test.
   /// To get the [FrameTiming] of your app, see [Window.onReportTimings].
-  FrameTiming(List<int> timestamps)
+  FrameTiming._(List<int> timestamps)
       : assert(timestamps.length == FramePhase.values.length), _timestamps = timestamps;
 
   /// Construct [FrameTiming] with given timestamp in micrseconds.
@@ -106,7 +131,9 @@ class FrameTiming {
     required int rasterStart,
     required int rasterFinish
   }) {
-    return FrameTiming(<int>[
+    return FrameTiming._(<int>[
+      // This is for temporarily backward compatiblilty.
+      vsyncStart ?? buildStart,
       buildStart,
       buildFinish,
       rasterStart,
@@ -143,14 +170,18 @@ class FrameTiming {
   /// {@macro dart.ui.FrameTiming.fps_milliseconds}
   Duration get rasterDuration => _rawDuration(FramePhase.rasterFinish) - _rawDuration(FramePhase.rasterStart);
 
-  /// The timespan between build start and raster finish.
+  /// The duration between receiving the vsync signal and starting building the
+  /// frame.
+  Duration get vsyncOverhead => _rawDuration(FramePhase.buildStart) - _rawDuration(FramePhase.vsyncStart);
+
+  /// The timespan between vsync start and raster finish.
   ///
   /// To achieve the lowest latency on an X fps display, this should not exceed
   /// 1000/X milliseconds.
   /// {@macro dart.ui.FrameTiming.fps_milliseconds}
   ///
-  /// See also [buildDuration] and [rasterDuration].
-  Duration get totalSpan => _rawDuration(FramePhase.rasterFinish) - _rawDuration(FramePhase.buildStart);
+  /// See also [vsyncOverhead], [buildDuration] and [rasterDuration].
+  Duration get totalSpan => _rawDuration(FramePhase.rasterFinish) - _rawDuration(FramePhase.vsyncStart);
 
   final List<int> _timestamps;  // in microseconds
 
@@ -158,7 +189,7 @@ class FrameTiming {
 
   @override
   String toString() {
-    return '$runtimeType(buildDuration: ${_formatMS(buildDuration)}, rasterDuration: ${_formatMS(rasterDuration)}, totalSpan: ${_formatMS(totalSpan)})';
+    return '$runtimeType(buildDuration: ${_formatMS(buildDuration)}, rasterDuration: ${_formatMS(rasterDuration)}, vsyncOverhead: ${_formatMS(vsyncOverhead)}, totalSpan: ${_formatMS(totalSpan)})';
   }
 }
 

lib/web_ui/lib/src/ui/window.dart

@@ -1005,6 +1005,11 @@ class IsolateNameServer {
 ///
 /// [FrameTiming] records a timestamp of each phase for performance analysis.
 enum FramePhase {
+  /// The timestamp of the vsync signal given by the operating system.
+  ///
+  /// See also [FrameTiming.vsyncOverhead].
+  vsyncStart,
+
   /// When the UI thread starts building a frame.
   ///
   /// See also [FrameTiming.buildDuration].
@@ -1035,6 +1040,26 @@ enum FramePhase {
 /// Therefore it's recommended to only monitor and analyze performance metrics
 /// in profile and release modes.
 class FrameTiming {
+  /// Construct [FrameTiming] with raw timestamps in microseconds.
+  ///
+  /// This constructor is used for unit test only. Real [FrameTiming]s should
+  /// be retrieved from [Window.onReportTimings].
+  factory FrameTiming({
+    required int vsyncStart,
+    required int buildStart,
+    required int buildFinish,
+    required int rasterStart,
+    required int rasterFinish,
+  }) {
+    return FrameTiming._(<int>[
+      vsyncStart,
+      buildStart,
+      buildFinish,
+      rasterStart,
+      rasterFinish
+    ]);
+  }
+
   /// Construct [FrameTiming] with raw timestamps in microseconds.
   ///
   /// List [timestamps] must have the same number of elements as
@@ -1042,9 +1067,8 @@ class FrameTiming {
   ///
   /// This constructor is usually only called by the Flutter engine, or a test.
   /// To get the [FrameTiming] of your app, see [Window.onReportTimings].
-  FrameTiming(List<int> timestamps)
-      : assert(timestamps.length == FramePhase.values.length),
-        _timestamps = timestamps;
+  FrameTiming._(List<int> timestamps)
+      : assert(timestamps.length == FramePhase.values.length), _timestamps = timestamps;
 
   /// Construct [FrameTiming] with given timestamp in micrseconds.
   ///
@@ -1053,13 +1077,22 @@ class FrameTiming {
   ///
   /// TODO(CareF): This is part of #20229. Remove back to default constructor
   /// after #20229 lands and corresponding framwork PRs land.
-  FrameTiming.fromTimeStamps({
+  factory FrameTiming.fromTimeStamps({
     int? vsyncStart,
     required int buildStart,
     required int buildFinish,
     required int rasterStart,
     required int rasterFinish
-  }) : _timestamps = <int>[buildStart, buildFinish, rasterStart, rasterFinish];
+  }) {
+    return FrameTiming._(<int>[
+      // This is for temporarily backward compatiblilty.
+      vsyncStart ?? buildStart,
+      buildStart,
+      buildFinish,
+      rasterStart,
+      rasterFinish
+    ]);
+  }
 
   /// This is a raw timestamp in microseconds from some epoch. The epoch in all
   /// [FrameTiming] is the same, but it may not match [DateTime]'s epoch.
@@ -1095,16 +1128,20 @@ class FrameTiming {
       _rawDuration(FramePhase.rasterFinish) -
       _rawDuration(FramePhase.rasterStart);
 
-  /// The timespan between build start and raster finish.
+  /// The duration between receiving the vsync signal and starting building the
+  /// frame.
+  Duration get vsyncOverhead => _rawDuration(FramePhase.buildStart) - _rawDuration(FramePhase.vsyncStart);
+
+  /// The timespan between vsync start and raster finish.
   ///
   /// To achieve the lowest latency on an X fps display, this should not exceed
   /// 1000/X milliseconds.
   /// {@macro dart.ui.FrameTiming.fps_milliseconds}
   ///
-  /// See also [buildDuration] and [rasterDuration].
+  /// See also [vsyncOverhead], [buildDuration] and [rasterDuration].
   Duration get totalSpan =>
       _rawDuration(FramePhase.rasterFinish) -
-      _rawDuration(FramePhase.buildStart);
+      _rawDuration(FramePhase.vsyncStart);
 
   final List<int> _timestamps; // in microseconds
 
@@ -1112,7 +1149,7 @@ class FrameTiming {
 
   @override
   String toString() {
-    return '$runtimeType(buildDuration: ${_formatMS(buildDuration)}, rasterDuration: ${_formatMS(rasterDuration)}, totalSpan: ${_formatMS(totalSpan)})';
+    return '$runtimeType(buildDuration: ${_formatMS(buildDuration)}, rasterDuration: ${_formatMS(rasterDuration)}, vsyncOverhead: ${_formatMS(vsyncOverhead)}, totalSpan: ${_formatMS(totalSpan)})';
   }
 }
 

shell/common/animator.cc

@@ -26,6 +26,7 @@ Animator::Animator(Delegate& delegate,
       task_runners_(std::move(task_runners)),
       waiter_(std::move(waiter)),
       last_frame_begin_time_(),
+      last_vsync_start_time_(),
       last_frame_target_time_(),
       dart_frame_deadline_(0),
 #if FLUTTER_SHELL_ENABLE_METAL
@@ -98,7 +99,7 @@ static int64_t FxlToDartOrEarlier(fml::TimePoint time) {
   return (time - fxl_now).ToMicroseconds() + dart_now;
 }
 
-void Animator::BeginFrame(fml::TimePoint frame_start_time,
+void Animator::BeginFrame(fml::TimePoint vsync_start_time,
                           fml::TimePoint frame_target_time) {
   TRACE_EVENT_ASYNC_END0("flutter", "Frame Request Pending", frame_number_++);
 
@@ -133,7 +134,11 @@ void Animator::BeginFrame(fml::TimePoint frame_start_time,
   // to service potential frame.
   FML_DCHECK(producer_continuation_);
 
-  last_frame_begin_time_ = frame_start_time;
+  last_frame_begin_time_ = fml::TimePoint::Now();
+  last_vsync_start_time_ = vsync_start_time;
+  fml::tracing::TraceEventAsyncComplete("flutter", "VsyncSchedulingOverhead",
+                                        last_vsync_start_time_,
+                                        last_frame_begin_time_);
   last_frame_target_time_ = frame_target_time;
   dart_frame_deadline_ = FxlToDartOrEarlier(frame_target_time);
   {
@@ -179,7 +184,8 @@ void Animator::Render(std::unique_ptr<flutter::LayerTree> layer_tree) {
   last_layer_tree_size_ = layer_tree->frame_size();
 
   // Note the frame time for instrumentation.
-  layer_tree->RecordBuildTime(last_frame_begin_time_, last_frame_target_time_);
+  layer_tree->RecordBuildTime(last_vsync_start_time_, last_frame_begin_time_,
+                              last_frame_target_time_);
 
   // Commit the pending continuation.
   bool result = producer_continuation_.Complete(std::move(layer_tree));
@@ -233,13 +239,13 @@ void Animator::RequestFrame(bool regenerate_layer_tree) {
 
 void Animator::AwaitVSync() {
   waiter_->AsyncWaitForVsync(
-      [self = weak_factory_.GetWeakPtr()](fml::TimePoint frame_start_time,
+      [self = weak_factory_.GetWeakPtr()](fml::TimePoint vsync_start_time,
                                           fml::TimePoint frame_target_time) {
         if (self) {
           if (self->CanReuseLastLayerTree()) {
             self->DrawLastLayerTree();
           } else {
-            self->BeginFrame(frame_start_time, frame_target_time);
+            self->BeginFrame(vsync_start_time, frame_target_time);
           }
         }
       });

shell/common/animator.h

@@ -98,6 +98,7 @@ class Animator final {
   std::shared_ptr<VsyncWaiter> waiter_;
 
   fml::TimePoint last_frame_begin_time_;
+  fml::TimePoint last_vsync_start_time_;
   fml::TimePoint last_frame_target_time_;
   int64_t dart_frame_deadline_;
   fml::RefPtr<LayerTreePipeline> layer_tree_pipeline_;

shell/common/rasterizer.cc

@@ -290,6 +290,7 @@ RasterStatus Rasterizer::DoDraw(
 #if !defined(OS_FUCHSIA)
   const fml::TimePoint frame_target_time = layer_tree->target_time();
 #endif
+  timing.Set(FrameTiming::kVsyncStart, layer_tree->vsync_start());
   timing.Set(FrameTiming::kBuildStart, layer_tree->build_start());
   timing.Set(FrameTiming::kBuildFinish, layer_tree->build_finish());
   timing.Set(FrameTiming::kRasterStart, fml::TimePoint::Now());

shell/common/vsync_waiter.cc

@@ -122,9 +122,6 @@ void VsyncWaiter::FireCallback(fml::TimePoint frame_start_time,
         [callback, flow_identifier, frame_start_time, frame_target_time]() {
           FML_TRACE_EVENT("flutter", kVsyncTraceName, "StartTime",
                           frame_start_time, "TargetTime", frame_target_time);
-          fml::tracing::TraceEventAsyncComplete(
-              "flutter", "VsyncSchedulingOverhead", fml::TimePoint::Now(),
-              frame_start_time);
           callback(frame_start_time, frame_target_time);
           TRACE_FLOW_END("flutter", kVsyncFlowName, flow_identifier);
         },

testing/dart/window_test.dart

@@ -22,8 +22,14 @@ void main() {
   });
 
   test('FrameTiming.toString has the correct format', () {
-    final FrameTiming timing = FrameTiming(<int>[1000, 8000, 9000, 19500]);
-    expect(timing.toString(), 'FrameTiming(buildDuration: 7.0ms, rasterDuration: 10.5ms, totalSpan: 18.5ms)');
+    final FrameTiming timing = FrameTiming(
+      vsyncStart: 500,
+      buildStart: 1000,
+      buildFinish: 8000,
+      rasterStart: 9000,
+      rasterFinish: 19500
+    );
+    expect(timing.toString(), 'FrameTiming(buildDuration: 7.0ms, rasterDuration: 10.5ms, vsyncOverhead: 0.5ms, totalSpan: 19.0ms)');
   });
 
   test('computePlatformResolvedLocale basic', () {