Add frame and target time metadata to vsync events and connect platform vsync events using flows. (flutter/engine#8172)

This will allow us to easily visualize the time the platform informed the engine of a vsync event, its arguments, and when the engine began its UI thread workload using this information.

engine/src/flutter/fml/trace_event.cc

@@ -5,6 +5,7 @@
 #include "flutter/fml/trace_event.h"
 
 #include <algorithm>
+#include <atomic>
 
 #include "flutter/fml/build_config.h"
 #include "flutter/fml/logging.h"
@@ -31,6 +32,11 @@
 namespace fml {
 namespace tracing {
 
+size_t TraceNonce() {
+  static std::atomic_size_t gLastItem;
+  return ++gLastItem;
+}
+
 void TraceTimelineEvent(TraceArg category_group,
                         TraceArg name,
                         TraceIDArg identifier,

engine/src/flutter/fml/trace_event.h

@@ -30,6 +30,7 @@
 #include <vector>
 
 #include "flutter/fml/macros.h"
+#include "flutter/fml/time/time_point.h"
 #include "third_party/dart/runtime/include/dart_tools_api.h"
 
 #if !defined(OS_FUCHSIA)
@@ -50,6 +51,10 @@
   ::fml::tracing::TraceCounter((category_group), (name), (counter_id), (arg1), \
                                __VA_ARGS__);
 
+#define FML_TRACE_EVENT(category_group, name, ...)                   \
+  ::fml::tracing::TraceEvent((category_group), (name), __VA_ARGS__); \
+  __FML__AUTO_TRACE_END(name)
+
 #define TRACE_EVENT0(category_group, name)           \
   ::fml::tracing::TraceEvent0(category_group, name); \
   __FML__AUTO_TRACE_END(name)
@@ -116,6 +121,10 @@ inline std::string TraceToString(std::string string) {
   return string;
 }
 
+inline std::string TraceToString(TimePoint point) {
+  return std::to_string(point.ToEpochDelta().ToNanoseconds());
+}
+
 template <typename T, typename = std::enable_if_t<std::is_arithmetic<T>::value>>
 std::string TraceToString(T string) {
   return std::to_string(string);
@@ -149,6 +158,8 @@ SplitArguments(Key key, Value value, Args... args) {
   return std::make_pair(std::move(keys), std::move(values));
 }
 
+size_t TraceNonce();
+
 template <typename... Args>
 void TraceCounter(TraceArg category,
                   TraceArg name,
@@ -159,6 +170,13 @@ void TraceCounter(TraceArg category,
                      split.first, split.second);
 }
 
+template <typename... Args>
+void TraceEvent(TraceArg category, TraceArg name, Args... args) {
+  auto split = SplitArguments(args...);
+  TraceTimelineEvent(category, name, 0, Dart_Timeline_Event_Begin, split.first,
+                     split.second);
+}
+
 void TraceEvent0(TraceArg category_group, TraceArg name);
 
 void TraceEvent1(TraceArg category_group,

engine/src/flutter/shell/common/vsync_waiter.cc

@@ -9,6 +9,20 @@
 
 namespace shell {
 
+#if defined(OS_FUCHSIA)
+// In general, traces on Fuchsia are recorded across the whole system.
+// Because of this, emitting a "VSYNC" event per flutter process is
+// undesirable, as the events will collide with each other.  We
+// instead let another area of the system emit them.
+static constexpr const char* kVsyncTraceName = "vsync callback";
+#else   // defined(OS_FUCHSIA)
+// Note: The tag name must be "VSYNC" (it is special) so that the
+// "Highlight Vsync" checkbox in the timeline can be enabled.
+static constexpr const char* kVsyncTraceName = "VSYNC";
+#endif  // defined(OS_FUCHSIA)
+
+static constexpr const char* kVsyncFlowName = "VsyncFlow";
+
 VsyncWaiter::VsyncWaiter(blink::TaskRunners task_runners)
     : task_runners_(std::move(task_runners)) {}
 
@@ -35,19 +49,20 @@ void VsyncWaiter::FireCallback(fml::TimePoint frame_start_time,
     return;
   }
 
+  auto flow_identifier = fml::tracing::TraceNonce();
+
+  // The base trace ensures that flows have a root to begin from if one does not
+  // exist. The trace viewer will ignore traces that have no base event trace.
+  // 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, frame_start_time, frame_target_time]() {
-#if defined(OS_FUCHSIA)
-        // In general, traces on Fuchsia are recorded across the whole system.
-        // Because of this, emitting a "VSYNC" event per flutter process is
-        // undesirable, as the events will collide with each other.  We
-        // instead let another area of the system emit them.
-        TRACE_EVENT0("flutter", "vsync callback");
-#else
-        // Note: The tag name must be "VSYNC" (it is special) so that the
-        // "Highlight Vsync" checkbox in the timeline can be enabled.
-        TRACE_EVENT0("flutter", "VSYNC");
-#endif
+      [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);
         callback(frame_start_time, frame_target_time);
       },
       frame_start_time);

engine/src/flutter/shell/platform/embedder/embedder.cc

@@ -888,6 +888,8 @@ FlutterEngineResult FlutterEngineOnVsync(FlutterEngine engine,
     return LOG_EMBEDDER_ERROR(kInvalidArguments);
   }
 
+  TRACE_EVENT0("flutter", "FlutterEngineOnVsync");
+
   auto start_time = fml::TimePoint::FromEpochDelta(
       fml::TimeDelta::FromNanoseconds(frame_start_time_nanos));
 

engine/src/flutter/shell/platform/embedder/embedder.h

@@ -664,6 +664,8 @@ FlutterEngineResult FlutterEngineDispatchSemanticsAction(
 // garbage collection in periods in which the various threads are most likely to
 // be idle. For example, for a 60Hz display, embedders should add 16.6 * 1e6 to
 // the frame time field. The system monotonic clock is used as the timebase.
+//
+// That frame timepoints are in nanoseconds.
 FLUTTER_EXPORT
 FlutterEngineResult FlutterEngineOnVsync(FlutterEngine engine,
                                          intptr_t baton,