perfetto: Switch to TrackEvent fields for phase & name

Write TrackEvent's type and name_iid fields instead of LegacyEvent's
where possible. Also avoid creating the LegacyEvent if we don't need
to set any of its fields.

This should save us some trace size in the (probably common) case where
we don't need to set any special LegacyEvent flags, e.g. for END events
of former COMPLETE events.

Also removes a few remaining remnants of emitting complete events.

Bug: 1029510, 1029465
Change-Id: If544f5e2dff97660ba7523605d20d09e29b26da3
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/1944393
Commit-Queue: Eric Seckler <eseckler@chromium.org>
Reviewed-by: Stephen Nusko <nuskos@chromium.org>
Cr-Commit-Position: refs/heads/master@{#720479}

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

@@ -40,12 +40,13 @@ constexpr char kTraceEventEndName[] = "";
 //       });
 #define TRACE_EVENT_BEGIN(category, name, ...)                              \
   TRACING_INTERNAL_ADD_TRACE_EVENT(TRACE_EVENT_PHASE_BEGIN, category, name, \
-                                   ##__VA_ARGS__)
+                                   TRACE_EVENT_FLAG_NONE, ##__VA_ARGS__)
 
 // End a thread-scoped slice under |category|.
-#define TRACE_EVENT_END(category, ...)                              \
-  TRACING_INTERNAL_ADD_TRACE_EVENT(TRACE_EVENT_PHASE_END, category, \
-                                   kTraceEventEndName, ##__VA_ARGS__)
+#define TRACE_EVENT_END(category, ...)                                        \
+  TRACING_INTERNAL_ADD_TRACE_EVENT(TRACE_EVENT_PHASE_END, category,           \
+                                   kTraceEventEndName, TRACE_EVENT_FLAG_NONE, \
+                                   ##__VA_ARGS__)
 
 // Begin a thread-scoped slice which gets automatically closed when going out
 // of scope.
@@ -57,6 +58,6 @@ constexpr char kTraceEventEndName[] = "";
 // perfetto does.
 #define TRACE_EVENT_INSTANT(category, name, ...)                              \
   TRACING_INTERNAL_ADD_TRACE_EVENT(TRACE_EVENT_PHASE_INSTANT, category, name, \
-                                   ##__VA_ARGS__)
+                                   TRACE_EVENT_SCOPE_THREAD, ##__VA_ARGS__)
 
 #endif  // SERVICES_TRACING_PUBLIC_CPP_PERFETTO_MACROS_H_

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

@@ -27,7 +27,8 @@ base::trace_event::ThreadInstructionCount ThreadInstructionNow() {
 base::Optional<base::trace_event::TraceEvent> CreateTraceEvent(
     char phase,
     const unsigned char* category_group_enabled,
-    const char* name) {
+    const char* name,
+    unsigned int flags) {
   DCHECK(phase == TRACE_EVENT_PHASE_BEGIN || phase == TRACE_EVENT_PHASE_END ||
          phase == TRACE_EVENT_PHASE_INSTANT);
   DCHECK(category_group_enabled);
@@ -49,8 +50,7 @@ base::Optional<base::trace_event::TraceEvent> CreateTraceEvent(
   return base::trace_event::TraceEvent(
       thread_id, offset_event_timestamp, thread_now, thread_instruction_now,
       phase, category_group_enabled, name, trace_event_internal::kGlobalScope,
-      trace_event_internal::kNoId, trace_event_internal::kNoId, nullptr,
-      TRACE_EVENT_FLAG_NONE);
+      trace_event_internal::kNoId, trace_event_internal::kNoId, nullptr, flags);
 }
 
 }  // namespace internal

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

@@ -18,7 +18,8 @@ namespace internal {
 base::Optional<base::trace_event::TraceEvent> COMPONENT_EXPORT(TRACING_CPP)
     CreateTraceEvent(char phase,
                      const unsigned char* category_group_enabled,
-                     const char* name);
+                     const char* name,
+                     unsigned int flags);
 
 // A simple function that will add the TraceEvent requested and will call the
 // |argument_func| after the track_event has been filled in.
@@ -28,9 +29,11 @@ static inline base::trace_event::TraceEventHandle AddTraceEvent(
     char phase,
     const unsigned char* category_group_enabled,
     const char* name,
+    unsigned int flags,
     TrackEventArgumentFunction argument_func) {
   base::trace_event::TraceEventHandle handle = {0, 0, 0};
-  auto maybe_event = CreateTraceEvent(phase, category_group_enabled, name);
+  auto maybe_event =
+      CreateTraceEvent(phase, category_group_enabled, name, flags);
   if (!maybe_event) {
     return handle;
   }
@@ -49,14 +52,14 @@ static inline base::trace_event::TraceEventHandle AddTraceEvent(
 #define TRACING_INTERNAL_CONCAT(a, b) TRACING_INTERNAL_CONCAT2(a, b)
 #define TRACING_INTERNAL_UID(prefix) TRACING_INTERNAL_CONCAT(prefix, __LINE__)
 
-#define TRACING_INTERNAL_ADD_TRACE_EVENT(phase, category, name, ...)     \
-  do {                                                                   \
-    INTERNAL_TRACE_EVENT_GET_CATEGORY_INFO(category);                    \
-    if (INTERNAL_TRACE_EVENT_CATEGORY_GROUP_ENABLED()) {                 \
-      tracing::internal::AddTraceEvent(                                  \
-          phase, INTERNAL_TRACE_EVENT_UID(category_group_enabled), name, \
-          ##__VA_ARGS__);                                                \
-    }                                                                    \
+#define TRACING_INTERNAL_ADD_TRACE_EVENT(phase, category, name, flags, ...) \
+  do {                                                                      \
+    INTERNAL_TRACE_EVENT_GET_CATEGORY_INFO(category);                       \
+    if (INTERNAL_TRACE_EVENT_CATEGORY_GROUP_ENABLED()) {                    \
+      tracing::internal::AddTraceEvent(                                     \
+          phase, INTERNAL_TRACE_EVENT_UID(category_group_enabled), name,    \
+          flags, ##__VA_ARGS__);                                            \
+    }                                                                       \
   } while (false)
 
 #define TRACING_INTERNAL_SCOPED_ADD_TRACE_EVENT(category, name, ...)          \
@@ -74,12 +77,13 @@ static inline base::trace_event::TraceEventHandle AddTraceEvent(
         /* field. As described in macros.h we shouldn't need it in our */     \
         /* end state                                                   */     \
         TRACING_INTERNAL_ADD_TRACE_EVENT(TRACE_EVENT_PHASE_END, category, "", \
+                                         TRACE_EVENT_FLAG_NONE,               \
                                          [](perfetto::EventContext) {});      \
       }                                                                       \
     } event;                                                                  \
   } TRACING_INTERNAL_UID(scoped_event){[&]() {                                \
     TRACING_INTERNAL_ADD_TRACE_EVENT(TRACE_EVENT_PHASE_BEGIN, category, name, \
-                                     ##__VA_ARGS__);                          \
+                                     TRACE_EVENT_FLAG_NONE, ##__VA_ARGS__);   \
     return 0;                                                                 \
   }()};
 

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

@@ -315,8 +315,7 @@ class TraceEventDataSourceTest : public testing::Test {
                         uint64_t id = 0,
                         int64_t absolute_timestamp = 0,
                         int32_t tid_override = 0,
-                        int32_t pid_override = 0,
-                        int64_t duration = 0) {
+                        int32_t pid_override = 0) {
     EXPECT_TRUE(packet->has_track_event());
 
     if (absolute_timestamp > 0) {
@@ -344,12 +343,41 @@ class TraceEventDataSourceTest : public testing::Test {
       EXPECT_EQ(packet->track_event().category_iids_size(), 0);
     }
 
-    EXPECT_TRUE(packet->track_event().has_legacy_event());
+    EXPECT_EQ(packet->track_event().name_iid(), name_iid);
 
+    TrackEvent::Type track_event_type;
+    switch (phase) {
+      case TRACE_EVENT_PHASE_BEGIN:
+        track_event_type = TrackEvent::TYPE_SLICE_BEGIN;
+        break;
+      case TRACE_EVENT_PHASE_END:
+        track_event_type = TrackEvent::TYPE_SLICE_END;
+        break;
+      case TRACE_EVENT_PHASE_INSTANT:
+        track_event_type = TrackEvent::TYPE_INSTANT;
+        break;
+      default:
+        track_event_type = TrackEvent::TYPE_UNSPECIFIED;
+        break;
+    }
+
+    if (track_event_type != TrackEvent::TYPE_UNSPECIFIED) {
+      EXPECT_EQ(packet->track_event().type(), track_event_type);
+    }
+
+    // We don't emit the legacy event if we don't need it.
+    if (track_event_type != TrackEvent::TYPE_UNSPECIFIED && !flags &&
+        !tid_override && !pid_override) {
+      EXPECT_FALSE(packet->track_event().has_legacy_event());
+      return;
+    }
+
+    EXPECT_TRUE(packet->track_event().has_legacy_event());
     const auto& legacy_event = packet->track_event().legacy_event();
-    EXPECT_EQ(legacy_event.name_iid(), name_iid);
-    EXPECT_EQ(legacy_event.phase(), phase);
-    EXPECT_EQ(legacy_event.duration_us(), duration);
+
+    if (track_event_type == TrackEvent::TYPE_UNSPECIFIED) {
+      EXPECT_EQ(legacy_event.phase(), phase);
+    }
 
     if (phase == TRACE_EVENT_PHASE_INSTANT) {
       switch (flags & TRACE_EVENT_FLAG_SCOPE_MASK) {
@@ -1435,7 +1463,7 @@ TEST_F(TraceEventDataSourceTest, TypedArgumentsTracingOnInstant) {
 
   auto* e_packet = producer_client()->GetFinalizedPacket(1);
   ExpectTraceEvent(e_packet, /*category_iid=*/1u, /*name_iid=*/1u,
-                   TRACE_EVENT_PHASE_INSTANT);
+                   TRACE_EVENT_PHASE_INSTANT, TRACE_EVENT_SCOPE_THREAD);
 
   ExpectEventCategories(e_packet, {{1u, "browser"}});
   ExpectEventNames(e_packet, {{1u, "bar"}});

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

@@ -144,6 +144,27 @@ ThreadDescriptor::ChromeThreadType GetThreadType(
   return ThreadDescriptor::CHROME_THREAD_UNSPECIFIED;
 }
 
+// Lazily sets |legacy_event| on the |track_event|. Note that you should not set
+// any other fields of |track_event| (outside the LegacyEvent) between any calls
+// to GetOrCreate(), as the protozero serialization requires the writes to a
+// message's fields to be consecutive.
+class LazyLegacyEventInitializer {
+ public:
+  LazyLegacyEventInitializer(TrackEvent* track_event)
+      : track_event_(track_event) {}
+
+  TrackEvent::LegacyEvent* GetOrCreate() {
+    if (!legacy_event_) {
+      legacy_event_ = track_event_->set_legacy_event();
+    }
+    return legacy_event_;
+  }
+
+ private:
+  TrackEvent* track_event_;
+  TrackEvent::LegacyEvent* legacy_event_ = nullptr;
+};
+
 }  // namespace
 
 // static
@@ -211,7 +232,7 @@ void TrackEventThreadLocalEventSink::ResetIncrementalStateIfNeeded(
 void TrackEventThreadLocalEventSink::PrepareTrackEvent(
     base::trace_event::TraceEvent* trace_event,
     base::trace_event::TraceEventHandle* handle,
-    perfetto::protos::pbzero::TrackEvent* track_event) {
+    TrackEvent* track_event) {
   // Each event's updates to InternedData are flushed at the end of
   // AddTraceEvent().
   DCHECK(pending_interning_updates_.empty());
@@ -390,45 +411,54 @@ void TrackEventThreadLocalEventSink::PrepareTrackEvent(
     WriteDebugAnnotations(trace_event, track_event, interned_annotation_names);
   }
 
-  auto* legacy_event = track_event->set_legacy_event();
-
-  // TODO(eseckler): Set name on |track_event| instead.
   if (interned_name.id) {
-    legacy_event->set_name_iid(interned_name.id);
+    track_event->set_name_iid(interned_name.id);
   }
 
-  legacy_event->set_phase(phase);
+  // Only set the |legacy_event| field of the TrackEvent if we need to emit any
+  // of the legacy fields. BEWARE: Do not set any other TrackEvent fields in
+  // between calls to |legacy_event.GetOrCreate()|.
+  LazyLegacyEventInitializer legacy_event(track_event);
 
-  if (phase == TRACE_EVENT_PHASE_COMPLETE) {
-    legacy_event->set_duration_us(trace_event->duration().InMicroseconds());
+  // TODO(eseckler): Also convert async events / flow events to corresponding
+  // native TrackEvent types.
+  TrackEvent::Type track_event_type;
+  switch (phase) {
+    case TRACE_EVENT_PHASE_BEGIN:
+      track_event_type = TrackEvent::TYPE_SLICE_BEGIN;
+      break;
+    case TRACE_EVENT_PHASE_END:
+      track_event_type = TrackEvent::TYPE_SLICE_END;
+      break;
+    case TRACE_EVENT_PHASE_INSTANT:
+      track_event_type = TrackEvent::TYPE_INSTANT;
+      break;
+    default:
+      track_event_type = TrackEvent::TYPE_UNSPECIFIED;
+      break;
+  }
 
-    if (!trace_event->thread_timestamp().is_null()) {
-      int64_t thread_duration = trace_event->thread_duration().InMicroseconds();
-      if (thread_duration != -1) {
-        legacy_event->set_thread_duration_us(thread_duration);
-      }
-    }
+  if (track_event_type != TrackEvent::TYPE_UNSPECIFIED) {
+    track_event->set_type(track_event_type);
+  } else {
+    legacy_event.GetOrCreate()->set_phase(phase);
+  }
 
-    // TODO(acomminos): Add thread instruction count for BEGIN/END events
-    if (!trace_event->thread_instruction_count().is_null()) {
-      int64_t instruction_delta =
-          trace_event->thread_instruction_delta().ToInternalValue();
-      legacy_event->set_thread_instruction_delta(instruction_delta);
-    }
-  } else if (phase == TRACE_EVENT_PHASE_INSTANT) {
+  // TODO(eseckler): Convert instant event scopes to tracks.
+  if (phase == TRACE_EVENT_PHASE_INSTANT) {
     switch (flags & TRACE_EVENT_FLAG_SCOPE_MASK) {
       case TRACE_EVENT_SCOPE_GLOBAL:
-        legacy_event->set_instant_event_scope(
+        legacy_event.GetOrCreate()->set_instant_event_scope(
             TrackEvent::LegacyEvent::SCOPE_GLOBAL);
         break;
 
       case TRACE_EVENT_SCOPE_PROCESS:
-        legacy_event->set_instant_event_scope(
+        legacy_event.GetOrCreate()->set_instant_event_scope(
             TrackEvent::LegacyEvent::SCOPE_PROCESS);
         break;
 
       case TRACE_EVENT_SCOPE_THREAD:
-        legacy_event->set_instant_event_scope(
+        legacy_event.GetOrCreate()->set_instant_event_scope(
             TrackEvent::LegacyEvent::SCOPE_THREAD);
         break;
     }
@@ -439,13 +469,13 @@ void TrackEventThreadLocalEventSink::PrepareTrackEvent(
                TRACE_EVENT_FLAG_HAS_GLOBAL_ID);
   switch (id_flags) {
     case TRACE_EVENT_FLAG_HAS_ID:
-      legacy_event->set_unscoped_id(trace_event->id());
+      legacy_event.GetOrCreate()->set_unscoped_id(trace_event->id());
       break;
     case TRACE_EVENT_FLAG_HAS_LOCAL_ID:
-      legacy_event->set_local_id(trace_event->id());
+      legacy_event.GetOrCreate()->set_local_id(trace_event->id());
       break;
     case TRACE_EVENT_FLAG_HAS_GLOBAL_ID:
-      legacy_event->set_global_id(trace_event->id());
+      legacy_event.GetOrCreate()->set_global_id(trace_event->id());
       break;
     default:
       break;
@@ -455,44 +485,47 @@ void TrackEventThreadLocalEventSink::PrepareTrackEvent(
   if (!privacy_filtering_enabled_) {
     if (id_flags &&
         trace_event->scope() != trace_event_internal::kGlobalScope) {
-      legacy_event->set_id_scope(trace_event->scope());
+      legacy_event.GetOrCreate()->set_id_scope(trace_event->scope());
     }
   }
 
   if (flags & TRACE_EVENT_FLAG_ASYNC_TTS) {
-    legacy_event->set_use_async_tts(true);
+    legacy_event.GetOrCreate()->set_use_async_tts(true);
   }
 
   uint32_t flow_flags =
       flags & (TRACE_EVENT_FLAG_FLOW_OUT | TRACE_EVENT_FLAG_FLOW_IN);
   switch (flow_flags) {
     case TRACE_EVENT_FLAG_FLOW_OUT | TRACE_EVENT_FLAG_FLOW_IN:
-      legacy_event->set_flow_direction(TrackEvent::LegacyEvent::FLOW_INOUT);
+      legacy_event.GetOrCreate()->set_flow_direction(
+          TrackEvent::LegacyEvent::FLOW_INOUT);
       break;
     case TRACE_EVENT_FLAG_FLOW_OUT:
-      legacy_event->set_flow_direction(TrackEvent::LegacyEvent::FLOW_OUT);
+      legacy_event.GetOrCreate()->set_flow_direction(
+          TrackEvent::LegacyEvent::FLOW_OUT);
       break;
     case TRACE_EVENT_FLAG_FLOW_IN:
-      legacy_event->set_flow_direction(TrackEvent::LegacyEvent::FLOW_IN);
+      legacy_event.GetOrCreate()->set_flow_direction(
+          TrackEvent::LegacyEvent::FLOW_IN);
       break;
     default:
       break;
   }
 
   if (flow_flags) {
-    legacy_event->set_bind_id(trace_event->bind_id());
+    legacy_event.GetOrCreate()->set_bind_id(trace_event->bind_id());
   }
 
   if (flags & TRACE_EVENT_FLAG_BIND_TO_ENCLOSING) {
-    legacy_event->set_bind_to_enclosing(true);
+    legacy_event.GetOrCreate()->set_bind_to_enclosing(true);
   }
 
   if ((flags & TRACE_EVENT_FLAG_HAS_PROCESS_ID) &&
       trace_event->process_id() != base::kNullProcessId) {
-    legacy_event->set_pid_override(trace_event->process_id());
-    legacy_event->set_tid_override(-1);
+    legacy_event.GetOrCreate()->set_pid_override(trace_event->process_id());
+    legacy_event.GetOrCreate()->set_tid_override(-1);
   } else if (thread_id_ != trace_event->thread_id()) {
-    legacy_event->set_tid_override(trace_event->thread_id());
+    legacy_event.GetOrCreate()->set_tid_override(trace_event->thread_id());
   }
 
   if (interned_category.id && !interned_category.was_emitted) {