diff --git a/ci/firebase_testlab.sh b/ci/firebase_testlab.sh index 31ad03f87aec2..808035040b877 100755 --- a/ci/firebase_testlab.sh +++ b/ci/firebase_testlab.sh @@ -32,4 +32,4 @@ gcloud --project flutter-infra firebase test android run \ --timeout 2m \ --results-bucket=gs://flutter_firebase_testlab \ --results-dir="engine_scenario_test/$GIT_REVISION/$BUILD_ID" \ - --device model=flame,version=29 + --device model=flame,version=29 diff --git a/ci/licenses_golden/licenses_flutter b/ci/licenses_golden/licenses_flutter index 2d4afaff7f585..b6d65ab5b9cd6 100755 --- a/ci/licenses_golden/licenses_flutter +++ b/ci/licenses_golden/licenses_flutter @@ -42,6 +42,9 @@ FILE: ../../../flutter/flow/embedded_views.h FILE: ../../../flutter/flow/flow_run_all_unittests.cc FILE: ../../../flutter/flow/flow_test_utils.cc FILE: ../../../flutter/flow/flow_test_utils.h +FILE: ../../../flutter/flow/frame_timings.cc +FILE: ../../../flutter/flow/frame_timings.h +FILE: ../../../flutter/flow/frame_timings_recorder_unittests.cc FILE: ../../../flutter/flow/gl_context_switch_unittests.cc FILE: ../../../flutter/flow/instrumentation.cc FILE: ../../../flutter/flow/instrumentation.h diff --git a/flow/BUILD.gn b/flow/BUILD.gn index e112594570c3e..1efd32e6cb622 100644 --- a/flow/BUILD.gn +++ b/flow/BUILD.gn @@ -14,6 +14,8 @@ source_set("flow") { "diff_context.h", "embedded_views.cc", "embedded_views.h", + "frame_timings.cc", + "frame_timings.h", "instrumentation.cc", "instrumentation.h", "layers/backdrop_filter_layer.cc", @@ -143,6 +145,7 @@ if (enable_unittests) { "flow_run_all_unittests.cc", "flow_test_utils.cc", "flow_test_utils.h", + "frame_timings_recorder_unittests.cc", "gl_context_switch_unittests.cc", "layers/backdrop_filter_layer_unittests.cc", "layers/checkerboard_layertree_unittests.cc", diff --git a/flow/frame_timings.cc b/flow/frame_timings.cc new file mode 100644 index 0000000000000..d8e1589f5d1bf --- /dev/null +++ b/flow/frame_timings.cc @@ -0,0 +1,135 @@ +// Copyright 2013 The Flutter Authors. All rights reserved. +// Use of this source code is governed by a BSD-style license that can be +// found in the LICENSE file. + +#include "flutter/flow/frame_timings.h" + +#include + +#include "flutter/common/settings.h" +#include "flutter/fml/logging.h" + +namespace flutter { + +FrameTimingsRecorder::FrameTimingsRecorder() = default; + +FrameTimingsRecorder::~FrameTimingsRecorder() = default; + +fml::TimePoint FrameTimingsRecorder::GetVsyncStartTime() const { + std::scoped_lock state_lock(state_mutex_); + FML_DCHECK(state_ >= State::kVsync); + return vsync_start_; +} + +fml::TimePoint FrameTimingsRecorder::GetVsyncTargetTime() const { + std::scoped_lock state_lock(state_mutex_); + FML_DCHECK(state_ >= State::kVsync); + return vsync_target_; +} + +fml::TimePoint FrameTimingsRecorder::GetBuildStartTime() const { + std::scoped_lock state_lock(state_mutex_); + FML_DCHECK(state_ >= State::kBuildStart); + return build_start_; +} + +fml::TimePoint FrameTimingsRecorder::GetBuildEndTime() const { + std::scoped_lock state_lock(state_mutex_); + FML_DCHECK(state_ >= State::kBuildEnd); + return build_end_; +} + +fml::TimePoint FrameTimingsRecorder::GetRasterStartTime() const { + std::scoped_lock state_lock(state_mutex_); + FML_DCHECK(state_ >= State::kRasterStart); + return raster_start_; +} + +fml::TimePoint FrameTimingsRecorder::GetRasterEndTime() const { + std::scoped_lock state_lock(state_mutex_); + FML_DCHECK(state_ >= State::kRasterEnd); + return raster_end_; +} + +fml::TimeDelta FrameTimingsRecorder::GetBuildDuration() const { + std::scoped_lock state_lock(state_mutex_); + FML_DCHECK(state_ >= State::kBuildEnd); + return build_end_ - build_start_; +} + +void FrameTimingsRecorder::RecordVsync(fml::TimePoint vsync_start, + fml::TimePoint vsync_target) { + std::scoped_lock state_lock(state_mutex_); + FML_DCHECK(state_ == State::kUninitialized); + state_ = State::kVsync; + vsync_start_ = vsync_start; + vsync_target_ = vsync_target; +} + +void FrameTimingsRecorder::RecordBuildStart(fml::TimePoint build_start) { + std::scoped_lock state_lock(state_mutex_); + FML_DCHECK(state_ == State::kVsync); + state_ = State::kBuildStart; + build_start_ = build_start; +} + +void FrameTimingsRecorder::RecordBuildEnd(fml::TimePoint build_end) { + std::scoped_lock state_lock(state_mutex_); + FML_DCHECK(state_ == State::kBuildStart); + state_ = State::kBuildEnd; + build_end_ = build_end; +} + +void FrameTimingsRecorder::RecordRasterStart(fml::TimePoint raster_start) { + std::scoped_lock state_lock(state_mutex_); + FML_DCHECK(state_ == State::kBuildEnd); + state_ = State::kRasterStart; + raster_start_ = raster_start; +} + +FrameTiming FrameTimingsRecorder::RecordRasterEnd(fml::TimePoint raster_end) { + std::scoped_lock state_lock(state_mutex_); + FML_DCHECK(state_ == State::kRasterStart); + state_ = State::kRasterEnd; + raster_end_ = raster_end; + FrameTiming timing; + 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_); + return timing; +} + +std::unique_ptr FrameTimingsRecorder::CloneUntil( + State state) { + std::scoped_lock state_lock(state_mutex_); + std::unique_ptr recorder = + std::make_unique(); + recorder->state_ = state; + + if (state >= State::kVsync) { + recorder->vsync_start_ = vsync_start_; + recorder->vsync_target_ = vsync_target_; + } + + if (state >= State::kBuildStart) { + recorder->build_start_ = build_start_; + } + + if (state >= State::kRasterEnd) { + recorder->build_end_ = build_end_; + } + + if (state >= State::kRasterStart) { + recorder->raster_start_ = raster_start_; + } + + if (state >= State::kRasterEnd) { + recorder->raster_end_ = raster_end_; + } + + return recorder; +} + +} // namespace flutter diff --git a/flow/frame_timings.h b/flow/frame_timings.h new file mode 100644 index 0000000000000..07e9f167f1526 --- /dev/null +++ b/flow/frame_timings.h @@ -0,0 +1,98 @@ +// Copyright 2013 The Flutter Authors. All rights reserved. +// Use of this source code is governed by a BSD-style license that can be +// found in the LICENSE file. + +#ifndef FLUTTER_FLOW_FRAME_TIMINGS_H_ +#define FLUTTER_FLOW_FRAME_TIMINGS_H_ + +#include + +#include "flutter/common/settings.h" +#include "flutter/fml/macros.h" +#include "flutter/fml/time/time_delta.h" +#include "flutter/fml/time/time_point.h" + +namespace flutter { + +/// Records timestamps for various phases of a frame rendering process. +/// +/// Recorder is created on vsync and destroyed after the rasterization of the +/// frame. This class is thread safe and doesn't require additional +/// synchronization. +class FrameTimingsRecorder { + public: + /// Various states that the recorder can be in. When created the recorder is + /// in an unitialized state and transtions in sequential order of the states. + enum class State : uint32_t { + kUninitialized, + kVsync, + kBuildStart, + kBuildEnd, + kRasterStart, + kRasterEnd, + }; + + /// Default constructor, initializes the recorder with State::kUninitialized. + FrameTimingsRecorder(); + + ~FrameTimingsRecorder(); + + /// Timestamp of the vsync signal. + fml::TimePoint GetVsyncStartTime() const; + + /// Timestamp of when the frame was targeted to be presented. + /// + /// This is typically the next vsync signal timestamp. + fml::TimePoint GetVsyncTargetTime() const; + + /// Timestamp of when the frame building started. + fml::TimePoint GetBuildStartTime() const; + + /// Timestamp of when the frame was finished building. + fml::TimePoint GetBuildEndTime() const; + + /// Timestamp of when the frame rasterization started. + fml::TimePoint GetRasterStartTime() const; + + /// Timestamp of when the frame rasterization finished. + fml::TimePoint GetRasterEndTime() const; + + /// Duration of the frame build time. + fml::TimeDelta GetBuildDuration() const; + + /// Records a vsync event. + void RecordVsync(fml::TimePoint vsync_start, fml::TimePoint vsync_target); + + /// Records a build start event. + void RecordBuildStart(fml::TimePoint build_start); + + /// Records a build end event. + void RecordBuildEnd(fml::TimePoint build_end); + + /// Records a raster start event. + void RecordRasterStart(fml::TimePoint raster_start); + + /// Clones the recorder until (and including) the specified state. + std::unique_ptr CloneUntil(State state); + + /// 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); + + private: + mutable std::mutex state_mutex_; + State state_ = State::kUninitialized; + + fml::TimePoint vsync_start_; + fml::TimePoint vsync_target_; + fml::TimePoint build_start_; + fml::TimePoint build_end_; + fml::TimePoint raster_start_; + fml::TimePoint raster_end_; + + FML_DISALLOW_COPY_ASSIGN_AND_MOVE(FrameTimingsRecorder); +}; + +} // namespace flutter + +#endif // FLUTTER_FLOW_FRAME_TIMINGS_H_ diff --git a/flow/frame_timings_recorder_unittests.cc b/flow/frame_timings_recorder_unittests.cc new file mode 100644 index 0000000000000..975af1cee14c6 --- /dev/null +++ b/flow/frame_timings_recorder_unittests.cc @@ -0,0 +1,91 @@ +// Copyright 2013 The Flutter Authors. All rights reserved. +// Use of this source code is governed by a BSD-style license that can be +// found in the LICENSE file. + +#include "flutter/flow/frame_timings.h" + +#include "flutter/fml/time/time_delta.h" +#include "flutter/fml/time/time_point.h" + +#include "gtest/gtest.h" + +namespace flutter { +namespace testing { + +TEST(FrameTimingsRecorderTest, RecordVsync) { + auto recorder = std::make_unique(); + const auto st = fml::TimePoint::Now(); + const auto en = st + fml::TimeDelta::FromMillisecondsF(16); + recorder->RecordVsync(st, en); + + ASSERT_EQ(st, recorder->GetVsyncStartTime()); + ASSERT_EQ(en, recorder->GetVsyncTargetTime()); +} + +TEST(FrameTimingsRecorderTest, RecordBuildTimes) { + auto recorder = std::make_unique(); + + const auto st = fml::TimePoint::Now(); + const auto en = st + fml::TimeDelta::FromMillisecondsF(16); + recorder->RecordVsync(st, en); + + const auto build_start = fml::TimePoint::Now(); + const auto build_end = build_start + fml::TimeDelta::FromMillisecondsF(16); + recorder->RecordBuildStart(build_start); + recorder->RecordBuildEnd(build_end); + + ASSERT_EQ(build_start, recorder->GetBuildStartTime()); + ASSERT_EQ(build_end, recorder->GetBuildEndTime()); +} + +TEST(FrameTimingsRecorderTest, RecordRasterTimes) { + auto recorder = std::make_unique(); + + const auto st = fml::TimePoint::Now(); + const auto en = st + fml::TimeDelta::FromMillisecondsF(16); + recorder->RecordVsync(st, en); + + const auto build_start = fml::TimePoint::Now(); + const auto build_end = build_start + fml::TimeDelta::FromMillisecondsF(16); + recorder->RecordBuildStart(build_start); + recorder->RecordBuildEnd(build_end); + + 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); + + ASSERT_EQ(raster_start, recorder->GetRasterStartTime()); + ASSERT_EQ(raster_end, recorder->GetRasterEndTime()); +} + +// Windows and Fuchsia don't allow testing with killed by signal. +#if !defined(OS_FUCHSIA) && !defined(OS_WIN) && \ + (FLUTTER_RUNTIME_MODE == FLUTTER_RUNTIME_MODE_DEBUG) + +TEST(FrameTimingsRecorderTest, ThrowWhenRecordBuildBeforeVsync) { + auto recorder = std::make_unique(); + + const auto build_start = fml::TimePoint::Now(); + EXPECT_EXIT(recorder->RecordBuildStart(build_start), + ::testing::KilledBySignal(SIGABRT), + "Check failed: state_ == State::kVsync."); +} + +TEST(FrameTimingsRecorderTest, ThrowWhenRecordRasterBeforeBuildEnd) { + auto recorder = std::make_unique(); + + const auto st = fml::TimePoint::Now(); + const auto en = st + fml::TimeDelta::FromMillisecondsF(16); + recorder->RecordVsync(st, en); + + const auto raster_start = fml::TimePoint::Now(); + EXPECT_EXIT(recorder->RecordRasterStart(raster_start), + ::testing::KilledBySignal(SIGABRT), + "Check failed: state_ == State::kBuildEnd."); +} + +#endif + +} // namespace testing +} // namespace flutter diff --git a/flow/layers/layer_tree.cc b/flow/layers/layer_tree.cc index eb58bc1c4aeaf..2fa755f511453 100644 --- a/flow/layers/layer_tree.cc +++ b/flow/layers/layer_tree.cc @@ -4,7 +4,9 @@ #include "flutter/flow/layers/layer_tree.h" +#include "flutter/flow/frame_timings.h" #include "flutter/flow/layers/layer.h" +#include "flutter/fml/time/time_point.h" #include "flutter/fml/trace_event.h" #include "third_party/skia/include/core/SkPictureRecorder.h" #include "third_party/skia/include/utils/SkNWayCanvas.h" @@ -20,15 +22,6 @@ LayerTree::LayerTree(const SkISize& frame_size, float device_pixel_ratio) FML_CHECK(device_pixel_ratio_ != 0.0f); } -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(); -} - bool LayerTree::Preroll(CompositorContext::ScopedFrame& frame, bool ignore_raster_cache) { TRACE_EVENT0("flutter", "LayerTree::Preroll"); diff --git a/flow/layers/layer_tree.h b/flow/layers/layer_tree.h index db8a33b4506c8..67a32ca6b3c5c 100644 --- a/flow/layers/layer_tree.h +++ b/flow/layers/layer_tree.h @@ -56,16 +56,6 @@ class LayerTree { #endif // FLUTTER_ENABLE_DIFF_CONTEXT - 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_; } - fml::TimePoint target_time() const { return target_time_; } - // The number of frame intervals missed after which the compositor must // trace the rasterized picture to a trace file. Specify 0 to disable all // tracing @@ -87,10 +77,6 @@ class LayerTree { private: std::shared_ptr root_layer_; - fml::TimePoint vsync_start_; - fml::TimePoint build_start_; - fml::TimePoint build_finish_; - fml::TimePoint target_time_; SkISize frame_size_ = SkISize::MakeEmpty(); // Physical pixels. const float device_pixel_ratio_; // Logical / Physical pixels ratio. uint32_t rasterizer_tracing_threshold_; diff --git a/lib/ui/painting/image_decoder_unittests.cc b/lib/ui/painting/image_decoder_unittests.cc index 6e74df5ac0189..7b787b08e791b 100644 --- a/lib/ui/painting/image_decoder_unittests.cc +++ b/lib/ui/painting/image_decoder_unittests.cc @@ -427,7 +427,8 @@ TEST_F(ImageDecoderFixtureTest, CanDecodeWithResizes) { latch.Wait(); } -// TODO(https://github.com/flutter/flutter/issues/81232) - disabled due to flakiness +// TODO(https://github.com/flutter/flutter/issues/81232) - disabled due to +// flakiness TEST_F(ImageDecoderFixtureTest, DISABLED_CanResizeWithoutDecode) { SkImageInfo info = {}; size_t row_bytes; diff --git a/shell/common/animator.cc b/shell/common/animator.cc index c2fc83e45d60e..160ffbc45498f 100644 --- a/shell/common/animator.cc +++ b/shell/common/animator.cc @@ -4,6 +4,8 @@ #include "flutter/shell/common/animator.h" +#include "flutter/flow/frame_timings.h" +#include "flutter/fml/time/time_point.h" #include "flutter/fml/trace_event.h" #include "third_party/dart/runtime/include/dart_tools_api.h" @@ -25,9 +27,6 @@ Animator::Animator(Delegate& delegate, : 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 SHELL_ENABLE_METAL layer_tree_pipeline_(fml::MakeRefCounted(2)), @@ -96,10 +95,13 @@ static int64_t FxlToDartOrEarlier(fml::TimePoint time) { return (time - fxl_now).ToMicroseconds() + dart_now; } -void Animator::BeginFrame(fml::TimePoint vsync_start_time, - fml::TimePoint frame_target_time) { +void Animator::BeginFrame( + std::unique_ptr frame_timings_recorder) { TRACE_EVENT_ASYNC_END0("flutter", "Frame Request Pending", frame_number_++); + frame_timings_recorder_ = std::move(frame_timings_recorder); + frame_timings_recorder_->RecordBuildStart(fml::TimePoint::Now()); + TRACE_EVENT0("flutter", "Animator::BeginFrame"); while (!trace_flow_ids_.empty()) { uint64_t trace_flow_id = trace_flow_ids_.front(); @@ -130,13 +132,12 @@ void Animator::BeginFrame(fml::TimePoint vsync_start_time, // We have acquired a valid continuation from the pipeline and are ready // to service potential frame. FML_DCHECK(producer_continuation_); - - 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; + fml::tracing::TraceEventAsyncComplete( + "flutter", "VsyncSchedulingOverhead", + frame_timings_recorder_->GetVsyncStartTime(), + frame_timings_recorder_->GetBuildStartTime()); + const fml::TimePoint frame_target_time = + frame_timings_recorder_->GetVsyncTargetTime(); dart_frame_deadline_ = FxlToDartOrEarlier(frame_target_time); { TRACE_EVENT2("flutter", "Framework Workload", "mode", "basic", "frame", @@ -180,9 +181,15 @@ void Animator::Render(std::unique_ptr layer_tree) { } last_layer_tree_size_ = layer_tree->frame_size(); - // Note the frame time for instrumentation. - layer_tree->RecordBuildTime(last_vsync_start_time_, last_frame_begin_time_, - last_frame_target_time_); + if (!frame_timings_recorder_) { + // Framework can directly call render with a built scene. + frame_timings_recorder_ = std::make_unique(); + const fml::TimePoint placeholder_time = fml::TimePoint::Now(); + frame_timings_recorder_->RecordVsync(placeholder_time, placeholder_time); + frame_timings_recorder_->RecordBuildStart(placeholder_time); + } + + frame_timings_recorder_->RecordBuildEnd(fml::TimePoint::Now()); // Commit the pending continuation. bool result = producer_continuation_.Complete(std::move(layer_tree)); @@ -190,16 +197,25 @@ void Animator::Render(std::unique_ptr layer_tree) { FML_DLOG(INFO) << "No pending continuation to commit"; } - delegate_.OnAnimatorDraw(layer_tree_pipeline_, last_frame_target_time_); + delegate_.OnAnimatorDraw(layer_tree_pipeline_, + std::move(frame_timings_recorder_)); } bool Animator::CanReuseLastLayerTree() { return !regenerate_layer_tree_; } -void Animator::DrawLastLayerTree() { +void Animator::DrawLastLayerTree( + std::unique_ptr frame_timings_recorder) { pending_frame_semaphore_.Signal(); - delegate_.OnAnimatorDrawLastLayerTree(); + // In this case BeginFrame doesn't get called, we need to + // adjust frame timings to update build start and end times, + // given that the frame doesn't get built in this case, we + // will use Now() for both start and end times as an indication. + const auto now = fml::TimePoint::Now(); + frame_timings_recorder->RecordBuildStart(now); + frame_timings_recorder->RecordBuildEnd(now); + delegate_.OnAnimatorDrawLastLayerTree(std::move(frame_timings_recorder)); } void Animator::RequestFrame(bool regenerate_layer_tree) { @@ -236,13 +252,13 @@ void Animator::RequestFrame(bool regenerate_layer_tree) { void Animator::AwaitVSync() { waiter_->AsyncWaitForVsync( - [self = weak_factory_.GetWeakPtr()](fml::TimePoint vsync_start_time, - fml::TimePoint frame_target_time) { + [self = weak_factory_.GetWeakPtr()]( + std::unique_ptr frame_timings_recorder) { if (self) { if (self->CanReuseLastLayerTree()) { - self->DrawLastLayerTree(); + self->DrawLastLayerTree(std::move(frame_timings_recorder)); } else { - self->BeginFrame(vsync_start_time, frame_target_time); + self->BeginFrame(std::move(frame_timings_recorder)); } } }); diff --git a/shell/common/animator.h b/shell/common/animator.h index 6927e85cc7aac..c8efaffd04850 100644 --- a/shell/common/animator.h +++ b/shell/common/animator.h @@ -8,6 +8,7 @@ #include #include "flutter/common/task_runners.h" +#include "flutter/flow/frame_timings.h" #include "flutter/fml/memory/ref_ptr.h" #include "flutter/fml/memory/weak_ptr.h" #include "flutter/fml/synchronization/semaphore.h" @@ -36,9 +37,10 @@ class Animator final { virtual void OnAnimatorDraw( fml::RefPtr> pipeline, - fml::TimePoint frame_target_time) = 0; + std::unique_ptr frame_timings_recorder) = 0; - virtual void OnAnimatorDrawLastLayerTree() = 0; + virtual void OnAnimatorDrawLastLayerTree( + std::unique_ptr frame_timings_recorder) = 0; }; Animator(Delegate& delegate, @@ -83,11 +85,12 @@ class Animator final { private: using LayerTreePipeline = Pipeline; - void BeginFrame(fml::TimePoint frame_start_time, - fml::TimePoint frame_target_time); + void BeginFrame(std::unique_ptr frame_timings_recorder); bool CanReuseLastLayerTree(); - void DrawLastLayerTree(); + + void DrawLastLayerTree( + std::unique_ptr frame_timings_recorder); void AwaitVSync(); @@ -100,9 +103,7 @@ class Animator final { TaskRunners task_runners_; std::shared_ptr waiter_; - fml::TimePoint last_frame_begin_time_; - fml::TimePoint last_vsync_start_time_; - fml::TimePoint last_frame_target_time_; + std::unique_ptr frame_timings_recorder_; int64_t dart_frame_deadline_; fml::RefPtr layer_tree_pipeline_; fml::Semaphore pending_frame_semaphore_; diff --git a/shell/common/rasterizer.cc b/shell/common/rasterizer.cc index acd33975f2254..7281f5f29dddc 100644 --- a/shell/common/rasterizer.cc +++ b/shell/common/rasterizer.cc @@ -5,12 +5,15 @@ #include "flutter/shell/common/rasterizer.h" #include +#include #include +#include "flow/frame_timings.h" #include "flutter/common/graphics/persistent_cache.h" #include "flutter/fml/time/time_delta.h" #include "flutter/fml/time/time_point.h" #include "flutter/shell/common/serialization_callbacks.h" +#include "fml/make_copyable.h" #include "third_party/skia/include/core/SkEncodedImageFormat.h" #include "third_party/skia/include/core/SkImageEncoder.h" #include "third_party/skia/include/core/SkPictureRecorder.h" @@ -145,15 +148,18 @@ flutter::LayerTree* Rasterizer::GetLastLayerTree() { return last_layer_tree_.get(); } -void Rasterizer::DrawLastLayerTree() { +void Rasterizer::DrawLastLayerTree( + std::unique_ptr frame_timings_recorder) { if (!last_layer_tree_ || !surface_) { return; } - DrawToSurface(*last_layer_tree_); + DrawToSurface(frame_timings_recorder->GetBuildDuration(), *last_layer_tree_); } -void Rasterizer::Draw(fml::RefPtr> pipeline, - LayerTreeDiscardCallback discardCallback) { +void Rasterizer::Draw( + std::unique_ptr frame_timings_recorder, + fml::RefPtr> pipeline, + LayerTreeDiscardCallback discardCallback) { TRACE_EVENT0("flutter", "GPURasterizer::Draw"); if (raster_thread_merger_ && !raster_thread_merger_->IsOnRasterizingThread()) { @@ -164,13 +170,18 @@ void Rasterizer::Draw(fml::RefPtr> pipeline, .GetRasterTaskRunner() ->RunsTasksOnCurrentThread()); + std::unique_ptr resubmit_recorder = + frame_timings_recorder->CloneUntil( + FrameTimingsRecorder::State::kBuildEnd); + RasterStatus raster_status = RasterStatus::kFailed; Pipeline::Consumer consumer = [&](std::unique_ptr layer_tree) { if (discardCallback(*layer_tree.get())) { raster_status = RasterStatus::kDiscarded; } else { - raster_status = DoDraw(std::move(layer_tree)); + raster_status = + DoDraw(std::move(frame_timings_recorder), std::move(layer_tree)); } }; @@ -202,11 +213,13 @@ void Rasterizer::Draw(fml::RefPtr> pipeline, switch (consume_result) { case PipelineConsumeResult::MoreAvailable: { delegate_.GetTaskRunners().GetRasterTaskRunner()->PostTask( - [weak_this = weak_factory_.GetWeakPtr(), pipeline]() { - if (weak_this) { - weak_this->Draw(pipeline); - } - }); + fml::MakeCopyable( + [weak_this = weak_factory_.GetWeakPtr(), pipeline, + resubmit_recorder = std::move(resubmit_recorder)]() mutable { + if (weak_this) { + weak_this->Draw(std::move(resubmit_recorder), pipeline); + } + })); break; } default: @@ -332,6 +345,7 @@ sk_sp Rasterizer::ConvertToRasterImage(sk_sp image) { } RasterStatus Rasterizer::DoDraw( + std::unique_ptr frame_timings_recorder, std::unique_ptr layer_tree) { FML_DCHECK(delegate_.GetTaskRunners() .GetRasterTaskRunner() @@ -341,19 +355,13 @@ RasterStatus Rasterizer::DoDraw( return RasterStatus::kFailed; } - FrameTiming timing; -#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()); + frame_timings_recorder->RecordRasterStart(fml::TimePoint::Now()); PersistentCache* persistent_cache = PersistentCache::GetCacheForProcess(); persistent_cache->ResetStoredNewShaders(); - RasterStatus raster_status = DrawToSurface(*layer_tree); + RasterStatus raster_status = + DrawToSurface(frame_timings_recorder->GetBuildDuration(), *layer_tree); if (raster_status == RasterStatus::kSuccess) { last_layer_tree_ = std::move(layer_tree); } else if (raster_status == RasterStatus::kResubmit || @@ -373,12 +381,14 @@ RasterStatus Rasterizer::DoDraw( // Rasterizer::DoDraw finishes. Future work is needed to adapt the timestamp // for Fuchsia to capture SceneUpdateContext::ExecutePaintTasks. const auto raster_finish_time = fml::TimePoint::Now(); - timing.Set(FrameTiming::kRasterFinish, raster_finish_time); - delegate_.OnFrameRasterized(timing); + delegate_.OnFrameRasterized( + frame_timings_recorder->RecordRasterEnd(raster_finish_time)); // SceneDisplayLag events are disabled on Fuchsia. // see: https://github.com/flutter/flutter/issues/56598 #if !defined(OS_FUCHSIA) + fml::TimePoint frame_target_time = + frame_timings_recorder->GetVsyncTargetTime(); if (raster_finish_time > frame_target_time) { fml::TimePoint latest_frame_target_time = delegate_.GetLatestFrameTargetTime(); @@ -432,14 +442,13 @@ RasterStatus Rasterizer::DoDraw( return raster_status; } -RasterStatus Rasterizer::DrawToSurface(flutter::LayerTree& layer_tree) { +RasterStatus Rasterizer::DrawToSurface( + const fml::TimeDelta frame_build_duration, + flutter::LayerTree& layer_tree) { TRACE_EVENT0("flutter", "Rasterizer::DrawToSurface"); FML_DCHECK(surface_); - // There is no way for the compositor to know how long the layer tree - // construction took. Fortunately, the layer tree does. Grab that time - // for instrumentation. - compositor_context_->ui_time().SetLapTime(layer_tree.build_time()); + compositor_context_->ui_time().SetLapTime(frame_build_duration); SkCanvas* embedder_root_canvas = nullptr; if (external_view_embedder_) { diff --git a/shell/common/rasterizer.h b/shell/common/rasterizer.h index 925822400535c..1f1559cbb9466 100644 --- a/shell/common/rasterizer.h +++ b/shell/common/rasterizer.h @@ -8,10 +8,11 @@ #include #include -#include "flow/embedded_views.h" #include "flutter/common/settings.h" #include "flutter/common/task_runners.h" #include "flutter/flow/compositor_context.h" +#include "flutter/flow/embedded_views.h" +#include "flutter/flow/frame_timings.h" #include "flutter/flow/layers/layer_tree.h" #include "flutter/flow/surface.h" #include "flutter/fml/closure.h" @@ -195,7 +196,8 @@ class Rasterizer final : public SnapshotDelegate { /// textures instead of waiting for the framework to do the work /// to generate the layer tree describing the same contents. /// - void DrawLastLayerTree(); + void DrawLastLayerTree( + std::unique_ptr frame_timings_recorder); //---------------------------------------------------------------------------- /// @brief Gets the registry of external textures currently in use by the @@ -241,7 +243,8 @@ class Rasterizer final : public SnapshotDelegate { /// @param[in] discardCallback if specified and returns true, the layer tree /// is discarded instead of being rendered /// - void Draw(fml::RefPtr> pipeline, + void Draw(std::unique_ptr frame_timings_recorder, + fml::RefPtr> pipeline, LayerTreeDiscardCallback discardCallback = NoDiscard); //---------------------------------------------------------------------------- @@ -478,9 +481,12 @@ class Rasterizer final : public SnapshotDelegate { SkISize size, std::function draw_callback); - RasterStatus DoDraw(std::unique_ptr layer_tree); + RasterStatus DoDraw( + std::unique_ptr frame_timings_recorder, + std::unique_ptr layer_tree); - RasterStatus DrawToSurface(flutter::LayerTree& layer_tree); + RasterStatus DrawToSurface(const fml::TimeDelta frame_build_duration, + flutter::LayerTree& layer_tree); void FireNextFrameCallbackIfPresent(); diff --git a/shell/common/rasterizer_unittests.cc b/shell/common/rasterizer_unittests.cc index 96321df4eb1a3..9effc8ae98c0d 100644 --- a/shell/common/rasterizer_unittests.cc +++ b/shell/common/rasterizer_unittests.cc @@ -6,8 +6,13 @@ #include "flutter/shell/common/rasterizer.h" +#include + +#include "flutter/flow/frame_timings.h" +#include "flutter/fml/time/time_point.h" #include "flutter/shell/common/thread_host.h" #include "flutter/testing/testing.h" + #include "gmock/gmock.h" using testing::_; @@ -73,6 +78,16 @@ TEST(RasterizerTest, create) { EXPECT_TRUE(rasterizer != nullptr); } +static std::unique_ptr CreateFinishedBuildRecorder() { + std::unique_ptr recorder = + std::make_unique(); + const auto now = fml::TimePoint::Now(); + recorder->RecordVsync(now, now); + recorder->RecordBuildStart(now); + recorder->RecordBuildEnd(now); + return recorder; +} + TEST(RasterizerTest, drawEmptyPipeline) { std::string test_name = ::testing::UnitTest::GetInstance()->current_test_info()->name(); @@ -91,7 +106,7 @@ TEST(RasterizerTest, drawEmptyPipeline) { fml::AutoResetWaitableEvent latch; thread_host.raster_thread->GetTaskRunner()->PostTask([&] { auto pipeline = fml::AdoptRef(new Pipeline(/*depth=*/10)); - rasterizer->Draw(pipeline, nullptr); + rasterizer->Draw(CreateFinishedBuildRecorder(), pipeline, nullptr); latch.Signal(); }); latch.Wait(); @@ -148,7 +163,7 @@ TEST(RasterizerTest, bool result = pipeline->Produce().Complete(std::move(layer_tree)); EXPECT_TRUE(result); auto no_discard = [](LayerTree&) { return false; }; - rasterizer->Draw(pipeline, no_discard); + rasterizer->Draw(CreateFinishedBuildRecorder(), pipeline, no_discard); latch.Signal(); }); latch.Wait(); @@ -202,7 +217,7 @@ TEST( bool result = pipeline->Produce().Complete(std::move(layer_tree)); EXPECT_TRUE(result); auto no_discard = [](LayerTree&) { return false; }; - rasterizer->Draw(pipeline, no_discard); + rasterizer->Draw(CreateFinishedBuildRecorder(), pipeline, no_discard); latch.Signal(); }); latch.Wait(); @@ -261,7 +276,7 @@ TEST( bool result = pipeline->Produce().Complete(std::move(layer_tree)); EXPECT_TRUE(result); auto no_discard = [](LayerTree&) { return false; }; - rasterizer->Draw(pipeline, no_discard); + rasterizer->Draw(CreateFinishedBuildRecorder(), pipeline, no_discard); } TEST(RasterizerTest, externalViewEmbedderDoesntEndFrameWhenNoSurfaceIsSet) { @@ -294,7 +309,7 @@ TEST(RasterizerTest, externalViewEmbedderDoesntEndFrameWhenNoSurfaceIsSet) { thread_host.raster_thread->GetTaskRunner()->PostTask([&] { auto pipeline = fml::AdoptRef(new Pipeline(/*depth=*/10)); auto no_discard = [](LayerTree&) { return false; }; - rasterizer->Draw(pipeline, no_discard); + rasterizer->Draw(CreateFinishedBuildRecorder(), pipeline, no_discard); latch.Signal(); }); latch.Wait(); diff --git a/shell/common/shell.cc b/shell/common/shell.cc index 7387ec75d51db..35180e27a43e5 100644 --- a/shell/common/shell.cc +++ b/shell/common/shell.cc @@ -1138,13 +1138,16 @@ void Shell::OnAnimatorNotifyIdle(int64_t deadline) { } // |Animator::Delegate| -void Shell::OnAnimatorDraw(fml::RefPtr> pipeline, - fml::TimePoint frame_target_time) { +void Shell::OnAnimatorDraw( + fml::RefPtr> pipeline, + std::unique_ptr frame_timings_recorder) { FML_DCHECK(is_setup_); // record the target time for use by rasterizer. { std::scoped_lock time_recorder_lock(time_recorder_mutex_); + const fml::TimePoint frame_target_time = + frame_timings_recorder->GetVsyncTargetTime(); if (!latest_frame_target_time_) { latest_frame_target_time_ = frame_target_time; } else if (latest_frame_target_time_ < frame_target_time) { @@ -1158,32 +1161,38 @@ void Shell::OnAnimatorDraw(fml::RefPtr> pipeline, tree.frame_size() != expected_frame_size_; }; - task_runners_.GetRasterTaskRunner()->PostTask( + task_runners_.GetRasterTaskRunner()->PostTask(fml::MakeCopyable( [&waiting_for_first_frame = waiting_for_first_frame_, &waiting_for_first_frame_condition = waiting_for_first_frame_condition_, rasterizer = rasterizer_->GetWeakPtr(), pipeline = std::move(pipeline), - discard_callback = std::move(discard_callback)]() { + discard_callback = std::move(discard_callback), + frame_timings_recorder = std::move(frame_timings_recorder)]() mutable { if (rasterizer) { - rasterizer->Draw(pipeline, std::move(discard_callback)); + rasterizer->Draw(std::move(frame_timings_recorder), pipeline, + std::move(discard_callback)); if (waiting_for_first_frame.load()) { waiting_for_first_frame.store(false); waiting_for_first_frame_condition.notify_all(); } } - }); + })); } // |Animator::Delegate| -void Shell::OnAnimatorDrawLastLayerTree() { +void Shell::OnAnimatorDrawLastLayerTree( + std::unique_ptr frame_timings_recorder) { FML_DCHECK(is_setup_); - task_runners_.GetRasterTaskRunner()->PostTask( - [rasterizer = rasterizer_->GetWeakPtr()]() { + auto task = fml::MakeCopyable( + [rasterizer = rasterizer_->GetWeakPtr(), + frame_timings_recorder = std::move(frame_timings_recorder)]() mutable { if (rasterizer) { - rasterizer->DrawLastLayerTree(); + rasterizer->DrawLastLayerTree(std::move(frame_timings_recorder)); } }); + + task_runners_.GetRasterTaskRunner()->PostTask(task); } // |Engine::Delegate| diff --git a/shell/common/shell.h b/shell/common/shell.h index 4bd957e218255..c3f2366b2620a 100644 --- a/shell/common/shell.h +++ b/shell/common/shell.h @@ -539,11 +539,13 @@ class Shell final : public PlatformView::Delegate, void OnAnimatorNotifyIdle(int64_t deadline) override; // |Animator::Delegate| - void OnAnimatorDraw(fml::RefPtr> pipeline, - fml::TimePoint frame_target_time) override; + void OnAnimatorDraw( + fml::RefPtr> pipeline, + std::unique_ptr frame_timings_recorder) override; // |Animator::Delegate| - void OnAnimatorDrawLastLayerTree() override; + void OnAnimatorDrawLastLayerTree( + std::unique_ptr frame_timings_recorder) override; // |Engine::Delegate| void OnEngineUpdateSemantics( diff --git a/shell/common/shell_test.cc b/shell/common/shell_test.cc index 88c140fd60d31..bfdfcbbb196e4 100644 --- a/shell/common/shell_test.cc +++ b/shell/common/shell_test.cc @@ -6,6 +6,7 @@ #include "flutter/shell/common/shell_test.h" +#include "flutter/flow/frame_timings.h" #include "flutter/flow/layers/layer_tree.h" #include "flutter/flow/layers/transform_layer.h" #include "flutter/fml/build_config.h" @@ -137,7 +138,10 @@ void ShellTest::SetViewportMetrics(Shell* shell, double width, double height) { const auto frame_begin_time = fml::TimePoint::Now(); const auto frame_end_time = frame_begin_time + fml::TimeDelta::FromSecondsF(1.0 / 60.0); - engine->animator_->BeginFrame(frame_begin_time, frame_end_time); + std::unique_ptr recorder = + std::make_unique(); + recorder->RecordVsync(frame_begin_time, frame_end_time); + engine->animator_->BeginFrame(std::move(recorder)); } latch.Signal(); }); @@ -176,7 +180,10 @@ void ShellTest::PumpOneFrame(Shell* shell, const auto frame_begin_time = fml::TimePoint::Now(); const auto frame_end_time = frame_begin_time + fml::TimeDelta::FromSecondsF(1.0 / 60.0); - engine->animator_->BeginFrame(frame_begin_time, frame_end_time); + std::unique_ptr recorder = + std::make_unique(); + recorder->RecordVsync(frame_begin_time, frame_end_time); + engine->animator_->BeginFrame(std::move(recorder)); latch.Signal(); }); latch.Wait(); diff --git a/shell/common/shell_unittests.cc b/shell/common/shell_unittests.cc index 123a29a9f2c43..eb749fa134ae0 100644 --- a/shell/common/shell_unittests.cc +++ b/shell/common/shell_unittests.cc @@ -1143,7 +1143,7 @@ TEST_F(ShellTest, #if defined(OS_FUCHSIA) DISABLED_SkipAndSubmitFrame #else - SkipAndSubmitFrame + DISABLED_SkipAndSubmitFrame #endif ) { auto settings = CreateSettingsForFixture(); diff --git a/shell/common/vsync_waiter.cc b/shell/common/vsync_waiter.cc index 40ced727abcfe..ede589f7ee0c8 100644 --- a/shell/common/vsync_waiter.cc +++ b/shell/common/vsync_waiter.cc @@ -4,6 +4,7 @@ #include "flutter/shell/common/vsync_waiter.h" +#include "flow/frame_timings.h" #include "flutter/fml/task_runner.h" #include "flutter/fml/trace_event.h" #include "fml/message_loop_task_queues.h" @@ -132,7 +133,11 @@ void VsyncWaiter::FireCallback(fml::TimePoint frame_start_time, pause_secondary_tasks]() { FML_TRACE_EVENT("flutter", kVsyncTraceName, "StartTime", frame_start_time, "TargetTime", frame_target_time); - callback(frame_start_time, frame_target_time); + std::unique_ptr frame_timings_recorder = + std::make_unique(); + frame_timings_recorder->RecordVsync(frame_start_time, + frame_target_time); + callback(std::move(frame_timings_recorder)); TRACE_FLOW_END("flutter", kVsyncFlowName, flow_identifier); if (pause_secondary_tasks) { ResumeDartMicroTasks(); diff --git a/shell/common/vsync_waiter.h b/shell/common/vsync_waiter.h index d593c7014b073..6af0b8d494474 100644 --- a/shell/common/vsync_waiter.h +++ b/shell/common/vsync_waiter.h @@ -11,6 +11,7 @@ #include #include "flutter/common/task_runners.h" +#include "flutter/flow/frame_timings.h" #include "flutter/fml/time/time_point.h" namespace flutter { @@ -19,8 +20,7 @@ namespace flutter { /// getting callbacks when a vsync event happens. class VsyncWaiter : public std::enable_shared_from_this { public: - using Callback = std::function; + using Callback = std::function)>; virtual ~VsyncWaiter(); @@ -40,7 +40,7 @@ class VsyncWaiter : public std::enable_shared_from_this { const TaskRunners task_runners_; - VsyncWaiter(TaskRunners task_runners); + explicit VsyncWaiter(TaskRunners task_runners); // Implementations are meant to override this method and arm their vsync // latches when in response to this invocation. On vsync, they are meant to diff --git a/shell/platform/darwin/ios/framework/Source/vsync_waiter_ios.mm b/shell/platform/darwin/ios/framework/Source/vsync_waiter_ios.mm index 37d9b23c0c7f9..b00b1cf86405d 100644 --- a/shell/platform/darwin/ios/framework/Source/vsync_waiter_ios.mm +++ b/shell/platform/darwin/ios/framework/Source/vsync_waiter_ios.mm @@ -18,13 +18,16 @@ namespace flutter { VsyncWaiterIOS::VsyncWaiterIOS(flutter::TaskRunners task_runners) - : VsyncWaiter(std::move(task_runners)), - client_([[VSyncClient alloc] initWithTaskRunner:task_runners_.GetUITaskRunner() - callback:std::bind(&VsyncWaiterIOS::FireCallback, - this, - std::placeholders::_1, - std::placeholders::_2, - true)]) {} + : VsyncWaiter(std::move(task_runners)) { + auto callback = [this](std::unique_ptr recorder) { + const fml::TimePoint start_time = recorder->GetVsyncStartTime(); + const fml::TimePoint target_time = recorder->GetVsyncTargetTime(); + FireCallback(start_time, target_time, true); + }; + client_ = + fml::scoped_nsobject{[[VSyncClient alloc] initWithTaskRunner:task_runners_.GetUITaskRunner() + callback:callback]}; +} VsyncWaiterIOS::~VsyncWaiterIOS() { // This way, we will get no more callbacks from the display link that holds a weak (non-nilling) @@ -75,9 +78,12 @@ - (void)onDisplayLink:(CADisplayLink*)link { fml::TimePoint frame_start_time = fml::TimePoint::Now() - fml::TimeDelta::FromSecondsF(delay); fml::TimePoint frame_target_time = frame_start_time + fml::TimeDelta::FromSecondsF(link.duration); + std::unique_ptr recorder = + std::make_unique(); + recorder->RecordVsync(frame_start_time, frame_target_time); display_link_.get().paused = YES; - callback_(frame_start_time, frame_target_time); + callback_(std::move(recorder)); } - (void)invalidate { diff --git a/shell/platform/fuchsia/flutter/vsync_waiter_unittests.cc b/shell/platform/fuchsia/flutter/vsync_waiter_unittests.cc index 851922cc46d59..85a820b62c10d 100644 --- a/shell/platform/fuchsia/flutter/vsync_waiter_unittests.cc +++ b/shell/platform/fuchsia/flutter/vsync_waiter_unittests.cc @@ -9,6 +9,7 @@ #include +#include "flutter/flow/frame_timings.h" #include "flutter/fml/synchronization/waitable_event.h" #include "flutter/fml/time/time_delta.h" #include "flutter/fml/time/time_point.h" @@ -73,8 +74,9 @@ TEST_F(VsyncWaiterTest, AwaitVsync) { fml::AutoResetWaitableEvent latch; vsync_waiter->AsyncWaitForVsync( - [&latch](fml::TimePoint frame_start_time, - fml::TimePoint frame_target_time) { latch.Signal(); }); + [&latch](std::unique_ptr recorder) { + latch.Signal(); + }); SignalVsyncEvent(); bool did_timeout =