From 3db3a4c5d9e634fac50f0ce1ff90fd768f6da3e2 Mon Sep 17 00:00:00 2001 From: Jonah Williams Date: Wed, 19 May 2021 09:59:01 -0700 Subject: [PATCH] plumb frame number through to framework (#26233) --- common/settings.h | 4 ++++ flow/frame_timings.cc | 1 + flow/frame_timings_recorder_unittests.cc | 3 ++- lib/ui/platform_dispatcher.dart | 19 +++++++++++++------ .../lib/src/ui/platform_dispatcher.dart | 10 +++++++--- shell/common/shell.cc | 5 +++-- testing/dart/window_test.dart | 5 +++-- 7 files changed, 33 insertions(+), 14 deletions(-) diff --git a/common/settings.h b/common/settings.h index e3ad8589443f1..4b9ff999dc541 100644 --- a/common/settings.h +++ b/common/settings.h @@ -40,8 +40,12 @@ class FrameTiming { return data_[phase] = value; } + uint64_t GetFrameNumber() const { return frame_number_; } + void SetFrameNumber(uint64_t frame_number) { frame_number_ = frame_number; } + private: fml::TimePoint data_[kCount]; + uint64_t frame_number_; }; using TaskObserverAdd = diff --git a/flow/frame_timings.cc b/flow/frame_timings.cc index 847227ed9db8c..16dce12f57e16 100644 --- a/flow/frame_timings.cc +++ b/flow/frame_timings.cc @@ -109,6 +109,7 @@ FrameTiming FrameTimingsRecorder::RecordRasterEnd(fml::TimePoint raster_end) { timing.Set(FrameTiming::kBuildFinish, build_end_); timing.Set(FrameTiming::kRasterStart, raster_start_); timing.Set(FrameTiming::kRasterFinish, raster_end_); + timing.SetFrameNumber(GetFrameNumber()); return timing; } diff --git a/flow/frame_timings_recorder_unittests.cc b/flow/frame_timings_recorder_unittests.cc index db843b91fa50f..30f908b248574 100644 --- a/flow/frame_timings_recorder_unittests.cc +++ b/flow/frame_timings_recorder_unittests.cc @@ -53,10 +53,11 @@ TEST(FrameTimingsRecorderTest, RecordRasterTimes) { const auto raster_start = fml::TimePoint::Now(); const auto raster_end = raster_start + fml::TimeDelta::FromMillisecondsF(16); recorder->RecordRasterStart(raster_start); - recorder->RecordRasterEnd(raster_end); + const auto timing = recorder->RecordRasterEnd(raster_end); ASSERT_EQ(raster_start, recorder->GetRasterStartTime()); ASSERT_EQ(raster_end, recorder->GetRasterEndTime()); + ASSERT_EQ(recorder->GetFrameNumber(), timing.GetFrameNumber()); } // Windows and Fuchsia don't allow testing with killed by signal. diff --git a/lib/ui/platform_dispatcher.dart b/lib/ui/platform_dispatcher.dart index 3efa757e6dae2..c6244103c973b 100644 --- a/lib/ui/platform_dispatcher.dart +++ b/lib/ui/platform_dispatcher.dart @@ -433,10 +433,10 @@ class PlatformDispatcher { // Called from the engine, via hooks.dart void _reportTimings(List timings) { - assert(timings.length % FramePhase.values.length == 0); + assert(timings.length % (FramePhase.values.length + 1) == 0); final List frameTimings = []; - for (int i = 0; i < timings.length; i += FramePhase.values.length) { - frameTimings.add(FrameTiming._(timings.sublist(i, i + FramePhase.values.length))); + for (int i = 0; i < timings.length; i += FramePhase.values.length + 1) { + frameTimings.add(FrameTiming._(timings.sublist(i, i + FramePhase.values.length + 1))); } _invoke1(onReportTimings, _onReportTimingsZone, frameTimings); } @@ -1145,19 +1145,23 @@ class FrameTiming { /// /// This constructor is used for unit test only. Real [FrameTiming]s should /// be retrieved from [PlatformDispatcher.onReportTimings]. + /// + /// If the [frameNumber] is not provided, it defaults to `-1`. factory FrameTiming({ required int vsyncStart, required int buildStart, required int buildFinish, required int rasterStart, required int rasterFinish, + int frameNumber = -1, }) { return FrameTiming._([ vsyncStart, buildStart, buildFinish, rasterStart, - rasterFinish + rasterFinish, + frameNumber, ]); } @@ -1169,7 +1173,7 @@ class FrameTiming { /// This constructor is usually only called by the Flutter engine, or a test. /// To get the [FrameTiming] of your app, see [PlatformDispatcher.onReportTimings]. FrameTiming._(this._timestamps) - : assert(_timestamps.length == FramePhase.values.length); + : assert(_timestamps.length == FramePhase.values.length + 1); /// 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. @@ -1214,13 +1218,16 @@ class FrameTiming { /// See also [vsyncOverhead], [buildDuration] and [rasterDuration]. Duration get totalSpan => _rawDuration(FramePhase.rasterFinish) - _rawDuration(FramePhase.vsyncStart); + /// The frame key associated with this frame measurement. + int get frameNumber => _timestamps.last; + final List _timestamps; // in microseconds String _formatMS(Duration duration) => '${duration.inMicroseconds * 0.001}ms'; @override String toString() { - return '$runtimeType(buildDuration: ${_formatMS(buildDuration)}, rasterDuration: ${_formatMS(rasterDuration)}, vsyncOverhead: ${_formatMS(vsyncOverhead)}, totalSpan: ${_formatMS(totalSpan)})'; + return '$runtimeType(buildDuration: ${_formatMS(buildDuration)}, rasterDuration: ${_formatMS(rasterDuration)}, vsyncOverhead: ${_formatMS(vsyncOverhead)}, totalSpan: ${_formatMS(totalSpan)}, frameNumber: ${_timestamps.last})'; } } diff --git a/lib/web_ui/lib/src/ui/platform_dispatcher.dart b/lib/web_ui/lib/src/ui/platform_dispatcher.dart index 9371814356f2b..f802d9fc4d19b 100644 --- a/lib/web_ui/lib/src/ui/platform_dispatcher.dart +++ b/lib/web_ui/lib/src/ui/platform_dispatcher.dart @@ -204,18 +204,20 @@ class FrameTiming { required int buildFinish, required int rasterStart, required int rasterFinish, + int frameNumber = 1, }) { return FrameTiming._([ vsyncStart, buildStart, buildFinish, rasterStart, - rasterFinish + rasterFinish, + frameNumber, ]); } FrameTiming._(this._timestamps) - : assert(_timestamps.length == FramePhase.values.length); + : assert(_timestamps.length == FramePhase.values.length + 1); int timestampInMicroseconds(FramePhase phase) => _timestamps[phase.index]; @@ -232,13 +234,15 @@ class FrameTiming { Duration get totalSpan => _rawDuration(FramePhase.rasterFinish) - _rawDuration(FramePhase.vsyncStart); + int get frameNumber => _timestamps.last; + final List _timestamps; // in microseconds String _formatMS(Duration duration) => '${duration.inMicroseconds * 0.001}ms'; @override String toString() { - return '$runtimeType(buildDuration: ${_formatMS(buildDuration)}, rasterDuration: ${_formatMS(rasterDuration)}, vsyncOverhead: ${_formatMS(vsyncOverhead)}, totalSpan: ${_formatMS(totalSpan)})'; + return '$runtimeType(buildDuration: ${_formatMS(buildDuration)}, rasterDuration: ${_formatMS(rasterDuration)}, vsyncOverhead: ${_formatMS(vsyncOverhead)}, totalSpan: ${_formatMS(totalSpan)}, frameNumber: $frameNumber)'; } } diff --git a/shell/common/shell.cc b/shell/common/shell.cc index 8c37afa183eff..4db17e85087ec 100644 --- a/shell/common/shell.cc +++ b/shell/common/shell.cc @@ -1353,8 +1353,8 @@ void Shell::ReportTimings() { size_t Shell::UnreportedFramesCount() const { // Check that this is running on the raster thread to avoid race conditions. FML_DCHECK(task_runners_.GetRasterTaskRunner()->RunsTasksOnCurrentThread()); - FML_DCHECK(unreported_timings_.size() % FrameTiming::kCount == 0); - return unreported_timings_.size() / FrameTiming::kCount; + FML_DCHECK(unreported_timings_.size() % (FrameTiming::kCount + 1) == 0); + return unreported_timings_.size() / (FrameTiming::kCount + 1); } void Shell::OnFrameRasterized(const FrameTiming& timing) { @@ -1375,6 +1375,7 @@ void Shell::OnFrameRasterized(const FrameTiming& timing) { unreported_timings_.push_back( timing.Get(phase).ToEpochDelta().ToMicroseconds()); } + unreported_timings_.push_back(timing.GetFrameNumber()); // In tests using iPhone 6S with profile mode, sending a batch of 1 frame or a // batch of 100 frames have roughly the same cost of less than 0.1ms. Sending diff --git a/testing/dart/window_test.dart b/testing/dart/window_test.dart index 79767f881e7bc..d54f209f81993 100644 --- a/testing/dart/window_test.dart +++ b/testing/dart/window_test.dart @@ -27,9 +27,10 @@ void main() { buildStart: 1000, buildFinish: 8000, rasterStart: 9000, - rasterFinish: 19500 + rasterFinish: 19500, + frameNumber: 23, ); - expect(timing.toString(), 'FrameTiming(buildDuration: 7.0ms, rasterDuration: 10.5ms, vsyncOverhead: 0.5ms, totalSpan: 19.0ms)'); + expect(timing.toString(), 'FrameTiming(buildDuration: 7.0ms, rasterDuration: 10.5ms, vsyncOverhead: 0.5ms, totalSpan: 19.0ms, frameNumber: 23)'); }); test('computePlatformResolvedLocale basic', () {