Revert "Perfetto: Stop splitting _COMPLETE events"

This reverts commit 53e8b2a2.

Reason for revert: crbug.com/910704

Original change's description:
> Perfetto: Stop splitting _COMPLETE events
> 
> The current Perfetto backend splits _COMPLETE trace events into
> separate _BEGIN and _END pairs, as it's not very feasible to modify
> existing events after they're written into the Shared Memory Buffers.
> 
> This is causing some issues with the trace-viewer which has some
> assumptions about the ordering of begin/end events vs. async events,
> and is also bloating the sizes of traces and adding extra
> overhead for the perf infra.
> 
> Instead, we now keep the _COMPLETE events in an internal stack in
> TLS and only emit them when we have their duration.
> 
> R=​eseckler@chromium.org,skyostil@chromium.org
> 
> Bug: 909728,888558
> Change-Id: I80e37264de66d8bbcb6c9095d21047957fd6eb9f
> Reviewed-on: https://chromium-review.googlesource.com/c/1354503
> Commit-Queue: oysteine <oysteine@chromium.org>
> Reviewed-by: Eric Seckler <eseckler@chromium.org>
> Reviewed-by: Sami Kyöstilä <skyostil@chromium.org>
> Cr-Commit-Position: refs/heads/master@{#612360}

TBR=oysteine@chromium.org,skyostil@chromium.org,eseckler@chromium.org

Change-Id: I0cda9ab36248042c3889d810bfd07a6d03a6d58e
No-Presubmit: true
No-Tree-Checks: true
No-Try: true
Bug: 909728, 888558
Reviewed-on: https://chromium-review.googlesource.com/c/1357500Reviewed-by: oysteine <oysteine@chromium.org>
Commit-Queue: oysteine <oysteine@chromium.org>
Cr-Commit-Position: refs/heads/master@{#612776}

base/trace_event/trace_log.cc

@@ -328,13 +328,14 @@ void TraceLog::ThreadLocalEventBuffer::FlushWhileLocked() {
   // find the generation mismatch and delete this buffer soon.
 }
 
-void TraceLog::SetAddTraceEventOverrides(
-    const AddTraceEventOverrideCallback& add_event_override,
-    const OnFlushCallback& on_flush_callback,
-    const UpdateDurationCallback& update_duration_callback) {
-  add_trace_event_override_.store(add_event_override);
-  on_flush_callback_.store(on_flush_callback);
-  update_duration_callback_.store(update_duration_callback);
+void TraceLog::SetAddTraceEventOverride(
+    const AddTraceEventOverrideCallback& override,
+    const OnFlushCallback& on_flush_callback) {
+  subtle::NoBarrier_Store(&trace_event_override_,
+                          reinterpret_cast<subtle::AtomicWord>(override));
+  subtle::NoBarrier_Store(
+      &on_flush_callback_,
+      reinterpret_cast<subtle::AtomicWord>(on_flush_callback));
 }
 
 struct TraceLog::RegisteredAsyncObserver {
@@ -379,6 +380,8 @@ TraceLog::TraceLog()
       thread_shared_chunk_index_(0),
       generation_(0),
       use_worker_thread_(false),
+      trace_event_override_(0),
+      on_flush_callback_(0),
       filter_factory_for_testing_(nullptr) {
   CategoryRegistry::Initialize();
 
@@ -1022,7 +1025,8 @@ void TraceLog::FlushCurrentThread(int generation, bool discard_events) {
   // This will flush the thread local buffer.
   delete thread_local_event_buffer_.Get();
 
-  auto on_flush_callback = on_flush_callback_.load(std::memory_order_relaxed);
+  auto on_flush_callback = reinterpret_cast<OnFlushCallback>(
+      subtle::NoBarrier_Load(&on_flush_callback_));
   if (on_flush_callback) {
     on_flush_callback();
   }
@@ -1290,9 +1294,17 @@ TraceEventHandle TraceLog::AddTraceEventWithThreadIdAndTimestamp(
                                   convertable_values);
 #endif  // OS_WIN
 
-  auto trace_event_override =
-      add_trace_event_override_.load(std::memory_order_relaxed);
+  AddTraceEventOverrideCallback trace_event_override =
+      reinterpret_cast<AddTraceEventOverrideCallback>(
+          subtle::NoBarrier_Load(&trace_event_override_));
   if (trace_event_override) {
+    // If we have an override in place for events, rather than sending
+    // them to the tracelog, we don't have a way of going back and updating
+    // the duration of _COMPLETE events. Instead, we emit separate _BEGIN
+    // and _END events.
+    if (phase == TRACE_EVENT_PHASE_COMPLETE)
+      phase = TRACE_EVENT_PHASE_BEGIN;
+
     TraceEvent new_trace_event(thread_id, offset_event_timestamp, thread_now,
                                phase, category_group_enabled, name, scope, id,
                                bind_id, num_args, arg_names, arg_types,
@@ -1300,7 +1312,7 @@ TraceEventHandle TraceLog::AddTraceEventWithThreadIdAndTimestamp(
 
     trace_event_override(
         &new_trace_event,
-        /*thread_will_flush=*/thread_local_event_buffer != nullptr, &handle);
+        /*thread_will_flush=*/thread_local_event_buffer != nullptr);
     return handle;
   }
 
@@ -1488,10 +1500,29 @@ void TraceLog::UpdateTraceEventDurationExplicit(
 #endif  // OS_WIN
 
   if (category_group_enabled_local & TraceCategory::ENABLED_FOR_RECORDING) {
-    auto update_duration_callback =
-        update_duration_callback_.load(std::memory_order_relaxed);
-    if (update_duration_callback) {
-      update_duration_callback(handle, now, thread_now);
+    AddTraceEventOverrideCallback trace_event_override =
+        reinterpret_cast<AddTraceEventOverrideCallback>(
+            subtle::NoBarrier_Load(&trace_event_override_));
+
+    // If we send events off to an override instead of the TraceBuffer,
+    // we don't have way of updating the prior event so we'll emit a
+    // separate _END event instead.
+    if (trace_event_override) {
+      TraceEvent new_trace_event(
+          static_cast<int>(base::PlatformThread::CurrentId()), now, thread_now,
+          TRACE_EVENT_PHASE_END, category_group_enabled, name,
+          trace_event_internal::kGlobalScope,
+          trace_event_internal::kNoId /* id */,
+          trace_event_internal::kNoId /* bind_id */, 0, nullptr, nullptr,
+          nullptr, nullptr, TRACE_EVENT_FLAG_NONE);
+      trace_event_override(
+          &new_trace_event,
+          /*thread_will_flush=*/thread_local_event_buffer_.Get() != nullptr);
+
+#if defined(OS_ANDROID)
+      new_trace_event.SendToATrace();
+#endif
+
       return;
     }
   }
@@ -1532,13 +1563,13 @@ void TraceLog::AddMetadataEventWhileLocked(int thread_id,
                                            const char* metadata_name,
                                            const char* arg_name,
                                            const T& value) {
-  auto trace_event_override =
-      add_trace_event_override_.load(std::memory_order_relaxed);
+  auto trace_event_override = reinterpret_cast<AddTraceEventOverrideCallback>(
+      subtle::NoBarrier_Load(&trace_event_override_));
   if (trace_event_override) {
     TraceEvent trace_event;
     InitializeMetadataEvent(&trace_event, thread_id, metadata_name, arg_name,
                             value);
-    trace_event_override(&trace_event, /*thread_will_flush=*/true, nullptr);
+    trace_event_override(&trace_event, /*thread_will_flush=*/true);
   } else {
     InitializeMetadataEvent(
         AddEventToThreadSharedChunkWhileLocked(nullptr, false), thread_id,
@@ -1549,14 +1580,14 @@ void TraceLog::AddMetadataEventWhileLocked(int thread_id,
 void TraceLog::AddMetadataEventsWhileLocked() {
   lock_.AssertAcquired();
 
-  auto trace_event_override =
-      add_trace_event_override_.load(std::memory_order_relaxed);
+  auto trace_event_override = reinterpret_cast<AddTraceEventOverrideCallback>(
+      subtle::NoBarrier_Load(&trace_event_override_));
 
   // Move metadata added by |AddMetadataEvent| into the trace log.
   if (trace_event_override) {
     while (!metadata_events_.empty()) {
       trace_event_override(metadata_events_.back().get(),
-                           /*thread_will_flush=*/true, nullptr);
+                           /*thread_will_flush=*/true);
       metadata_events_.pop_back();
     }
   } else {

base/trace_event/trace_log.h

@@ -8,7 +8,6 @@
 #include <stddef.h>
 #include <stdint.h>
 
-#include <atomic>
 #include <memory>
 #include <string>
 #include <unordered_map>
@@ -187,20 +186,14 @@ class BASE_EXPORT TraceLog : public MemoryDumpProvider {
   // Cancels tracing and discards collected data.
   void CancelTracing(const OutputCallback& cb);
 
-  using AddTraceEventOverrideCallback = void (*)(TraceEvent*,
-                                                 bool thread_will_flush,
-                                                 TraceEventHandle* handle);
-  using OnFlushCallback = void (*)();
-  using UpdateDurationCallback = void (*)(TraceEventHandle handle,
-                                          const TimeTicks& now,
-                                          const ThreadTicks& thread_now);
-  // The callbacks will be called up until the point where the flush is
+  typedef void (*AddTraceEventOverrideCallback)(TraceEvent*,
+                                                bool thread_will_flush);
+  typedef void (*OnFlushCallback)();
+  // The callback will be called up until the point where the flush is
   // finished, i.e. must be callable until OutputCallback is called with
   // has_more_events==false.
-  void SetAddTraceEventOverrides(
-      const AddTraceEventOverrideCallback& add_event_override,
-      const OnFlushCallback& on_flush_callback,
-      const UpdateDurationCallback& update_duration_callback);
+  void SetAddTraceEventOverride(const AddTraceEventOverrideCallback& override,
+                                const OnFlushCallback& on_flush_callback);
 
   // Called by TRACE_EVENT* macros, don't call this directly.
   // The name parameter is a category group for example:
@@ -555,9 +548,8 @@ class BASE_EXPORT TraceLog : public MemoryDumpProvider {
   ArgumentFilterPredicate argument_filter_predicate_;
   subtle::AtomicWord generation_;
   bool use_worker_thread_;
-  std::atomic<AddTraceEventOverrideCallback> add_trace_event_override_;
-  std::atomic<OnFlushCallback> on_flush_callback_;
-  std::atomic<UpdateDurationCallback> update_duration_callback_;
+  subtle::AtomicWord trace_event_override_;
+  subtle::AtomicWord on_flush_callback_;
 
   FilterFactoryForTesting filter_factory_for_testing_;
 

base/trace_event/traced_value.cc

@@ -435,7 +435,7 @@ class PickleWriter final : public TracedValue::Writer {
 
 std::unique_ptr<TracedValue::Writer> CreateWriter(size_t capacity) {
   TracedValue::WriterFactoryCallback callback =
-      g_writer_factory_callback.load(std::memory_order_relaxed);
+      g_writer_factory_callback.load();
   if (callback) {
     return callback(capacity);
   }

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

@@ -4,7 +4,6 @@
 
 #include "services/tracing/public/cpp/perfetto/trace_event_data_source.h"
 
-#include <atomic>
 #include <map>
 #include <utility>
 
@@ -12,9 +11,7 @@
 #include "base/memory/ref_counted_memory.h"
 #include "base/no_destructor.h"
 #include "base/process/process_handle.h"
-#include "base/trace_event/trace_buffer.h"
 #include "base/trace_event/trace_event.h"
-#include "build/build_config.h"
 #include "services/tracing/public/cpp/perfetto/traced_value_proto_writer.h"
 #include "services/tracing/public/mojom/constants.mojom.h"
 #include "third_party/perfetto/include/perfetto/tracing/core/shared_memory_arbiter.h"
@@ -28,14 +25,6 @@ using TraceConfig = base::trace_event::TraceConfig;
 
 namespace {
 static const size_t kMaxEventsPerMessage = 100;
-static const size_t kMaxCompleteEventDepth = 20;
-
-// To mark TraceEvent handles that have been added by Perfetto,
-// we use the chunk index so high that TraceLog would've asserted
-// at this point anyway.
-static const uint32_t kMagicChunkIndex =
-    base::trace_event::TraceBufferChunk::kMaxChunkIndex;
-
 }  // namespace
 
 namespace tracing {
@@ -119,12 +108,7 @@ class TraceEventDataSource::ThreadLocalEventSink {
   ThreadLocalEventSink(std::unique_ptr<perfetto::TraceWriter> trace_writer,
                        bool thread_will_flush)
       : trace_writer_(std::move(trace_writer)),
-        thread_will_flush_(thread_will_flush) {
-#if DCHECK_IS_ON()
-    static std::atomic<int32_t> id_counter(1);
-    sink_id_ = id_counter.fetch_add(1, std::memory_order_relaxed);
-#endif  // DCHECK_IS_ON()
-  }
+        thread_will_flush_(thread_will_flush) {}
 
   ~ThreadLocalEventSink() {
     // Finalize the current message before posting the |trace_writer_| for
@@ -187,8 +171,7 @@ class TraceEventDataSource::ThreadLocalEventSink {
     arg->set_json_value(json.c_str());
   }
 
-  void AddTraceEvent(TraceEvent* trace_event,
-                     base::trace_event::TraceEventHandle* handle) {
+  void AddTraceEvent(TraceEvent* trace_event) {
     // TODO(oysteine): Adding trace events to Perfetto will
     // stall in some situations, specifically when we overflow
     // the buffer and need to make a sync call to flush it, and we're
@@ -203,30 +186,6 @@ class TraceEventDataSource::ThreadLocalEventSink {
       return;
     }
 
-    if (handle && trace_event->phase() == TRACE_EVENT_PHASE_COMPLETE) {
-      // 'X' phase events are added through a scoped object and
-      // will have its duration updated when said object drops off
-      // the stack; keep a copy of the event around instead of
-      // writing it into SHM, until we have the duration.
-      // We can't keep the TraceEvent around in the scoped object
-      // itself as that causes a lot more codegen in the callsites
-      // and bloats the binary size too much (due to the increased
-      // sizeof() of the scoped object itself).
-      DCHECK_LT(current_stack_depth_, kMaxCompleteEventDepth);
-      if (current_stack_depth_ >= kMaxCompleteEventDepth) {
-        return;
-      }
-
-#if DCHECK_IS_ON()
-      handle->chunk_seq = sink_id_;
-#endif  // DCHECK_IS_ON()
-
-      complete_event_stack_[current_stack_depth_] = std::move(*trace_event);
-      handle->event_index = ++current_stack_depth_;
-      handle->chunk_index = kMagicChunkIndex;
-      return;
-    }
-
     EnsureValidHandles();
 
     int name_index = 0;
@@ -340,7 +299,15 @@ class TraceEventDataSource::ThreadLocalEventSink {
     }
 
     if (phase == TRACE_EVENT_PHASE_COMPLETE) {
-      new_trace_event->set_duration(trace_event->duration().InMicroseconds());
+      int64_t duration = trace_event->duration().InMicroseconds();
+      if (duration != -1) {
+        new_trace_event->set_duration(duration);
+      } else {
+        // TODO(oysteine): Workaround until TRACE_EVENT_PHASE_COMPLETE can be
+        // split into begin/end pairs. If the duration is -1 and the
+        // trace-viewer will spend forever generating a warning for each event.
+        new_trace_event->set_duration(0);
+      }
 
       if (!trace_event->thread_timestamp().is_null()) {
         int64_t thread_duration =
@@ -383,37 +350,7 @@ class TraceEventDataSource::ThreadLocalEventSink {
     }
   }
 
-  void UpdateDuration(base::trace_event::TraceEventHandle handle,
-                      const base::TimeTicks& now,
-                      const base::ThreadTicks& thread_now) {
-    if (!handle.event_index || handle.chunk_index != kMagicChunkIndex) {
-      return;
-    }
-
-#if DCHECK_IS_ON()
-    DCHECK_EQ(handle.chunk_seq, sink_id_);
-#endif  // DCHECK_IS_ON()
-
-    DCHECK_EQ(handle.event_index, current_stack_depth_);
-    DCHECK_GE(current_stack_depth_, 1u);
-    current_stack_depth_--;
-    complete_event_stack_[current_stack_depth_].UpdateDuration(now, thread_now);
-    AddTraceEvent(&complete_event_stack_[current_stack_depth_], nullptr);
-
-#if defined(OS_ANDROID)
-    complete_event_stack_[current_stack_depth_].SendToATrace();
-#endif
-  }
-
   void Flush() {
-    // TODO(oysteine): This will break events if we flush
-    // while recording. This can't be done on destruction
-    // as this can trigger PostTasks which may not be possible
-    // if the thread is being shut down.
-    while (current_stack_depth_--) {
-      AddTraceEvent(&complete_event_stack_[current_stack_depth_], nullptr);
-    }
-
     event_bundle_ = ChromeEventBundleHandle();
     trace_packet_handle_ = perfetto::TraceWriter::TracePacketHandle();
     trace_writer_->Flush();
@@ -427,11 +364,6 @@ class TraceEventDataSource::ThreadLocalEventSink {
   std::map<intptr_t, int> string_table_;
   int next_string_table_index_ = 0;
   size_t current_eventcount_for_message_ = 0;
-  TraceEvent complete_event_stack_[kMaxCompleteEventDepth];
-  uint32_t current_stack_depth_ = 0;
-#if DCHECK_IS_ON()
-  uint32_t sink_id_;
-#endif  // DCHECK_IS_ON()
 };
 
 namespace {
@@ -473,10 +405,9 @@ void TraceEventDataSource::StartTracing(
 
   RegisterTracedValueProtoWriter(true);
 
-  TraceLog::GetInstance()->SetAddTraceEventOverrides(
+  TraceLog::GetInstance()->SetAddTraceEventOverride(
       &TraceEventDataSource::OnAddTraceEvent,
-      &TraceEventDataSource::FlushCurrentThread,
-      &TraceEventDataSource::OnUpdateDuration);
+      &TraceEventDataSource::FlushCurrentThread);
 
   TraceLog::GetInstance()->SetEnabled(
       TraceConfig(data_source_config.trace_config), TraceLog::RECORDING_MODE);
@@ -494,8 +425,7 @@ void TraceEventDataSource::StopTracing(
         }
 
         RegisterTracedValueProtoWriter(false);
-        TraceLog::GetInstance()->SetAddTraceEventOverrides(nullptr, nullptr,
-                                                           nullptr);
+        TraceLog::GetInstance()->SetAddTraceEventOverride(nullptr, nullptr);
 
         if (data_source->stop_complete_callback_) {
           std::move(data_source->stop_complete_callback_).Run();
@@ -564,10 +494,8 @@ TraceEventDataSource::CreateThreadLocalEventSink(bool thread_will_flush) {
 }
 
 // static
-void TraceEventDataSource::OnAddTraceEvent(
-    TraceEvent* trace_event,
-    bool thread_will_flush,
-    base::trace_event::TraceEventHandle* handle) {
+void TraceEventDataSource::OnAddTraceEvent(TraceEvent* trace_event,
+                                           bool thread_will_flush) {
   auto* thread_local_event_sink =
       static_cast<ThreadLocalEventSink*>(ThreadLocalEventSinkSlot()->Get());
 
@@ -578,19 +506,7 @@ void TraceEventDataSource::OnAddTraceEvent(
   }
 
   if (thread_local_event_sink) {
-    thread_local_event_sink->AddTraceEvent(trace_event, handle);
-  }
-}
-
-// static
-void TraceEventDataSource::OnUpdateDuration(
-    base::trace_event::TraceEventHandle handle,
-    const base::TimeTicks& now,
-    const base::ThreadTicks& thread_now) {
-  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_local_event_sink->AddTraceEvent(trace_event);
   }
 }
 
@@ -600,9 +516,6 @@ void TraceEventDataSource::FlushCurrentThread() {
       static_cast<ThreadLocalEventSink*>(ThreadLocalEventSinkSlot()->Get());
   if (thread_local_event_sink) {
     thread_local_event_sink->Flush();
-    // TODO(oysteine): To support flushing while still recording, this needs to
-    // be changed to not destruct the TLS object as that will emit any
-    // uncompleted _COMPLETE events on the stack.
     delete thread_local_event_sink;
     ThreadLocalEventSinkSlot()->Set(nullptr);
   }

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

@@ -85,11 +85,7 @@ class COMPONENT_EXPORT(TRACING_CPP) TraceEventDataSource
 
   // Callback from TraceLog, can be called from any thread.
   static void OnAddTraceEvent(base::trace_event::TraceEvent* trace_event,
-                              bool thread_will_flush,
-                              base::trace_event::TraceEventHandle* handle);
-  static void OnUpdateDuration(base::trace_event::TraceEventHandle handle,
-                               const base::TimeTicks& now,
-                               const base::ThreadTicks& thread_now);
+                              bool thread_will_flush);
 
   base::Lock lock_;
   uint32_t target_buffer_ = 0;

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

@@ -548,7 +548,7 @@ TEST_F(TraceEventDataSourceTest, EventWithConvertableArgs) {
   EXPECT_EQ(kArgValue2, trace_args[1].json_value());
 }
 
-TEST_F(TraceEventDataSourceTest, UpdateDurationOfCompleteEvent) {
+TEST_F(TraceEventDataSourceTest, CompleteTraceEventsIntoSeparateBeginAndEnd) {
   static const char kEventName[] = "bar";
 
   CreateTraceEventDataSource();
@@ -569,31 +569,23 @@ TEST_F(TraceEventDataSourceTest, UpdateDurationOfCompleteEvent) {
 
   base::trace_event::TraceLog::GetInstance()->UpdateTraceEventDurationExplicit(
       category_group_enabled, kEventName, handle,
-      base::TimeTicks() + base::TimeDelta::FromMicroseconds(30),
+      base::TimeTicks() + base::TimeDelta::FromMicroseconds(20),
       base::ThreadTicks() + base::TimeDelta::FromMicroseconds(50));
 
-  // The call to UpdateTraceEventDurationExplicit should have successfully
-  // updated the duration of the event which was added in the
-  // AddTraceEventWithThreadIdAndTimestamp call.
+  // TRACE_EVENT_PHASE_COMPLETE events should internally emit a
+  // TRACE_EVENT_PHASE_BEGIN event first, and then a TRACE_EVENT_PHASE_END event
+  // when the duration is attempted set on the first event.
   auto events = producer_client()->GetChromeTraceEvents(0);
-  EXPECT_EQ(events.size(), 1);
+  EXPECT_EQ(events.size(), 2);
 
-  auto trace_event = events[0];
-  EXPECT_EQ(TRACE_EVENT_PHASE_COMPLETE, trace_event.phase());
-  EXPECT_EQ(10, trace_event.timestamp());
-  EXPECT_EQ(20, trace_event.duration());
+  auto begin_trace_event = events[0];
+  EXPECT_EQ(TRACE_EVENT_PHASE_BEGIN, begin_trace_event.phase());
+  EXPECT_EQ(10, begin_trace_event.timestamp());
 
-  // Updating the duration of an invalid event should cause no further events to
-  // be emitted.
-  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));
-
-  auto new_events = producer_client()->GetChromeTraceEvents(0);
-  EXPECT_EQ(new_events.size(), 1);
+  auto end_trace_event = events[1];
+  EXPECT_EQ(TRACE_EVENT_PHASE_END, end_trace_event.phase());
+  EXPECT_EQ(20, end_trace_event.timestamp());
+  EXPECT_EQ(50, end_trace_event.thread_timestamp());
 }
 
 }  // namespace