[tracing] Convert COMPLETE events to BEGIN/END pairs for perfetto

COMPLETE events are being deprecated and don't work well with perfetto
because we can't give out a handle into the buffer like we used to so
that the caller can update the existing event with the duration.

BEGIN/END pairs should be used instead to add two separate trace events
to the buffer which can be associated with one another by the trace
processor e.g. the trace viewer UI.

Cq-Include-Trybots: luci.v8.try:v8_linux64_perfetto_dbg_ng
Bug: v8:8339
Change-Id: Ib73c19d77ad58456ce23d15f0b658c26f3dc3d53
Reviewed-on: https://chromium-review.googlesource.com/c/v8/v8/+/1615257Reviewed-by: Jakob Gruber <jgruber@chromium.org>
Commit-Queue: Peter Marshall <petermarshall@chromium.org>
Cr-Commit-Position: refs/heads/master@{#61641}

src/libplatform/tracing/tracing-controller.cc

@@ -158,6 +158,10 @@ uint64_t TracingController::AddTraceEventWithTimestamp(
 
 #ifdef V8_USE_PERFETTO
   if (perfetto_recording_.load()) {
+    // Don't use COMPLETE events with perfetto - instead transform them into
+    // BEGIN/END pairs. This avoids the need for a thread-local stack of pending
+    // trace events as perfetto does not support handles into the trace buffer.
+    if (phase == TRACE_EVENT_PHASE_COMPLETE) phase = TRACE_EVENT_PHASE_BEGIN;
     ::perfetto::TraceWriter* writer =
         perfetto_tracing_controller_->GetOrCreateThreadLocalWriter();
     // TODO(petermarshall): We shouldn't start one packet for each event.
@@ -168,9 +172,6 @@ uint64_t TracingController::AddTraceEventWithTimestamp(
 
     trace_event->set_name(name);
     trace_event->set_timestamp(timestamp);
-    // TODO(petermarshall): Deal with instant (X) vs B/E events. Need to return
-    // a handle that can be used to edit the event in
-    // UpdateTraceEventDuration().
     trace_event->set_phase(phase);
     trace_event->set_thread_id(base::OS::GetCurrentThreadId());
     trace_event->set_duration(0);
@@ -222,25 +223,20 @@ void TracingController::UpdateTraceEventDuration(
   if (perfetto_recording_.load()) {
     // TODO(petermarshall): We shouldn't start one packet for each event. We
     // should try to bundle them together in one bundle.
-    auto* writer = perfetto_tracing_controller_->GetOrCreateThreadLocalWriter();
+    ::perfetto::TraceWriter* writer =
+        perfetto_tracing_controller_->GetOrCreateThreadLocalWriter();
 
     auto packet = writer->NewTracePacket();
     auto* trace_event_bundle = packet->set_chrome_events();
     auto* trace_event = trace_event_bundle->add_trace_events();
 
-    // TODO(petermarshall): Properly deal with begin/end events by using a
-    // thread-local stack of pending events like
-    // chrome_bundle_thread_local_event_sink.cc does.
-    trace_event->set_phase('E');
-    if (category_enabled_flag) {
-      const char* category_group_name =
-          GetCategoryGroupName(category_enabled_flag);
-      DCHECK_NOT_NULL(category_group_name);
-      trace_event->set_category_group_name(category_group_name);
-    }
-    trace_event->set_name(name);
+    trace_event->set_phase(TRACE_EVENT_PHASE_END);
+    trace_event->set_thread_id(base::OS::GetCurrentThreadId());
     trace_event->set_timestamp(now_us);
+    trace_event->set_process_id(base::OS::GetCurrentProcessId());
     trace_event->set_thread_timestamp(cpu_now_us);
+
+    packet->Finalize();
   }
 #endif  // V8_USE_PERFETTO
 

test/cctest/libplatform/test-tracing.cc

@@ -286,43 +286,45 @@ TEST(TestTracingControllerMultipleArgsAndCopy) {
     trace_config->AddIncludedCategory("v8");
     tracing_controller->StartTracing(trace_config);
 
-    TRACE_EVENT1("v8", "v8.Test.aa", "aa", aa);
-    TRACE_EVENT1("v8", "v8.Test.bb", "bb", bb);
-    TRACE_EVENT1("v8", "v8.Test.cc", "cc", cc);
-    TRACE_EVENT1("v8", "v8.Test.dd", "dd", dd);
-    TRACE_EVENT1("v8", "v8.Test.ee", "ee", ee);
-    TRACE_EVENT1("v8", "v8.Test.ff", "ff", ff);
-    TRACE_EVENT1("v8", "v8.Test.gg", "gg", gg);
-    TRACE_EVENT1("v8", "v8.Test.hh", "hh", hh);
-    TRACE_EVENT1("v8", "v8.Test.ii", "ii1", ii1);
-    TRACE_EVENT1("v8", "v8.Test.ii", "ii2", ii2);
-    TRACE_EVENT1("v8", "v8.Test.jj1", "jj1", jj1);
-    TRACE_EVENT1("v8", "v8.Test.jj2", "jj2", jj2);
-    TRACE_EVENT1("v8", "v8.Test.jj3", "jj3", jj3);
-    TRACE_EVENT1("v8", "v8.Test.jj4", "jj4", jj4);
-    TRACE_EVENT1("v8", "v8.Test.jj5", "jj5", jj5);
-    TRACE_EVENT1("v8", "v8.Test.kk", "kk", kk);
-    TRACE_EVENT1("v8", "v8.Test.ll", "ll", ll);
-    TRACE_EVENT1("v8", "v8.Test.mm", "mm", TRACE_STR_COPY(mmm.c_str()));
-
-    TRACE_EVENT2("v8", "v8.Test2.1", "aa", aa, "ll", ll);
-    TRACE_EVENT2("v8", "v8.Test2.2", "mm1", TRACE_STR_COPY(mm.c_str()), "mm2",
-                 TRACE_STR_COPY(mmm.c_str()));
-
-    // Check copies are correct.
-    TRACE_EVENT_COPY_INSTANT0("v8", mm.c_str(), TRACE_EVENT_SCOPE_THREAD);
-    TRACE_EVENT_COPY_INSTANT2("v8", mm.c_str(), TRACE_EVENT_SCOPE_THREAD, "mm1",
-                              mm.c_str(), "mm2", mmm.c_str());
-    mm = "CHANGED";
-    mmm = "CHANGED";
-
-    TRACE_EVENT_INSTANT1("v8", "v8.Test", TRACE_EVENT_SCOPE_THREAD, "a1",
-                         new ConvertableToTraceFormatMock(42));
-    std::unique_ptr<ConvertableToTraceFormatMock> trace_event_arg(
-        new ConvertableToTraceFormatMock(42));
-    TRACE_EVENT_INSTANT2("v8", "v8.Test", TRACE_EVENT_SCOPE_THREAD, "a1",
-                         std::move(trace_event_arg), "a2",
-                         new ConvertableToTraceFormatMock(123));
+    {
+      TRACE_EVENT1("v8", "v8.Test.aa", "aa", aa);
+      TRACE_EVENT1("v8", "v8.Test.bb", "bb", bb);
+      TRACE_EVENT1("v8", "v8.Test.cc", "cc", cc);
+      TRACE_EVENT1("v8", "v8.Test.dd", "dd", dd);
+      TRACE_EVENT1("v8", "v8.Test.ee", "ee", ee);
+      TRACE_EVENT1("v8", "v8.Test.ff", "ff", ff);
+      TRACE_EVENT1("v8", "v8.Test.gg", "gg", gg);
+      TRACE_EVENT1("v8", "v8.Test.hh", "hh", hh);
+      TRACE_EVENT1("v8", "v8.Test.ii", "ii1", ii1);
+      TRACE_EVENT1("v8", "v8.Test.ii", "ii2", ii2);
+      TRACE_EVENT1("v8", "v8.Test.jj1", "jj1", jj1);
+      TRACE_EVENT1("v8", "v8.Test.jj2", "jj2", jj2);
+      TRACE_EVENT1("v8", "v8.Test.jj3", "jj3", jj3);
+      TRACE_EVENT1("v8", "v8.Test.jj4", "jj4", jj4);
+      TRACE_EVENT1("v8", "v8.Test.jj5", "jj5", jj5);
+      TRACE_EVENT1("v8", "v8.Test.kk", "kk", kk);
+      TRACE_EVENT1("v8", "v8.Test.ll", "ll", ll);
+      TRACE_EVENT1("v8", "v8.Test.mm", "mm", TRACE_STR_COPY(mmm.c_str()));
+
+      TRACE_EVENT2("v8", "v8.Test2.1", "aa", aa, "ll", ll);
+      TRACE_EVENT2("v8", "v8.Test2.2", "mm1", TRACE_STR_COPY(mm.c_str()), "mm2",
+                   TRACE_STR_COPY(mmm.c_str()));
+
+      // Check copies are correct.
+      TRACE_EVENT_COPY_INSTANT0("v8", mm.c_str(), TRACE_EVENT_SCOPE_THREAD);
+      TRACE_EVENT_COPY_INSTANT2("v8", mm.c_str(), TRACE_EVENT_SCOPE_THREAD,
+                                "mm1", mm.c_str(), "mm2", mmm.c_str());
+      mm = "CHANGED";
+      mmm = "CHANGED";
+
+      TRACE_EVENT_INSTANT1("v8", "v8.Test", TRACE_EVENT_SCOPE_THREAD, "a1",
+                           new ConvertableToTraceFormatMock(42));
+      std::unique_ptr<ConvertableToTraceFormatMock> trace_event_arg(
+          new ConvertableToTraceFormatMock(42));
+      TRACE_EVENT_INSTANT2("v8", "v8.Test", TRACE_EVENT_SCOPE_THREAD, "a1",
+                           std::move(trace_event_arg), "a2",
+                           new ConvertableToTraceFormatMock(123));
+    }
 
     tracing_controller->StopTracing();