Reland "perfetto: Split COMPLETE events into BEGIN/END pairs"

This is a reland of 4da16526.

Relanding after the bad event nesting in v8's GC events was fixed.
Also increases the default trace buffer size, because the traces
with split events are slightly larger and cause some benchmarks to
lose data otherwise. Furthermore, includes a fix for a bug that
caused us to emit COMPLETE events as atrace events twice.

Original change's description:
> 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}

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

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

@@ -1415,15 +1415,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) {
@@ -1448,7 +1452,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;
     }
   }
@@ -1826,13 +1832,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);
@@ -298,6 +302,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/perfetto_config.cc

@@ -42,7 +42,7 @@ perfetto::TraceConfig GetDefaultPerfettoConfig(
 
   size_t size_limit = chrome_config.GetTraceBufferSizeInKb();
   if (size_limit == 0) {
-    size_limit = 100 * 1024;
+    size_limit = 150 * 1024;
   }
   auto* buffer_config = perfetto_config.add_buffers();
   buffer_config->set_size_kb(size_limit);

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

@@ -895,7 +895,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) {
@@ -908,8 +912,9 @@ void TraceEventDataSource::OnUpdateDuration(
   auto* thread_local_event_sink = static_cast<TrackEventThreadLocalEventSink*>(
       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

@@ -230,7 +230,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

@@ -337,8 +337,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();
@@ -932,44 +937,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

@@ -71,12 +71,6 @@ class COMPONENT_EXPORT(TRACING_CPP) TrackEventThreadLocalEventSink
   // (e.g. interning index entries and a ThreadDescriptor) to be emitted again.
   static void ClearIncrementalState();
 
-  // Returns true if the current |trace_event| is part of a COMPLETE event
-  // phase. As part of this we will update any stack information to keep track
-  // of the information when we can pop something off the stack.
-  bool MaybeHandleCompleteEvent(base::trace_event::TraceEvent* trace_event,
-                                base::trace_event::TraceEventHandle* handle);
-
   // If we need to perform an incremental reset we will do so, and also emit all
   // the relevant descriptors to start a new fresh sequence.
   void ResetIncrementalStateIfNeeded(
@@ -99,10 +93,6 @@ class COMPONENT_EXPORT(TRACING_CPP) TrackEventThreadLocalEventSink
   void AddTraceEvent(base::trace_event::TraceEvent* trace_event,
                      base::trace_event::TraceEventHandle* handle,
                      TrackEventArgumentFunction arg_func) {
-    if (MaybeHandleCompleteEvent(trace_event, handle)) {
-      return;
-    }
-
     ResetIncrementalStateIfNeeded(trace_event);
 
     auto trace_packet = trace_writer_->NewTracePacket();
@@ -117,7 +107,11 @@ class COMPONENT_EXPORT(TRACING_CPP) TrackEventThreadLocalEventSink
   }
 
   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);
@@ -168,9 +162,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_;
 
   std::unique_ptr<perfetto::StartupTraceWriter> trace_writer_;