From f175f414d4eac48df8c7b2d1fb7668ea79e2b64c Mon Sep 17 00:00:00 2001 From: Dan Field Date: Thu, 17 Nov 2022 17:28:55 -0800 Subject: [PATCH] Make NotifyIdle reject close and past deadlines. This patch also eliminates some extraneous tracing that is happening every frame. It is possible to get the same trace calls by enabling the API stream if needed. Also refactors the NotifyIdle callsites to just always work in TimeDeltas rather than converting back and forth between them and TimePoints, which I think reads more clearly. --- runtime/runtime_controller.cc | 14 +++++++-- runtime/runtime_controller.h | 2 +- shell/common/animator.cc | 38 ++++++++--------------- shell/common/animator.h | 5 ++- shell/common/animator_unittests.cc | 2 +- shell/common/engine.cc | 7 +---- shell/common/engine.h | 2 +- shell/common/engine_unittests.cc | 2 +- shell/common/shell.cc | 2 +- shell/common/shell.h | 2 +- shell/common/shell_test.cc | 2 +- shell/common/shell_test.h | 2 +- shell/common/shell_unittests.cc | 49 +++++++++++++++++++++++++++++- 13 files changed, 83 insertions(+), 46 deletions(-) diff --git a/runtime/runtime_controller.cc b/runtime/runtime_controller.cc index aaf279610562c..9870d5e7804ca 100644 --- a/runtime/runtime_controller.cc +++ b/runtime/runtime_controller.cc @@ -211,7 +211,15 @@ bool RuntimeController::ReportTimings(std::vector timings) { return false; } -bool RuntimeController::NotifyIdle(fml::TimePoint deadline) { +bool RuntimeController::NotifyIdle(fml::TimeDelta deadline) { + if (deadline - fml::TimeDelta::FromMicroseconds(Dart_TimelineGetMicros()) < + fml::TimeDelta::FromMilliseconds(1)) { + // There's less than 1ms left before the deadline. Upstream callers do not + // check to see if the deadline is in the past, and work after this point + // will be in vain. + return false; + } + std::shared_ptr root_isolate = root_isolate_.lock(); if (!root_isolate) { return false; @@ -225,12 +233,12 @@ bool RuntimeController::NotifyIdle(fml::TimePoint deadline) { return false; } - Dart_NotifyIdle(deadline.ToEpochDelta().ToMicroseconds()); + Dart_NotifyIdle(deadline.ToMicroseconds()); // Idle notifications being in isolate scope are part of the contract. if (idle_notification_callback_) { TRACE_EVENT0("flutter", "EmbedderIdleNotification"); - idle_notification_callback_(deadline.ToEpochDelta().ToMicroseconds()); + idle_notification_callback_(deadline.ToMicroseconds()); } return true; } diff --git a/runtime/runtime_controller.h b/runtime/runtime_controller.h index f6c50fbdd8c80..3f8fa2dcb3ab4 100644 --- a/runtime/runtime_controller.h +++ b/runtime/runtime_controller.h @@ -358,7 +358,7 @@ class RuntimeController : public PlatformConfigurationClient { /// /// @return If the idle notification was forwarded to the running isolate. /// - virtual bool NotifyIdle(fml::TimePoint deadline); + virtual bool NotifyIdle(fml::TimeDelta deadline); //---------------------------------------------------------------------------- /// @brief Notify the Dart VM that the attached flutter view has been diff --git a/shell/common/animator.cc b/shell/common/animator.cc index 6468f0f45f627..b396b0a4e2da0 100644 --- a/shell/common/animator.cc +++ b/shell/common/animator.cc @@ -57,12 +57,6 @@ void Animator::EnqueueTraceFlowId(uint64_t trace_flow_id) { }); } -static fml::TimePoint FxlToDartOrEarlier(fml::TimePoint time) { - auto dart_now = fml::TimeDelta::FromMicroseconds(Dart_TimelineGetMicros()); - fml::TimePoint fxl_now = fml::TimePoint::Now(); - return fml::TimePoint::FromEpochDelta(time - fxl_now + dart_now); -} - void Animator::BeginFrame( std::unique_ptr frame_timings_recorder) { TRACE_EVENT_ASYNC_END0("flutter", "Frame Request Pending", @@ -81,7 +75,6 @@ void Animator::BeginFrame( } frame_scheduled_ = false; - notify_idle_task_id_++; regenerate_layer_tree_ = false; pending_frame_semaphore_.Signal(); @@ -106,34 +99,29 @@ void Animator::BeginFrame( FML_DCHECK(producer_continuation_); const fml::TimePoint frame_target_time = frame_timings_recorder_->GetVsyncTargetTime(); - dart_frame_deadline_ = FxlToDartOrEarlier(frame_target_time); + dart_frame_deadline_ = frame_target_time.ToEpochDelta(); uint64_t frame_number = frame_timings_recorder_->GetFrameNumber(); delegate_.OnAnimatorBeginFrame(frame_target_time, frame_number); if (!frame_scheduled_ && has_rendered_) { - // Under certain workloads (such as our parent view resizing us, which is - // communicated to us by repeat viewport metrics events), we won't - // actually have a frame scheduled yet, despite the fact that we *will* be - // producing a frame next vsync (it will be scheduled once we receive the - // viewport event). Because of this, we hold off on calling - // |OnAnimatorNotifyIdle| for a little bit, as that could cause garbage - // collection to trigger at a highly undesirable time. + // Wait a tad more than 3 60hz frames before reporting a big idle period. + // This is a heuristic that is meant to avoid giving false positives to the + // VM when we are about to schedule a frame in the next vsync, the idea + // being that if there have been three vsyncs with no frames it's a good + // time to start doing GC work. task_runners_.GetUITaskRunner()->PostDelayedTask( - [self = weak_factory_.GetWeakPtr(), - notify_idle_task_id = notify_idle_task_id_]() { + [self = weak_factory_.GetWeakPtr()]() { if (!self) { return; } - // If our (this task's) task id is the same as the current one - // (meaning there were no follow up frames to the |BeginFrame| call - // that posted this task) and no frame is currently scheduled, then - // assume that we are idle, and notify the engine of this. - if (notify_idle_task_id == self->notify_idle_task_id_ && - !self->frame_scheduled_) { + auto now = fml::TimeDelta::FromMicroseconds(Dart_TimelineGetMicros()); + // If there's a frame scheduled, bail. + // If there's no frame scheduled, but we're not yet past the last + // vsync deadline, bail. + if (!self->frame_scheduled_ && now > self->dart_frame_deadline_) { TRACE_EVENT0("flutter", "BeginFrame idle callback"); self->delegate_.OnAnimatorNotifyIdle( - FxlToDartOrEarlier(fml::TimePoint::Now() + - fml::TimeDelta::FromMicroseconds(100000))); + now + fml::TimeDelta::FromMilliseconds(100)); } }, kNotifyIdleTaskWaitTime); diff --git a/shell/common/animator.h b/shell/common/animator.h index 116682d2d76ee..79373b5f0f246 100644 --- a/shell/common/animator.h +++ b/shell/common/animator.h @@ -34,7 +34,7 @@ class Animator final { virtual void OnAnimatorBeginFrame(fml::TimePoint frame_target_time, uint64_t frame_number) = 0; - virtual void OnAnimatorNotifyIdle(fml::TimePoint deadline) = 0; + virtual void OnAnimatorNotifyIdle(fml::TimeDelta deadline) = 0; virtual void OnAnimatorUpdateLatestFrameTargetTime( fml::TimePoint frame_target_time) = 0; @@ -100,13 +100,12 @@ class Animator final { std::unique_ptr frame_timings_recorder_; uint64_t frame_request_number_ = 1; - fml::TimePoint dart_frame_deadline_; + fml::TimeDelta dart_frame_deadline_; std::shared_ptr layer_tree_pipeline_; fml::Semaphore pending_frame_semaphore_; LayerTreePipeline::ProducerContinuation producer_continuation_; bool regenerate_layer_tree_ = false; bool frame_scheduled_ = false; - int notify_idle_task_id_ = 0; SkISize last_layer_tree_size_ = {0, 0}; std::deque trace_flow_ids_; bool has_rendered_ = false; diff --git a/shell/common/animator_unittests.cc b/shell/common/animator_unittests.cc index 0a68325e89f1b..05c728c57ae16 100644 --- a/shell/common/animator_unittests.cc +++ b/shell/common/animator_unittests.cc @@ -28,7 +28,7 @@ class FakeAnimatorDelegate : public Animator::Delegate { MOCK_METHOD2(OnAnimatorBeginFrame, void(fml::TimePoint frame_target_time, uint64_t frame_number)); - void OnAnimatorNotifyIdle(fml::TimePoint deadline) override { + void OnAnimatorNotifyIdle(fml::TimeDelta deadline) override { notify_idle_called_ = true; } diff --git a/shell/common/engine.cc b/shell/common/engine.cc index 85db9043eeff7..7d2a63d57cad2 100644 --- a/shell/common/engine.cc +++ b/shell/common/engine.cc @@ -254,15 +254,10 @@ void Engine::BeginFrame(fml::TimePoint frame_time, uint64_t frame_number) { } void Engine::ReportTimings(std::vector timings) { - TRACE_EVENT0("flutter", "Engine::ReportTimings"); runtime_controller_->ReportTimings(std::move(timings)); } -void Engine::NotifyIdle(fml::TimePoint deadline) { - auto trace_event = std::to_string(deadline.ToEpochDelta().ToMicroseconds() - - Dart_TimelineGetMicros()); - TRACE_EVENT1("flutter", "Engine::NotifyIdle", "deadline_now_delta", - trace_event.c_str()); +void Engine::NotifyIdle(fml::TimeDelta deadline) { runtime_controller_->NotifyIdle(deadline); } diff --git a/shell/common/engine.h b/shell/common/engine.h index 82e041e6ff2d1..70402c24a7876 100644 --- a/shell/common/engine.h +++ b/shell/common/engine.h @@ -552,7 +552,7 @@ class Engine final : public RuntimeDelegate, PointerDataDispatcher::Delegate { /// corresponding sweep can be performed within the /// deadline. /// - void NotifyIdle(fml::TimePoint deadline); + void NotifyIdle(fml::TimeDelta deadline); //---------------------------------------------------------------------------- /// @brief Notifies the engine that the attached flutter view has been diff --git a/shell/common/engine_unittests.cc b/shell/common/engine_unittests.cc index a5f8e4f4c6353..c2c9a84f634da 100644 --- a/shell/common/engine_unittests.cc +++ b/shell/common/engine_unittests.cc @@ -77,7 +77,7 @@ class MockRuntimeController : public RuntimeController { MOCK_METHOD3(LoadDartDeferredLibraryError, void(intptr_t, const std::string, bool)); MOCK_CONST_METHOD0(GetDartVM, DartVM*()); - MOCK_METHOD1(NotifyIdle, bool(fml::TimePoint)); + MOCK_METHOD1(NotifyIdle, bool(fml::TimeDelta)); }; std::unique_ptr MakePlatformMessage( diff --git a/shell/common/shell.cc b/shell/common/shell.cc index a8bad9ea960b4..693d36a143366 100644 --- a/shell/common/shell.cc +++ b/shell/common/shell.cc @@ -1133,7 +1133,7 @@ void Shell::OnAnimatorBeginFrame(fml::TimePoint frame_target_time, } // |Animator::Delegate| -void Shell::OnAnimatorNotifyIdle(fml::TimePoint deadline) { +void Shell::OnAnimatorNotifyIdle(fml::TimeDelta deadline) { FML_DCHECK(is_setup_); FML_DCHECK(task_runners_.GetUITaskRunner()->RunsTasksOnCurrentThread()); diff --git a/shell/common/shell.h b/shell/common/shell.h index 79581ce480762..71ee082c0a4ac 100644 --- a/shell/common/shell.h +++ b/shell/common/shell.h @@ -591,7 +591,7 @@ class Shell final : public PlatformView::Delegate, uint64_t frame_number) override; // |Animator::Delegate| - void OnAnimatorNotifyIdle(fml::TimePoint deadline) override; + void OnAnimatorNotifyIdle(fml::TimeDelta deadline) override; // |Animator::Delegate| void OnAnimatorUpdateLatestFrameTargetTime( diff --git a/shell/common/shell_test.cc b/shell/common/shell_test.cc index 078455d3f8e5b..a799e6bcb4811 100644 --- a/shell/common/shell_test.cc +++ b/shell/common/shell_test.cc @@ -152,7 +152,7 @@ void ShellTest::SetViewportMetrics(Shell* shell, double width, double height) { latch.Wait(); } -void ShellTest::NotifyIdle(Shell* shell, fml::TimePoint deadline) { +void ShellTest::NotifyIdle(Shell* shell, fml::TimeDelta deadline) { fml::AutoResetWaitableEvent latch; shell->GetTaskRunners().GetUITaskRunner()->PostTask( [&latch, engine = shell->weak_engine_, deadline]() { diff --git a/shell/common/shell_test.h b/shell/common/shell_test.h index 5dad608088c2c..b9e95cc590e8b 100644 --- a/shell/common/shell_test.h +++ b/shell/common/shell_test.h @@ -74,7 +74,7 @@ class ShellTest : public FixtureTest { std::function root)>; static void SetViewportMetrics(Shell* shell, double width, double height); - static void NotifyIdle(Shell* shell, fml::TimePoint deadline); + static void NotifyIdle(Shell* shell, fml::TimeDelta deadline); static void PumpOneFrame(Shell* shell, double width = 1, diff --git a/shell/common/shell_unittests.cc b/shell/common/shell_unittests.cc index d5a0158c7ef25..d850eab688012 100644 --- a/shell/common/shell_unittests.cc +++ b/shell/common/shell_unittests.cc @@ -3891,6 +3891,51 @@ TEST_F(ShellTest, PluginUtilitiesCallbackHandleErrorHandling) { DestroyShell(std::move(shell)); } +TEST_F(ShellTest, NotifyIdleRejectsPastAndNearFuture) { + ASSERT_FALSE(DartVMRef::IsInstanceRunning()); + Settings settings = CreateSettingsForFixture(); + ThreadHost thread_host("io.flutter.test." + GetCurrentTestName() + ".", + ThreadHost::Type::Platform | ThreadHost::UI | + ThreadHost::IO | ThreadHost::RASTER); + auto platform_task_runner = thread_host.platform_thread->GetTaskRunner(); + TaskRunners task_runners("test", thread_host.platform_thread->GetTaskRunner(), + thread_host.raster_thread->GetTaskRunner(), + thread_host.ui_thread->GetTaskRunner(), + thread_host.io_thread->GetTaskRunner()); + auto shell = CreateShell(settings, task_runners); + ASSERT_TRUE(DartVMRef::IsInstanceRunning()); + ASSERT_TRUE(ValidateShell(shell.get())); + + fml::AutoResetWaitableEvent latch; + + auto configuration = RunConfiguration::InferFromSettings(settings); + configuration.SetEntrypoint("emptyMain"); + RunEngine(shell.get(), std::move(configuration)); + + fml::TaskRunner::RunNowOrPostTask( + task_runners.GetUITaskRunner(), [&latch, &shell]() { + auto runtime_controller = const_cast( + shell->GetEngine()->GetRuntimeController()); + + auto now = fml::TimeDelta::FromMicroseconds(Dart_TimelineGetMicros()); + + EXPECT_FALSE(runtime_controller->NotifyIdle( + now - fml::TimeDelta::FromMilliseconds(10))); + EXPECT_FALSE(runtime_controller->NotifyIdle(now)); + EXPECT_FALSE(runtime_controller->NotifyIdle( + now + fml::TimeDelta::FromNanoseconds(100))); + + EXPECT_TRUE(runtime_controller->NotifyIdle( + now + fml::TimeDelta::FromMilliseconds(100))); + latch.Signal(); + }); + + latch.Wait(); + + DestroyShell(std::move(shell), task_runners); + ASSERT_FALSE(DartVMRef::IsInstanceRunning()); +} + TEST_F(ShellTest, NotifyIdleNotCalledInLatencyMode) { ASSERT_FALSE(DartVMRef::IsInstanceRunning()); Settings settings = CreateSettingsForFixture(); @@ -3917,7 +3962,9 @@ TEST_F(ShellTest, NotifyIdleNotCalledInLatencyMode) { tonic::DartConverter::FromArguments(args, 0, exception); auto runtime_controller = const_cast( shell->GetEngine()->GetRuntimeController()); - bool success = runtime_controller->NotifyIdle(fml::TimePoint::Now()); + bool success = + runtime_controller->NotifyIdle(fml::TimeDelta::FromMicroseconds( + Dart_TimelineGetMicros() + 100000)); EXPECT_EQ(success, !is_in_latency_mode); latch.CountDown(); }));