Simplify the fallback waiter and add traces for vsync scheduling over…

…head. (flutter#8185)

fml/trace_event.cc

@@ -6,6 +6,7 @@
 
 #include <algorithm>
 #include <atomic>
+#include <utility>
 
 #include "flutter/fml/build_config.h"
 #include "flutter/fml/logging.h"
@@ -124,6 +125,34 @@ void TraceEventEnd(TraceArg name) {
   );
 }
 
+void TraceEventAsyncComplete(TraceArg category_group,
+                             TraceArg name,
+                             TimePoint begin,
+                             TimePoint end) {
+  auto identifier = TraceNonce();
+
+  if (begin > end) {
+    std::swap(begin, end);
+  }
+
+  Dart_TimelineEvent(DCHECK_LITERAL(name),                   // label
+                     begin.ToEpochDelta().ToMicroseconds(),  // timestamp0
+                     identifier,                       // timestamp1_or_async_id
+                     Dart_Timeline_Event_Async_Begin,  // event type
+                     0,                                // argument_count
+                     nullptr,                          // argument_names
+                     nullptr                           // argument_values
+  );
+  Dart_TimelineEvent(DCHECK_LITERAL(name),                 // label
+                     end.ToEpochDelta().ToMicroseconds(),  // timestamp0
+                     identifier,                     // timestamp1_or_async_id
+                     Dart_Timeline_Event_Async_End,  // event type
+                     0,                              // argument_count
+                     nullptr,                        // argument_names
+                     nullptr                         // argument_values
+  );
+}
+
 void TraceEventAsyncBegin0(TraceArg category_group,
                            TraceArg name,
                            TraceIDArg id) {

fml/trace_event.h

@@ -193,6 +193,11 @@ void TraceEvent2(TraceArg category_group,
 
 void TraceEventEnd(TraceArg name);
 
+void TraceEventAsyncComplete(TraceArg category_group,
+                             TraceArg name,
+                             TimePoint begin,
+                             TimePoint end);
+
 void TraceEventAsyncBegin0(TraceArg category_group,
                            TraceArg name,
                            TraceIDArg id);

shell/common/vsync_waiter.cc

@@ -28,9 +28,23 @@ VsyncWaiter::VsyncWaiter(blink::TaskRunners task_runners)
 
 VsyncWaiter::~VsyncWaiter() = default;
 
+// Public method invoked by the animator.
 void VsyncWaiter::AsyncWaitForVsync(Callback callback) {
+  if (!callback) {
+    return;
+  }
+
+  TRACE_EVENT0("flutter", "AsyncWaitForVsync");
+
   {
     std::lock_guard<std::mutex> lock(callback_mutex_);
+    if (callback_) {
+      // The animator may request a frame more than once within a frame
+      // interval. Multiple calls to request frame must result in a single
+      // callback per frame interval.
+      TRACE_EVENT_INSTANT0("flutter", "MultipleCallsToVsyncInFrameInterval");
+      return;
+    }
     callback_ = std::move(callback);
   }
   AwaitVSync();
@@ -46,6 +60,10 @@ void VsyncWaiter::FireCallback(fml::TimePoint frame_start_time,
   }
 
   if (!callback) {
+    // This means that the vsync waiter implementation fired a callback for a
+    // request we did not make. This is a paranoid check but we still want to
+    // make sure we catch misbehaving vsync implementations.
+    TRACE_EVENT_INSTANT0("flutter", "MismatchedFrameCallback");
     return;
   }
 
@@ -56,14 +74,18 @@ void VsyncWaiter::FireCallback(fml::TimePoint frame_start_time,
   // While all our message loops insert a base trace trace
   // (MessageLoop::RunExpiredTasks), embedders may not.
   TRACE_EVENT0("flutter", "VsyncFireCallback");
+
   TRACE_FLOW_BEGIN("flutter", kVsyncFlowName, flow_identifier);
 
   task_runners_.GetUITaskRunner()->PostTaskForTime(
       [callback, flow_identifier, frame_start_time, frame_target_time]() {
         FML_TRACE_EVENT("flutter", kVsyncTraceName, "StartTime",
                         frame_start_time, "TargetTime", frame_target_time);
-        TRACE_FLOW_END("flutter", kVsyncFlowName, flow_identifier);
+        fml::tracing::TraceEventAsyncComplete(
+            "flutter", "VsyncSchedulingOverhead", fml::TimePoint::Now(),
+            frame_start_time);
         callback(frame_start_time, frame_target_time);
+        TRACE_FLOW_END("flutter", kVsyncFlowName, flow_identifier);
       },
       frame_start_time);
 }

shell/common/vsync_waiter.h

@@ -10,6 +10,7 @@
 #include <mutex>
 
 #include "flutter/common/task_runners.h"
+#include "flutter/fml/synchronization/thread_annotations.h"
 #include "flutter/fml/time/time_point.h"
 
 namespace shell {
@@ -50,7 +51,7 @@ class VsyncWaiter : public std::enable_shared_from_this<VsyncWaiter> {
 
  private:
   std::mutex callback_mutex_;
-  Callback callback_;
+  Callback callback_ FML_GUARDED_BY(callback_mutex_);
 
   FML_DISALLOW_COPY_AND_ASSIGN(VsyncWaiter);
 };

shell/common/vsync_waiter_fallback.cc

@@ -9,9 +9,9 @@
 namespace shell {
 namespace {
 
-fml::TimePoint SnapToNextTick(fml::TimePoint value,
-                              fml::TimePoint tick_phase,
-                              fml::TimeDelta tick_interval) {
+static fml::TimePoint SnapToNextTick(fml::TimePoint value,
+                                     fml::TimePoint tick_phase,
+                                     fml::TimeDelta tick_interval) {
   fml::TimeDelta offset = (tick_phase - value) % tick_interval;
   if (offset != fml::TimeDelta::Zero())
     offset = offset + tick_interval;
@@ -21,27 +21,19 @@ fml::TimePoint SnapToNextTick(fml::TimePoint value,
 }  // namespace
 
 VsyncWaiterFallback::VsyncWaiterFallback(blink::TaskRunners task_runners)
-    : VsyncWaiter(std::move(task_runners)),
-      phase_(fml::TimePoint::Now()),
-      weak_factory_(this) {}
+    : VsyncWaiter(std::move(task_runners)), phase_(fml::TimePoint::Now()) {}
 
 VsyncWaiterFallback::~VsyncWaiterFallback() = default;
 
-constexpr fml::TimeDelta interval = fml::TimeDelta::FromSecondsF(1.0 / 60.0);
-
 // |shell::VsyncWaiter|
 void VsyncWaiterFallback::AwaitVSync() {
-  fml::TimePoint now = fml::TimePoint::Now();
-  fml::TimePoint next = SnapToNextTick(now, phase_, interval);
-
-  task_runners_.GetUITaskRunner()->PostDelayedTask(
-      [self = weak_factory_.GetWeakPtr()] {
-        if (self) {
-          const auto frame_time = fml::TimePoint::Now();
-          self->FireCallback(frame_time, frame_time + interval);
-        }
-      },
-      next - now);
+  constexpr fml::TimeDelta kSingleFrameInterval =
+      fml::TimeDelta::FromSecondsF(1.0 / 60.0);
+
+  auto next =
+      SnapToNextTick(fml::TimePoint::Now(), phase_, kSingleFrameInterval);
+
+  FireCallback(next, next + kSingleFrameInterval);
 }
 
 }  // namespace shell

shell/common/vsync_waiter_fallback.h

@@ -20,7 +20,6 @@ class VsyncWaiterFallback final : public VsyncWaiter {
 
  private:
   fml::TimePoint phase_;
-  fml::WeakPtrFactory<VsyncWaiterFallback> weak_factory_;
 
   // |shell::VsyncWaiter|
   void AwaitVSync() override;