FrameTimings captures raster finish time in wall-clock time (flutter/engine#27074)

engine/src/flutter/common/settings.h

@@ -29,11 +29,13 @@ class FrameTiming {
     kBuildFinish,
     kRasterStart,
     kRasterFinish,
+    kRasterFinishWallTime,
     kCount
   };
 
   static constexpr Phase kPhases[kCount] = {
-      kVsyncStart, kBuildStart, kBuildFinish, kRasterStart, kRasterFinish};
+      kVsyncStart,  kBuildStart,   kBuildFinish,
+      kRasterStart, kRasterFinish, kRasterFinishWallTime};
 
   fml::TimePoint Get(Phase phase) const { return data_[phase]; }
   fml::TimePoint Set(Phase phase, fml::TimePoint value) {

engine/src/flutter/flow/frame_timings.cc

@@ -9,6 +9,7 @@
 
 #include "flutter/common/settings.h"
 #include "flutter/fml/logging.h"
+#include "flutter/fml/time/time_point.h"
 
 namespace flutter {
 
@@ -66,6 +67,12 @@ fml::TimePoint FrameTimingsRecorder::GetRasterEndTime() const {
   return raster_end_;
 }
 
+fml::TimePoint FrameTimingsRecorder::GetRasterEndWallTime() const {
+  std::scoped_lock state_lock(state_mutex_);
+  FML_DCHECK(state_ >= State::kRasterEnd);
+  return raster_end_wall_time_;
+}
+
 fml::TimeDelta FrameTimingsRecorder::GetBuildDuration() const {
   std::scoped_lock state_lock(state_mutex_);
   FML_DCHECK(state_ >= State::kBuildEnd);
@@ -102,16 +109,18 @@ void FrameTimingsRecorder::RecordRasterStart(fml::TimePoint raster_start) {
   raster_start_ = raster_start;
 }
 
-FrameTiming FrameTimingsRecorder::RecordRasterEnd(fml::TimePoint raster_end) {
+FrameTiming FrameTimingsRecorder::RecordRasterEnd() {
   std::scoped_lock state_lock(state_mutex_);
   FML_DCHECK(state_ == State::kRasterStart);
   state_ = State::kRasterEnd;
-  raster_end_ = raster_end;
+  raster_end_ = fml::TimePoint::Now();
+  raster_end_wall_time_ = fml::TimePoint::CurrentWallTime();
   timing_.Set(FrameTiming::kVsyncStart, vsync_start_);
   timing_.Set(FrameTiming::kBuildStart, build_start_);
   timing_.Set(FrameTiming::kBuildFinish, build_end_);
   timing_.Set(FrameTiming::kRasterStart, raster_start_);
   timing_.Set(FrameTiming::kRasterFinish, raster_end_);
+  timing_.Set(FrameTiming::kRasterFinishWallTime, raster_end_wall_time_);
   timing_.SetFrameNumber(GetFrameNumber());
   return timing_;
 }

engine/src/flutter/flow/frame_timings.h

@@ -64,6 +64,9 @@ class FrameTimingsRecorder {
   /// Timestamp of when the frame rasterization finished.
   fml::TimePoint GetRasterEndTime() const;
 
+  /// Timestamp of when the frame rasterization is complete in wall-time.
+  fml::TimePoint GetRasterEndWallTime() const;
+
   /// Duration of the frame build time.
   fml::TimeDelta GetBuildDuration() const;
 
@@ -84,7 +87,7 @@ class FrameTimingsRecorder {
 
   /// Records a raster end event, and builds a `FrameTiming` that summarizes all
   /// the events. This summary is sent to the framework.
-  FrameTiming RecordRasterEnd(fml::TimePoint raster_end);
+  FrameTiming RecordRasterEnd();
 
   /// Returns the frame number. Frame number is unique per frame and a frame
   /// built earlier will have a frame number less than a frame that has been
@@ -112,6 +115,7 @@ class FrameTimingsRecorder {
   fml::TimePoint build_end_;
   fml::TimePoint raster_start_;
   fml::TimePoint raster_end_;
+  fml::TimePoint raster_end_wall_time_;
 
   // Set when `RecordRasterEnd` is called. Cannot be reset once set.
   FrameTiming timing_;

engine/src/flutter/flow/frame_timings_recorder_unittests.cc

@@ -4,6 +4,8 @@
 
 #include "flutter/flow/frame_timings.h"
 
+#include <thread>
+
 #include "flutter/fml/time/time_delta.h"
 #include "flutter/fml/time/time_point.h"
 
@@ -50,13 +52,19 @@ TEST(FrameTimingsRecorderTest, RecordRasterTimes) {
   recorder->RecordBuildStart(build_start);
   recorder->RecordBuildEnd(build_end);
 
+  using namespace std::chrono_literals;
+
   const auto raster_start = fml::TimePoint::Now();
-  const auto raster_end = raster_start + fml::TimeDelta::FromMillisecondsF(16);
   recorder->RecordRasterStart(raster_start);
-  const auto timing = recorder->RecordRasterEnd(raster_end);
+  const auto before_raster_end_wall_time = fml::TimePoint::CurrentWallTime();
+  std::this_thread::sleep_for(1ms);
+  const auto timing = recorder->RecordRasterEnd();
+  std::this_thread::sleep_for(1ms);
+  const auto after_raster_end_wall_time = fml::TimePoint::CurrentWallTime();
 
   ASSERT_EQ(raster_start, recorder->GetRasterStartTime());
-  ASSERT_EQ(raster_end, recorder->GetRasterEndTime());
+  ASSERT_GT(recorder->GetRasterEndWallTime(), before_raster_end_wall_time);
+  ASSERT_LT(recorder->GetRasterEndWallTime(), after_raster_end_wall_time);
   ASSERT_EQ(recorder->GetFrameNumber(), timing.GetFrameNumber());
 }
 

engine/src/flutter/fml/time/time_point.cc

@@ -5,6 +5,7 @@
 #include "flutter/fml/time/time_point.h"
 
 #include "flutter/fml/build_config.h"
+#include "flutter/fml/logging.h"
 
 #if defined(OS_FUCHSIA)
 #include <zircon/syscalls.h>
@@ -21,14 +22,27 @@ TimePoint TimePoint::Now() {
   return TimePoint(zx_clock_get_monotonic());
 }
 
+TimePoint TimePoint::CurrentWallTime() {
+  return Now();
+}
+
 #else
 
+template <typename Clock, typename Duration>
+static int64_t NanosSinceEpoch(
+    std::chrono::time_point<Clock, Duration> time_point) {
+  const auto elapsed = time_point.time_since_epoch();
+  return std::chrono::duration_cast<std::chrono::nanoseconds>(elapsed).count();
+}
+
 TimePoint TimePoint::Now() {
-  // The base time is arbitrary; use the clock epoch for convenience.
-  const auto elapsed_time = std::chrono::steady_clock::now().time_since_epoch();
-  return TimePoint(
-      std::chrono::duration_cast<std::chrono::nanoseconds>(elapsed_time)
-          .count());
+  const int64_t nanos = NanosSinceEpoch(std::chrono::steady_clock::now());
+  return TimePoint(nanos);
+}
+
+TimePoint TimePoint::CurrentWallTime() {
+  const int64_t nanos = NanosSinceEpoch(std::chrono::system_clock::now());
+  return TimePoint(nanos);
 }
 
 #endif

engine/src/flutter/fml/time/time_point.h

@@ -25,6 +25,8 @@ class TimePoint {
 
   static TimePoint Now();
 
+  static TimePoint CurrentWallTime();
+
   static constexpr TimePoint Min() {
     return TimePoint(std::numeric_limits<int64_t>::min());
   }

engine/src/flutter/lib/ui/platform_dispatcher.dart

@@ -1148,6 +1148,12 @@ enum FramePhase {
   ///
   /// See also [FrameTiming.rasterDuration].
   rasterFinish,
+
+  /// When the raster thread finished rasterizing a frame in wall-time.
+  ///
+  /// This is useful for correlating time raster finish time with the system
+  /// clock to integrate with other profiling tools.
+  rasterFinishWallTime,
 }
 
 /// Time-related performance metrics of a frame.
@@ -1176,6 +1182,7 @@ class FrameTiming {
     required int buildFinish,
     required int rasterStart,
     required int rasterFinish,
+    int rasterFinishWallTime = -1,
     int frameNumber = -1,
   }) {
     return FrameTiming._(<int>[
@@ -1184,6 +1191,7 @@ class FrameTiming {
       buildFinish,
       rasterStart,
       rasterFinish,
+      if (rasterFinishWallTime == -1) rasterFinish else rasterFinishWallTime,
       frameNumber,
     ]);
   }

engine/src/flutter/lib/web_ui/lib/src/ui/platform_dispatcher.dart

@@ -200,6 +200,7 @@ enum FramePhase {
   buildFinish,
   rasterStart,
   rasterFinish,
+  rasterFinishWallTime,
 }
 
 class FrameTiming {
@@ -209,6 +210,7 @@ class FrameTiming {
     required int buildFinish,
     required int rasterStart,
     required int rasterFinish,
+    int rasterFinishWallTime = -1,
     int frameNumber = 1,
   }) {
     return FrameTiming._(<int>[
@@ -217,6 +219,7 @@ class FrameTiming {
       buildFinish,
       rasterStart,
       rasterFinish,
+      if (rasterFinishWallTime == -1) rasterFinish else rasterFinishWallTime,
       frameNumber,
     ]);
   }

engine/src/flutter/shell/common/rasterizer.cc

@@ -518,7 +518,7 @@ RasterStatus Rasterizer::DrawToSurface(
       frame->Submit();
     }
 
-    frame_timings_recorder.RecordRasterEnd(fml::TimePoint::Now());
+    frame_timings_recorder.RecordRasterEnd();
     FireNextFrameCallbackIfPresent();
 
     if (surface_->GetContext()) {

engine/src/flutter/shell/common/shell_unittests.cc

@@ -523,6 +523,12 @@ static void CheckFrameTimings(const std::vector<FrameTiming>& timings,
 
     fml::TimePoint last_phase_time;
     for (auto phase : FrameTiming::kPhases) {
+      // raster finish wall time doesn't use the same clock base
+      // as rest of the frame timings.
+      if (phase == FrameTiming::kRasterFinishWallTime) {
+        continue;
+      }
+
       ASSERT_TRUE(timings[i].Get(phase) >= start);
       ASSERT_TRUE(timings[i].Get(phase) <= finish);
 

engine/src/flutter/testing/dart/window_test.dart

@@ -27,6 +27,7 @@ void main() {
       buildFinish: 8000,
       rasterStart: 9000,
       rasterFinish: 19500,
+      rasterFinishWallTime: 19501,
       frameNumber: 23,
     );
     expect(timing.toString(), 'FrameTiming(buildDuration: 7.0ms, rasterDuration: 10.5ms, vsyncOverhead: 0.5ms, totalSpan: 19.0ms, frameNumber: 23)');