[VM/Timeline] Support flow events in the Perfetto file recorder

This supports flow events reported through dart:developer, but does not
support ones reported with Dart_TimelineEvent in dart_tools_api.h. That
will have to be supported in a future CL.

TEST=CI, manually verifying that flow arrows appeared on flow events in
the trace viewer for traces recorded with our Perfetto recorder

Change-Id: Ic75a8ce277b436a609c027c2c0d4e94b51031aa7
Reviewed-on: https://dart-review.googlesource.com/c/sdk/+/280740
Reviewed-by: Stephen Adams <sra@google.com>
Reviewed-by: Siva Annamalai <asiva@google.com>
Reviewed-by: Ben Konyi <bkonyi@google.com>
Reviewed-by: Sigmund Cherem <sigmund@google.com>
Reviewed-by: Aske Simon Christensen <askesc@google.com>
Reviewed-by: Leaf Petersen <leafp@google.com>

runtime/lib/timeline.cc

@@ -36,12 +36,13 @@ DEFINE_NATIVE_ENTRY(Timeline_getTraceClock, 0, 0) {
   return Integer::New(OS::GetCurrentMonotonicMicros(), Heap::kNew);
 }
 
-DEFINE_NATIVE_ENTRY(Timeline_reportTaskEvent, 0, 4) {
+DEFINE_NATIVE_ENTRY(Timeline_reportTaskEvent, 0, 5) {
 #if defined(SUPPORT_TIMELINE)
   GET_NON_NULL_NATIVE_ARGUMENT(Integer, id, arguments->NativeArgAt(0));
-  GET_NON_NULL_NATIVE_ARGUMENT(Smi, type, arguments->NativeArgAt(1));
-  GET_NON_NULL_NATIVE_ARGUMENT(String, name, arguments->NativeArgAt(2));
-  GET_NON_NULL_NATIVE_ARGUMENT(String, args, arguments->NativeArgAt(3));
+  GET_NON_NULL_NATIVE_ARGUMENT(Integer, flow_id, arguments->NativeArgAt(1));
+  GET_NON_NULL_NATIVE_ARGUMENT(Smi, type, arguments->NativeArgAt(2));
+  GET_NON_NULL_NATIVE_ARGUMENT(String, name, arguments->NativeArgAt(3));
+  GET_NON_NULL_NATIVE_ARGUMENT(String, args, arguments->NativeArgAt(4));
 
   TimelineEventRecorder* recorder = Timeline::recorder();
   if (recorder == nullptr) {
@@ -55,8 +56,8 @@ DEFINE_NATIVE_ENTRY(Timeline_reportTaskEvent, 0, 4) {
   }
 
   DartTimelineEventHelpers::ReportTaskEvent(
-      event, id.AsInt64Value(), type.Value(), name.ToMallocCString(),
-      args.ToMallocCString());
+      event, id.AsInt64Value(), flow_id.AsInt64Value(), type.Value(),
+      name.ToMallocCString(), args.ToMallocCString());
 #endif  // SUPPORT_TIMELINE
   return Object::null();
 }

runtime/vm/bootstrap_natives.h

@@ -155,7 +155,7 @@ namespace dart {
   V(Timeline_getNextTaskId, 0)                                                 \
   V(Timeline_getTraceClock, 0)                                                 \
   V(Timeline_isDartStreamEnabled, 0)                                           \
-  V(Timeline_reportTaskEvent, 4)                                               \
+  V(Timeline_reportTaskEvent, 5)                                               \
   V(TypedData_Int8Array_new, 2)                                                \
   V(TypedData_Uint8Array_new, 2)                                               \
   V(TypedData_Uint8ClampedArray_new, 2)                                        \

runtime/vm/dart_api_impl.cc

@@ -6441,7 +6441,11 @@ DART_EXPORT void Dart_TimelineEvent(const char* label,
   if (event != nullptr) {
     switch (type) {
       case Dart_Timeline_Event_Begin:
-        event->Begin(label, timestamp1_or_async_id, timestamp0);
+        // TODO(derekx): Dart_TimelineEvent() needs to be updated so that arrows
+        // corresponding to flow events reported by embedders get included in
+        // Perfetto traces.
+        event->Begin(label, timestamp1_or_async_id,
+                     /*flow_id=*/TimelineEvent::kNoFlowId, timestamp0);
         break;
       case Dart_Timeline_Event_End:
         event->End(label, timestamp1_or_async_id, timestamp0);

runtime/vm/timeline.cc

@@ -504,6 +504,7 @@ TIMELINE_STREAM_LIST(TIMELINE_STREAM_DEFINE)
 TimelineEvent::TimelineEvent()
     : timestamp0_(0),
       timestamp1_(0),
+      flow_id_(TimelineEvent::kNoFlowId),
       state_(0),
       label_(nullptr),
       stream_(nullptr),
@@ -581,17 +582,23 @@ void TimelineEvent::Duration(const char* label,
   set_timestamp1(end_micros);
 }
 
-void TimelineEvent::Begin(const char* label, int64_t id, int64_t micros) {
+void TimelineEvent::Begin(const char* label,
+                          int64_t id,
+                          int64_t flow_id,
+                          int64_t micros) {
   Init(kBegin, label);
   set_timestamp0(micros);
-  // Overload timestamp1_ with the async_id.
+  // Overload timestamp1_ with the task id. This is required for the MacOS
+  // recorder to work.
   set_timestamp1(id);
+  set_flow_id(flow_id);
 }
 
 void TimelineEvent::End(const char* label, int64_t id, int64_t micros) {
   Init(kEnd, label);
   set_timestamp0(micros);
-  // Overload timestamp1_ with the async_id.
+  // Overload timestamp1_ with the task id. This is required for the MacOS
+  // recorder to work.
   set_timestamp1(id);
 }
 
@@ -662,6 +669,7 @@ void TimelineEvent::Init(EventType event_type, const char* label) {
   state_ = 0;
   timestamp0_ = 0;
   timestamp1_ = 0;
+  flow_id_ = TimelineEvent::kNoFlowId;
   OSThread* os_thread = OSThread::Current();
   ASSERT(os_thread != nullptr);
   thread_ = os_thread->trace_id();
@@ -823,6 +831,10 @@ int64_t TimelineEvent::TimeDuration() const {
   return timestamp1_ - timestamp0_;
 }
 
+bool TimelineEvent::HasFlowId() const {
+  return flow_id_ != TimelineEvent::kNoFlowId;
+}
+
 bool TimelineEvent::HasIsolateId() const {
   return isolate_id_ != ILLEGAL_ISOLATE_ID;
 }
@@ -1061,7 +1073,7 @@ void TimelineBeginEndScope::EmitBegin() {
   }
   ASSERT(event != nullptr);
   // Emit a begin event.
-  event->Begin(label(), id());
+  event->Begin(label(), id(), /*flow_id=*/TimelineEvent::kNoFlowId);
   event->Complete();
 }
 
@@ -1854,6 +1866,13 @@ inline void AddBeginEventFields(
   AddBeginAndInstantEventCommonFields(track_event, event);
   track_event->set_type(
       perfetto::protos::pbzero::TrackEvent::Type::TYPE_SLICE_BEGIN);
+  if (event.HasFlowId()) {
+    // TODO(derekx): |TrackEvent|s have a |terminating_flow_ids| field that we
+    // aren't able to populate right now because we aren't keeping track of
+    // terminating flow IDs in |TimelineEvent|. I'm not even sure if using that
+    // field will provide any benefit though.
+    track_event->add_flow_ids(event.flow_id());
+  }
 }
 
 inline void AddInstantEventFields(
@@ -2177,6 +2196,7 @@ void TimelineEventBlock::Finish() {
 
 void DartTimelineEventHelpers::ReportTaskEvent(TimelineEvent* event,
                                                int64_t id,
+                                               int64_t flow_id,
                                                intptr_t type,
                                                char* name,
                                                char* args) {
@@ -2192,7 +2212,7 @@ void DartTimelineEventHelpers::ReportTaskEvent(TimelineEvent* event,
       event->AsyncEnd(name, id, start);
       break;
     case TimelineEvent::kBegin:
-      event->Begin(name, id, start);
+      event->Begin(name, id, flow_id, start);
       break;
     case TimelineEvent::kEnd:
       event->End(name, id, start);

runtime/vm/timeline.h

@@ -332,6 +332,10 @@ class TimelineEvent {
     kNumEventTypes,
   };
 
+  // This value must be kept in sync with the value of _noFlowId in
+  // sdk/lib/developer/timeline.dart.
+  static const int64_t kNoFlowId = -1;
+
   TimelineEvent();
   ~TimelineEvent();
 
@@ -367,6 +371,7 @@ class TimelineEvent {
 
   void Begin(const char* label,
              int64_t id,
+             int64_t flow_id,
              int64_t micros = OS::GetCurrentMonotonicMicrosForTimeline());
 
   void End(const char* label,
@@ -434,6 +439,9 @@ class TimelineEvent {
   int64_t timestamp0() const { return timestamp0_; }
   int64_t timestamp1() const { return timestamp1_; }
 
+  bool HasFlowId() const;
+  int64_t flow_id() const { return flow_id_; }
+
   bool HasIsolateId() const;
   bool HasIsolateGroupId() const;
   char* GetFormattedIsolateId() const;
@@ -538,6 +546,11 @@ class TimelineEvent {
     timestamp1_ = value;
   }
 
+  void set_flow_id(int64_t flow_id) {
+    ASSERT(flow_id_ == TimelineEvent::kNoFlowId);
+    flow_id_ = flow_id;
+  }
+
   bool pre_serialized_args() const {
     return PreSerializedArgsBit::decode(state_);
   }
@@ -562,6 +575,12 @@ class TimelineEvent {
 
   int64_t timestamp0_;
   int64_t timestamp1_;
+  // This field is only used by the Perfetto recorders, because Perfetto's trace
+  // format handles flow events by processing flow IDs attached to
+  // |TimelineEvent::kBegin| events. Other recorders handle flow events by
+  // processing events of type TimelineEvent::kFlowBegin|,
+  // |TimelineEvent::kFlowStep|, and |TimelineEvent::kFlowEnd|.
+  int64_t flow_id_;
   TimelineEventArguments arguments_;
   uword state_;
   const char* label_;
@@ -1190,6 +1209,7 @@ class DartTimelineEventHelpers : public AllStatic {
  public:
   static void ReportTaskEvent(TimelineEvent* event,
                               int64_t id,
+                              int64_t flow_id,
                               intptr_t type,
                               char* name,
                               char* args);

runtime/vm/timeline_test.cc

@@ -85,7 +85,7 @@ class TimelineTestHelper : public AllStatic {
     ASSERT(start >= 0);
     TimelineEvent* event = recorder->StartEvent();
     ASSERT(event != nullptr);
-    event->Begin(label, start);
+    event->Begin(label, /*id=*/-1, /*flow_id=*/TimelineEvent::kNoFlowId, start);
     event->Complete();
   }
 

sdk/lib/_internal/js_dev_runtime/patch/developer_patch.dart

@@ -158,7 +158,7 @@ int _getNextTaskId() {
 
 @patch
 void _reportTaskEvent(
-    int taskId, int type, String name, String argumentsAsJson) {
+    int taskId, int flowId, int type, String name, String argumentsAsJson) {
   // TODO.
 }
 

sdk/lib/_internal/js_runtime/lib/developer_patch.dart

@@ -78,7 +78,7 @@ int _getNextTaskId() {
 
 @patch
 void _reportTaskEvent(
-    int taskId, int type, String name, String argumentsAsJson) {
+    int taskId, int flowId, int type, String name, String argumentsAsJson) {
   // TODO.
 }
 

sdk/lib/_internal/vm/lib/timeline.dart

@@ -19,4 +19,4 @@ external int _getNextTaskId();
 @patch
 @pragma("vm:external-name", "Timeline_reportTaskEvent")
 external void _reportTaskEvent(
-    int taskId, int type, String name, String argumentsAsJson);
+    int taskId, int flowId, int type, String name, String argumentsAsJson);

sdk/lib/_internal/wasm/lib/developer.dart

@@ -56,7 +56,7 @@ int _getNextTaskId() => 0;
 
 @patch
 void _reportTaskEvent(
-    int taskId, int type, String name, String argumentsAsJson) {}
+    int taskId, int flowId, int type, String name, String argumentsAsJson) {}
 
 @patch
 abstract final class NativeRuntime {

sdk/lib/developer/timeline.dart

@@ -28,6 +28,10 @@ const int _flowBegin = 9;
 const int _flowStep = 10;
 const int _flowEnd = 11;
 
+// This value must be kept in sync with the value of TimelineEvent::kNoFlowId in
+// runtime/vm/timeline.h.
+const int _noFlowId = -1;
+
 /// A class to represent Flow events.
 ///
 /// [Flow] objects are used to thread flow events between timeline slices,
@@ -154,7 +158,8 @@ abstract final class Timeline {
     // Instant events don't have an id because they don't need to be paired with
     // other events.
     int taskId = 0;
-    _reportTaskEvent(taskId, _instant, name, _argumentsAsJson(arguments));
+    _reportTaskEvent(taskId, /*flowId=*/ _noFlowId, _instant, name,
+        _argumentsAsJson(arguments));
   }
 
   /// A utility method to time a synchronous [function]. Internally calls
@@ -262,8 +267,8 @@ final class TimelineTask {
       instantArguments ??= {};
       instantArguments[_kFilterKey] = _filterKey;
     }
-    _reportTaskEvent(
-        _taskId, _asyncInstant, name, _argumentsAsJson(instantArguments));
+    _reportTaskEvent(_taskId, /*flowId=*/ _noFlowId, _asyncInstant, name,
+        _argumentsAsJson(instantArguments));
   }
 
   /// Finish the last synchronous operation that was started.
@@ -320,12 +325,14 @@ final class _AsyncBlock {
 
   // Emit the start event.
   void _start(Map arguments) {
-    _reportTaskEvent(_taskId, _asyncBegin, name, _argumentsAsJson(arguments));
+    _reportTaskEvent(_taskId, /*flowId=*/ _noFlowId, _asyncBegin, name,
+        _argumentsAsJson(arguments));
   }
 
   // Emit the finish event.
   void _finish(Map? arguments) {
-    _reportTaskEvent(_taskId, _asyncEnd, name, _argumentsAsJson(arguments));
+    _reportTaskEvent(_taskId, /*flowId=*/ _noFlowId, _asyncEnd, name,
+        _argumentsAsJson(arguments));
   }
 }
 
@@ -351,18 +358,19 @@ final class _SyncBlock {
 
   /// Start this block of time.
   void _startSync() {
-    _reportTaskEvent(taskId, _begin, name, _jsonArguments);
+    _reportTaskEvent(
+        taskId, flow?.id ?? _noFlowId, _begin, name, _jsonArguments);
   }
 
   /// Finish this block of time. At this point, this block can no longer be
   /// used.
   void finish() {
     // Report event to runtime.
-    _reportTaskEvent(taskId, _end, name, _jsonArguments);
+    _reportTaskEvent(taskId, flow?.id ?? _noFlowId, _end, name, _jsonArguments);
     final Flow? tempFlow = flow;
     if (tempFlow != null) {
-      _reportTaskEvent(tempFlow.id, tempFlow._type, "${tempFlow.id}",
-          _argumentsAsJson(null));
+      _reportTaskEvent(tempFlow.id, /*flowId=*/ _noFlowId, tempFlow._type,
+          "${tempFlow.id}", _argumentsAsJson(null));
     }
   }
 }
@@ -388,4 +396,4 @@ external int _getTraceClock();
 
 /// Reports an event for a task.
 external void _reportTaskEvent(
-    int taskId, int type, String name, String argumentsAsJson);
+    int taskId, int flowId, int type, String name, String argumentsAsJson);