diff --git a/engine/src/flutter/common/settings.h b/engine/src/flutter/common/settings.h index cc496285ba7..89310ed07df 100644 --- a/engine/src/flutter/common/settings.h +++ b/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) { diff --git a/engine/src/flutter/flow/frame_timings.cc b/engine/src/flutter/flow/frame_timings.cc index 0ba314a9e8a..4bfaa0e9c05 100644 --- a/engine/src/flutter/flow/frame_timings.cc +++ b/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_; } diff --git a/engine/src/flutter/flow/frame_timings.h b/engine/src/flutter/flow/frame_timings.h index a2d47fa63be..a882a45db98 100644 --- a/engine/src/flutter/flow/frame_timings.h +++ b/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_; diff --git a/engine/src/flutter/flow/frame_timings_recorder_unittests.cc b/engine/src/flutter/flow/frame_timings_recorder_unittests.cc index 4d37e44c681..5ae9e6dcd51 100644 --- a/engine/src/flutter/flow/frame_timings_recorder_unittests.cc +++ b/engine/src/flutter/flow/frame_timings_recorder_unittests.cc @@ -4,6 +4,8 @@ #include "flutter/flow/frame_timings.h" +#include + #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()); } diff --git a/engine/src/flutter/fml/time/time_point.cc b/engine/src/flutter/fml/time/time_point.cc index ad1282879f9..7c54d704f95 100644 --- a/engine/src/flutter/fml/time/time_point.cc +++ b/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 @@ -21,14 +22,27 @@ TimePoint TimePoint::Now() { return TimePoint(zx_clock_get_monotonic()); } +TimePoint TimePoint::CurrentWallTime() { + return Now(); +} + #else +template +static int64_t NanosSinceEpoch( + std::chrono::time_point time_point) { + const auto elapsed = time_point.time_since_epoch(); + return std::chrono::duration_cast(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(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 diff --git a/engine/src/flutter/fml/time/time_point.h b/engine/src/flutter/fml/time/time_point.h index a8c65121e9e..7b26bc7bec0 100644 --- a/engine/src/flutter/fml/time/time_point.h +++ b/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::min()); } diff --git a/engine/src/flutter/lib/ui/platform_dispatcher.dart b/engine/src/flutter/lib/ui/platform_dispatcher.dart index 51c0ceaeb9c..c42b6336c8c 100644 --- a/engine/src/flutter/lib/ui/platform_dispatcher.dart +++ b/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._([ @@ -1184,6 +1191,7 @@ class FrameTiming { buildFinish, rasterStart, rasterFinish, + if (rasterFinishWallTime == -1) rasterFinish else rasterFinishWallTime, frameNumber, ]); } diff --git a/engine/src/flutter/lib/web_ui/lib/src/ui/platform_dispatcher.dart b/engine/src/flutter/lib/web_ui/lib/src/ui/platform_dispatcher.dart index 76c70b79c16..4349858cc3f 100644 --- a/engine/src/flutter/lib/web_ui/lib/src/ui/platform_dispatcher.dart +++ b/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._([ @@ -217,6 +219,7 @@ class FrameTiming { buildFinish, rasterStart, rasterFinish, + if (rasterFinishWallTime == -1) rasterFinish else rasterFinishWallTime, frameNumber, ]); } diff --git a/engine/src/flutter/shell/common/rasterizer.cc b/engine/src/flutter/shell/common/rasterizer.cc index 3c6ba5fbf23..8a149bebd5b 100644 --- a/engine/src/flutter/shell/common/rasterizer.cc +++ b/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()) { diff --git a/engine/src/flutter/shell/common/shell_unittests.cc b/engine/src/flutter/shell/common/shell_unittests.cc index 48c27a1b77f..58e7e780a7f 100644 --- a/engine/src/flutter/shell/common/shell_unittests.cc +++ b/engine/src/flutter/shell/common/shell_unittests.cc @@ -523,6 +523,12 @@ static void CheckFrameTimings(const std::vector& 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); diff --git a/engine/src/flutter/testing/dart/window_test.dart b/engine/src/flutter/testing/dart/window_test.dart index 2b8526bd0c5..774f45d26c7 100644 --- a/engine/src/flutter/testing/dart/window_test.dart +++ b/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)');