From 020577edbb43f74fe4e942775931f695aef8b819 Mon Sep 17 00:00:00 2001 From: Dan Field Date: Fri, 18 Nov 2022 10:17:53 -0800 Subject: [PATCH] Make NotifyIdle reject close and past deadlines. (flutter/engine#37737) 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. --- .../src/flutter/runtime/runtime_controller.cc | 14 ++++-- .../src/flutter/runtime/runtime_controller.h | 2 +- engine/src/flutter/shell/common/animator.cc | 38 +++++--------- engine/src/flutter/shell/common/animator.h | 5 +- .../shell/common/animator_unittests.cc | 2 +- engine/src/flutter/shell/common/engine.cc | 7 +-- engine/src/flutter/shell/common/engine.h | 2 +- .../flutter/shell/common/engine_unittests.cc | 2 +- engine/src/flutter/shell/common/shell.cc | 2 +- engine/src/flutter/shell/common/shell.h | 2 +- engine/src/flutter/shell/common/shell_test.cc | 2 +- engine/src/flutter/shell/common/shell_test.h | 2 +- .../flutter/shell/common/shell_unittests.cc | 49 ++++++++++++++++++- 13 files changed, 83 insertions(+), 46 deletions(-) diff --git a/engine/src/flutter/runtime/runtime_controller.cc b/engine/src/flutter/runtime/runtime_controller.cc index aaf2796105..9870d5e780 100644 --- a/engine/src/flutter/runtime/runtime_controller.cc +++ b/engine/src/flutter/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/engine/src/flutter/runtime/runtime_controller.h b/engine/src/flutter/runtime/runtime_controller.h index f6c50fbdd8..3f8fa2dcb3 100644 --- a/engine/src/flutter/runtime/runtime_controller.h +++ b/engine/src/flutter/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/engine/src/flutter/shell/common/animator.cc b/engine/src/flutter/shell/common/animator.cc index 6468f0f45f..b396b0a4e2 100644 --- a/engine/src/flutter/shell/common/animator.cc +++ b/engine/src/flutter/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/engine/src/flutter/shell/common/animator.h b/engine/src/flutter/shell/common/animator.h index 116682d2d7..79373b5f0f 100644 --- a/engine/src/flutter/shell/common/animator.h +++ b/engine/src/flutter/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/engine/src/flutter/shell/common/animator_unittests.cc b/engine/src/flutter/shell/common/animator_unittests.cc index 0a68325e89..05c728c57a 100644 --- a/engine/src/flutter/shell/common/animator_unittests.cc +++ b/engine/src/flutter/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/engine/src/flutter/shell/common/engine.cc b/engine/src/flutter/shell/common/engine.cc index 85db9043ee..7d2a63d57c 100644 --- a/engine/src/flutter/shell/common/engine.cc +++ b/engine/src/flutter/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/engine/src/flutter/shell/common/engine.h b/engine/src/flutter/shell/common/engine.h index 82e041e6ff..70402c24a7 100644 --- a/engine/src/flutter/shell/common/engine.h +++ b/engine/src/flutter/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/engine/src/flutter/shell/common/engine_unittests.cc b/engine/src/flutter/shell/common/engine_unittests.cc index a5f8e4f4c6..c2c9a84f63 100644 --- a/engine/src/flutter/shell/common/engine_unittests.cc +++ b/engine/src/flutter/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/engine/src/flutter/shell/common/shell.cc b/engine/src/flutter/shell/common/shell.cc index a8bad9ea96..693d36a143 100644 --- a/engine/src/flutter/shell/common/shell.cc +++ b/engine/src/flutter/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/engine/src/flutter/shell/common/shell.h b/engine/src/flutter/shell/common/shell.h index 79581ce480..71ee082c0a 100644 --- a/engine/src/flutter/shell/common/shell.h +++ b/engine/src/flutter/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/engine/src/flutter/shell/common/shell_test.cc b/engine/src/flutter/shell/common/shell_test.cc index 078455d3f8..a799e6bcb4 100644 --- a/engine/src/flutter/shell/common/shell_test.cc +++ b/engine/src/flutter/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/engine/src/flutter/shell/common/shell_test.h b/engine/src/flutter/shell/common/shell_test.h index 5dad608088..b9e95cc590 100644 --- a/engine/src/flutter/shell/common/shell_test.h +++ b/engine/src/flutter/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/engine/src/flutter/shell/common/shell_unittests.cc b/engine/src/flutter/shell/common/shell_unittests.cc index d5a0158c7e..d850eab688 100644 --- a/engine/src/flutter/shell/common/shell_unittests.cc +++ b/engine/src/flutter/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(); }));