perfetto: Split COMPLETE events into BEGIN/END pairs

There are a few reasons why this is desirable:
(1) Reduces need for complete event stack in ThreadLocalEventSinks,
    which was brittle before (e.g. crbug.com/983307).
(2) Makes it possible to flush event sinks while tracing in the future
    without losing not-yet-completed COMPLETE events from the stack
    (streamed tracing use case). Events that didn't end before the
    flush will still be present in the trace as BEGIN only.
(3) Prevents reordering of nested COMPLETE events - something which
    could confuse TraceProcessor in the past (events with identical
    begin timestamps would be imported incorrectly).

To achieve this, this patch also plumbs the EXPLICIT_TIMESTAMP flag
and thread id through to TraceLog::UpdateTraceEventDurationExplicit,
because it seems that android can add COMPLETE events with explicit
timestamps / threads [1].

[1] https://cs.chromium.org/chromium/src/base/android/early_trace_event_binding.cc?q=INTERNAL_TRACE_EVENT_ADD_WITH_ID_TID_AND_TIMESTAMPS&ss=chromium&l=31

Bug: 983307, 928738, 1006770
Change-Id: I66e685c04c068646d550f182185d3c45febcbfa8
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/1899852
Commit-Queue: Eric Seckler <eseckler@chromium.org>
Reviewed-by: oysteine <oysteine@chromium.org>
Cr-Commit-Position: refs/heads/master@{#716871}

base/trace_event/trace_event.h

@@ -174,8 +174,11 @@
 //     const unsigned char* category_group_enabled,
 //     const char* name,
 //     base::trace_event::TraceEventHandle id,
-//     const TimeTicks& now,
-//     const ThreadTicks* thread_now)
+//     int thread_id,
+//     bool explicit_timestamps,
+//     const base::TimeTicks& now,
+//     const base::ThreadTicks& thread_now,
+//     base::trace_event::ThreadInstructionCount thread_instruction_now)
 #define TRACE_EVENT_API_UPDATE_TRACE_EVENT_DURATION_EXPLICIT \
   trace_event_internal::UpdateTraceEventDurationExplicit
 
@@ -379,28 +382,29 @@
 
 // Implementation detail: internal macro to create static category and add
 // event if the category is enabled.
-#define INTERNAL_TRACE_EVENT_ADD_WITH_ID_TID_AND_TIMESTAMPS(                  \
-    category_group, name, id, thread_id, begin_timestamp, end_timestamp,      \
-    thread_end_timestamp, flags, ...)                                         \
-  do {                                                                        \
-    INTERNAL_TRACE_EVENT_GET_CATEGORY_INFO(category_group);                   \
-    if (INTERNAL_TRACE_EVENT_CATEGORY_GROUP_ENABLED()) {                      \
-      trace_event_internal::TraceID trace_event_trace_id((id));               \
-      unsigned int trace_event_flags =                                        \
-          flags | trace_event_trace_id.id_flags();                            \
-      const unsigned char* uid_category_group_enabled =                       \
-          INTERNAL_TRACE_EVENT_UID(category_group_enabled);                   \
-      auto handle =                                                           \
-          trace_event_internal::AddTraceEventWithThreadIdAndTimestamp(        \
-              TRACE_EVENT_PHASE_COMPLETE, uid_category_group_enabled, name,   \
-              trace_event_trace_id.scope(), trace_event_trace_id.raw_id(),    \
-              thread_id, begin_timestamp,                                     \
-              trace_event_flags | TRACE_EVENT_FLAG_EXPLICIT_TIMESTAMP,        \
-              trace_event_internal::kNoId, ##__VA_ARGS__);                    \
-      TRACE_EVENT_API_UPDATE_TRACE_EVENT_DURATION_EXPLICIT(                   \
-          uid_category_group_enabled, name, handle, end_timestamp,            \
-          thread_end_timestamp, base::trace_event::ThreadInstructionCount()); \
-    }                                                                         \
+#define INTERNAL_TRACE_EVENT_ADD_WITH_ID_TID_AND_TIMESTAMPS(                 \
+    category_group, name, id, thread_id, begin_timestamp, end_timestamp,     \
+    thread_end_timestamp, flags, ...)                                        \
+  do {                                                                       \
+    INTERNAL_TRACE_EVENT_GET_CATEGORY_INFO(category_group);                  \
+    if (INTERNAL_TRACE_EVENT_CATEGORY_GROUP_ENABLED()) {                     \
+      trace_event_internal::TraceID trace_event_trace_id((id));              \
+      unsigned int trace_event_flags =                                       \
+          flags | trace_event_trace_id.id_flags();                           \
+      const unsigned char* uid_category_group_enabled =                      \
+          INTERNAL_TRACE_EVENT_UID(category_group_enabled);                  \
+      auto handle =                                                          \
+          trace_event_internal::AddTraceEventWithThreadIdAndTimestamp(       \
+              TRACE_EVENT_PHASE_COMPLETE, uid_category_group_enabled, name,  \
+              trace_event_trace_id.scope(), trace_event_trace_id.raw_id(),   \
+              thread_id, begin_timestamp,                                    \
+              trace_event_flags | TRACE_EVENT_FLAG_EXPLICIT_TIMESTAMP,       \
+              trace_event_internal::kNoId, ##__VA_ARGS__);                   \
+      TRACE_EVENT_API_UPDATE_TRACE_EVENT_DURATION_EXPLICIT(                  \
+          uid_category_group_enabled, name, handle, thread_id,               \
+          /*explicit_timestamps=*/true, end_timestamp, thread_end_timestamp, \
+          base::trace_event::ThreadInstructionCount());                      \
+    }                                                                        \
   } while (0)
 
 // The linked ID will not be mangled.
@@ -717,6 +721,8 @@ void BASE_EXPORT UpdateTraceEventDurationExplicit(
     const unsigned char* category_group_enabled,
     const char* name,
     base::trace_event::TraceEventHandle handle,
+    int thread_id,
+    bool explicit_timestamps,
     const base::TimeTicks& now,
     const base::ThreadTicks& thread_now,
     base::trace_event::ThreadInstructionCount thread_instruction_now);

base/trace_event/trace_log.cc

@@ -1405,15 +1405,19 @@ void TraceLog::UpdateTraceEventDuration(
   if (!category_group_enabled_local)
     return;
 
-  UpdateTraceEventDurationExplicit(category_group_enabled, name, handle,
-                                   OffsetNow(), ThreadNow(),
-                                   ThreadInstructionNow());
+  UpdateTraceEventDurationExplicit(
+      category_group_enabled, name, handle,
+      static_cast<int>(base::PlatformThread::CurrentId()),
+      /*explicit_timestamps=*/false, OffsetNow(), ThreadNow(),
+      ThreadInstructionNow());
 }
 
 void TraceLog::UpdateTraceEventDurationExplicit(
     const unsigned char* category_group_enabled,
     const char* name,
     TraceEventHandle handle,
+    int thread_id,
+    bool explicit_timestamps,
     const TimeTicks& now,
     const ThreadTicks& thread_now,
     ThreadInstructionCount thread_instruction_now) {
@@ -1438,7 +1442,9 @@ void TraceLog::UpdateTraceEventDurationExplicit(
     auto update_duration_override =
         update_duration_override_.load(std::memory_order_relaxed);
     if (update_duration_override) {
-      update_duration_override(handle, now, thread_now, thread_instruction_now);
+      update_duration_override(category_group_enabled, name, handle, thread_id,
+                               explicit_timestamps, now, thread_now,
+                               thread_instruction_now);
       return;
     }
   }
@@ -1816,13 +1822,15 @@ void UpdateTraceEventDurationExplicit(
     const unsigned char* category_group_enabled,
     const char* name,
     base::trace_event::TraceEventHandle handle,
+    int thread_id,
+    bool explicit_timestamps,
     const base::TimeTicks& now,
     const base::ThreadTicks& thread_now,
     base::trace_event::ThreadInstructionCount thread_instruction_now) {
   return base::trace_event::TraceLog::GetInstance()
       ->UpdateTraceEventDurationExplicit(category_group_enabled, name, handle,
-                                         now, thread_now,
-                                         thread_instruction_now);
+                                         thread_id, explicit_timestamps, now,
+                                         thread_now, thread_instruction_now);
 }
 
 ScopedTraceBinaryEfficient::ScopedTraceBinaryEfficient(

base/trace_event/trace_log.h

@@ -201,7 +201,11 @@ class BASE_EXPORT TraceLog : public MemoryDumpProvider {
                                                  TraceEventHandle* handle);
   using OnFlushFunction = void (*)();
   using UpdateDurationFunction =
-      void (*)(TraceEventHandle handle,
+      void (*)(const unsigned char* category_group_enabled,
+               const char* name,
+               TraceEventHandle handle,
+               int thread_id,
+               bool explicit_timestamps,
                const TimeTicks& now,
                const ThreadTicks& thread_now,
                ThreadInstructionCount thread_instruction_now);
@@ -292,6 +296,8 @@ class BASE_EXPORT TraceLog : public MemoryDumpProvider {
       const unsigned char* category_group_enabled,
       const char* name,
       TraceEventHandle handle,
+      int thread_id,
+      bool explicit_timestamps,
       const TimeTicks& now,
       const ThreadTicks& thread_now,
       ThreadInstructionCount thread_instruction_now);

services/tracing/public/cpp/perfetto/thread_local_event_sink.h

@@ -39,7 +39,11 @@ class COMPONENT_EXPORT(TRACING_CPP) ThreadLocalEventSink {
                              base::trace_event::TraceEventHandle* handle) = 0;
 
   virtual void UpdateDuration(
+      const unsigned char* category_group_enabled,
+      const char* name,
       base::trace_event::TraceEventHandle handle,
+      int thread_id,
+      bool explicit_timestamps,
       const base::TimeTicks& now,
       const base::ThreadTicks& thread_now,
       base::trace_event::ThreadInstructionCount thread_instruction_now) = 0;

services/tracing/public/cpp/perfetto/trace_event_data_source.cc

@@ -884,7 +884,11 @@ void TraceEventDataSource::OnAddTraceEvent(
 
 // static
 void TraceEventDataSource::OnUpdateDuration(
+    const unsigned char* category_group_enabled,
+    const char* name,
     base::trace_event::TraceEventHandle handle,
+    int thread_id,
+    bool explicit_timestamps,
     const base::TimeTicks& now,
     const base::ThreadTicks& thread_now,
     base::trace_event::ThreadInstructionCount thread_instruction_now) {
@@ -897,8 +901,9 @@ void TraceEventDataSource::OnUpdateDuration(
   auto* thread_local_event_sink =
       static_cast<ThreadLocalEventSink*>(ThreadLocalEventSinkSlot()->Get());
   if (thread_local_event_sink) {
-    thread_local_event_sink->UpdateDuration(handle, now, thread_now,
-                                            thread_instruction_now);
+    thread_local_event_sink->UpdateDuration(
+        category_group_enabled, name, handle, thread_id, explicit_timestamps,
+        now, thread_now, thread_instruction_now);
   }
 }
 

services/tracing/public/cpp/perfetto/trace_event_data_source.h

@@ -210,7 +210,11 @@ class COMPONENT_EXPORT(TRACING_CPP) TraceEventDataSource
                               bool thread_will_flush,
                               base::trace_event::TraceEventHandle* handle);
   static void OnUpdateDuration(
+      const unsigned char* category_group_enabled,
+      const char* name,
       base::trace_event::TraceEventHandle handle,
+      int thread_id,
+      bool explicit_timestamps,
       const base::TimeTicks& now,
       const base::ThreadTicks& thread_now,
       base::trace_event::ThreadInstructionCount thread_instruction_now);

services/tracing/public/cpp/perfetto/trace_event_data_source_unittest.cc

@@ -335,8 +335,13 @@ class TraceEventDataSourceTest : public testing::Test {
       last_thread_time_ += packet->track_event().thread_time_delta_us();
     }
 
-    EXPECT_EQ(packet->track_event().category_iids_size(), 1);
-    EXPECT_EQ(packet->track_event().category_iids(0), category_iid);
+    if (category_iid > 0) {
+      EXPECT_EQ(packet->track_event().category_iids_size(), 1);
+      EXPECT_EQ(packet->track_event().category_iids(0), category_iid);
+    } else {
+      EXPECT_EQ(packet->track_event().category_iids_size(), 0);
+    }
+
     EXPECT_TRUE(packet->track_event().has_legacy_event());
 
     const auto& legacy_event = packet->track_event().legacy_event();
@@ -930,44 +935,56 @@ TEST_F(TraceEventDataSourceTest, UpdateDurationOfCompleteEvent) {
   trace_event_internal::TraceID trace_event_trace_id =
       trace_event_internal::kNoId;
 
+  // COMPLETE events are split into a BEGIN/END event pair. Adding the event
+  // writes the BEGIN event immediately.
   auto handle = trace_event_internal::AddTraceEventWithThreadIdAndTimestamp(
       TRACE_EVENT_PHASE_COMPLETE, category_group_enabled, kEventName,
       trace_event_trace_id.scope(), trace_event_trace_id.raw_id(),
-      1 /* thread_id */,
+      /*thread_id=*/1,
       base::TimeTicks() + base::TimeDelta::FromMicroseconds(10),
       trace_event_trace_id.id_flags() | TRACE_EVENT_FLAG_EXPLICIT_TIMESTAMP,
       trace_event_internal::kNoId);
 
+  EXPECT_EQ(producer_client()->GetFinalizedPacketCount(), 2u);
+  auto* b_packet = producer_client()->GetFinalizedPacket(1);
+  ExpectTraceEvent(
+      b_packet, /*category_iid=*/1u, /*name_iid=*/1u, TRACE_EVENT_PHASE_BEGIN,
+      TRACE_EVENT_FLAG_EXPLICIT_TIMESTAMP | TRACE_EVENT_FLAG_HAS_ID, /*id=*/0u,
+      /*absolute_timestamp=*/10, /*tid_override=*/1, /*pid_override=*/0);
+
+  // Updating the duration of the event as it goes out of scope results in the
+  // corresponding END event being written. These END events don't contain any
+  // event names or categories in the proto format.
   base::trace_event::TraceLog::GetInstance()->UpdateTraceEventDurationExplicit(
-      category_group_enabled, kEventName, handle,
+      category_group_enabled, kEventName, handle, /*thread_id=*/1,
+      /*explicit_timestamps=*/true,
       base::TimeTicks() + base::TimeDelta::FromMicroseconds(30),
       base::ThreadTicks() + base::TimeDelta::FromMicroseconds(50),
       base::trace_event::ThreadInstructionCount());
 
-  // The call to UpdateTraceEventDurationExplicit should have successfully
-  // updated the duration of the event which was added in the
-  // AddTraceEventWithThreadIdAndTimestamp call.
-  EXPECT_EQ(producer_client()->GetFinalizedPacketCount(), 2u);
-  auto* e_packet = producer_client()->GetFinalizedPacket(1);
+  EXPECT_EQ(producer_client()->GetFinalizedPacketCount(), 3u);
+  auto* e_packet = producer_client()->GetFinalizedPacket(2);
   ExpectTraceEvent(
-      e_packet, /*category_iid=*/1u, /*name_iid=*/1u,
-      TRACE_EVENT_PHASE_COMPLETE,
-      TRACE_EVENT_FLAG_EXPLICIT_TIMESTAMP | TRACE_EVENT_FLAG_HAS_ID, /*id=*/0u,
-      /*absolute_timestamp=*/10, /*tid_override=*/1, /*pid_override=*/0,
-      /*duration=*/20);
+      e_packet, /*category_iid=*/0u, /*name_iid=*/0u, TRACE_EVENT_PHASE_END,
+      TRACE_EVENT_FLAG_EXPLICIT_TIMESTAMP, /*id=*/0u,
+      /*absolute_timestamp=*/30, /*tid_override=*/1, /*pid_override=*/0);
 
-  // Updating the duration of an invalid event should cause no further events to
-  // be emitted.
+  // Updating the duration of an event that wasn't added before tracing begun
+  // will only emit an END event, again without category or name.
   handle.event_index = 0;
-
   base::trace_event::TraceLog::GetInstance()->UpdateTraceEventDurationExplicit(
-      category_group_enabled, kEventName, handle,
-      base::TimeTicks() + base::TimeDelta::FromMicroseconds(30),
-      base::ThreadTicks() + base::TimeDelta::FromMicroseconds(50),
+      category_group_enabled, "other_event_name", handle, /*thread_id=*/1,
+      /*explicit_timestamps=*/true,
+      base::TimeTicks() + base::TimeDelta::FromMicroseconds(40),
+      base::ThreadTicks() + base::TimeDelta::FromMicroseconds(60),
       base::trace_event::ThreadInstructionCount());
 
-  // No further packets should have been emitted.
-  EXPECT_EQ(producer_client()->GetFinalizedPacketCount(), 2u);
+  EXPECT_EQ(producer_client()->GetFinalizedPacketCount(), 4u);
+  auto* e2_packet = producer_client()->GetFinalizedPacket(3);
+  ExpectTraceEvent(
+      e2_packet, /*category_iid=*/0u, /*name_iid=*/0u, TRACE_EVENT_PHASE_END,
+      TRACE_EVENT_FLAG_EXPLICIT_TIMESTAMP, /*id=*/0u,
+      /*absolute_timestamp=*/40, /*tid_override=*/1, /*pid_override=*/0);
 }
 
 // TODO(eseckler): Add a test with multiple events + same strings (cat, name,

services/tracing/public/cpp/perfetto/track_event_thread_local_event_sink.h

@@ -45,7 +45,11 @@ class COMPONENT_EXPORT(TRACING_CPP) TrackEventThreadLocalEventSink
   // ThreadLocalEventSink implementation:
   void AddTraceEvent(base::trace_event::TraceEvent* trace_event,
                      base::trace_event::TraceEventHandle* handle) override;
-  void UpdateDuration(base::trace_event::TraceEventHandle handle,
+  void UpdateDuration(const unsigned char* category_group_enabled,
+                      const char* name,
+                      base::trace_event::TraceEventHandle handle,
+                      int thread_id,
+                      bool explicit_timestamps,
                       const base::TimeTicks& now,
                       const base::ThreadTicks& thread_now,
                       base::trace_event::ThreadInstructionCount
@@ -94,9 +98,6 @@ class COMPONENT_EXPORT(TRACING_CPP) TrackEventThreadLocalEventSink
   perfetto::protos::pbzero::ThreadDescriptor::ChromeThreadType thread_type_ =
       perfetto::protos::pbzero::ThreadDescriptor::CHROME_THREAD_UNSPECIFIED;
 
-  base::trace_event::TraceEvent complete_event_stack_[kMaxCompleteEventDepth];
-  uint32_t current_stack_depth_ = 0;
-
   const bool privacy_filtering_enabled_;
 };