[tracing] Fix races in TracingController implementation

The default TracingController (used by d8 and Node) has some concurrency
issues. The new test flushes these out, when a second thread logs trace
events while the main thread calls StopTracing().

- Use an acquire load in UpdateCategoryGroupEnabledFlags() because this
  was racing with GetCategoryGroupEnabled() where a new category is
  added in the slow path. g_category_groups is append-only, but
  reads/writes to g_category_index need to be correctly ordered so that
  new categories are added and only then is the change to the index
  visible. The relaxed load ignored this and caused unsynchronized
  read/write.
- Use a relaxed load in ~ScopedTracer() to access category_group_enabled
  as this previously used a non-atomic operation which caused a race
  with UpdateCategoryGroupEnabledFlag() which does a relaxed store.
- Replace TracingController::mode_ with an atomic bool as read/writes to
  mode_ were not synchronized and caused TSAN errors. It only has two
  states and it doesn't seem like we will extend this so just convert it
  to bool.
- Take the lock around calling trace_object->Initialize in
  AddTraceEvent(), and around trace_buffer_->Flush() in StopTracing().
  These two raced previously as the underlying TraceBufferRingBuffer
  passes out pointers to TraceObjects in a synchronized way, but the
  caller (AddTraceEvent) then writes into the object without
  synchronization. This leads to races when Flush() is called, at which
  time TraceBufferRingBuffer assumes that all the pointers it handed out
  are to valid, initialized TraceObjects - which is not true because
  AddTraceEvent may still be calling Initialize on them. This could be
  the cause of issues in Node.js where the last line of tracing/logging
  sometimes gets cut off. This is kind of a band-aid solution - access
  to the TraceObjects handed out by the ring buffer really needs proper
  synchronization which at this point would require redesign. It's quite
  likely we will replace this with Perfetto in the near future so not
  much point investing in this code right now.
- Enable TracingCpuProfiler test which was flaky due to these bugs.

Bug: v8:8821
Change-Id: I141296800c6906ac0e7f3f21dd16d861b07dae62
Reviewed-on: https://chromium-review.googlesource.com/c/1477283
Commit-Queue: Peter Marshall <petermarshall@chromium.org>
Reviewed-by: Yang Guo <yangguo@chromium.org>
Reviewed-by: Ali Ijaz Sheikh <ofrobots@google.com>
Cr-Commit-Position: refs/heads/master@{#59752}

include/libplatform/v8-tracing.h

@@ -5,6 +5,7 @@
 #ifndef V8_LIBPLATFORM_V8_TRACING_H_
 #define V8_LIBPLATFORM_V8_TRACING_H_
 
+#include <atomic>
 #include <fstream>
 #include <memory>
 #include <unordered_set>
@@ -221,8 +222,6 @@ class V8_PLATFORM_EXPORT TraceConfig {
 class V8_PLATFORM_EXPORT TracingController
     : public V8_PLATFORM_NON_EXPORTED_BASE(v8::TracingController) {
  public:
-  enum Mode { DISABLED = 0, RECORDING_MODE };
-
   // The pointer returned from GetCategoryGroupEnabled() points to a value with
   // zero or more of the following bits. Used in this class only. The
   // TRACE_EVENT macros should only use the value as a bool. These values must
@@ -280,7 +279,7 @@ class V8_PLATFORM_EXPORT TracingController
   std::unique_ptr<TraceConfig> trace_config_;
   std::unique_ptr<base::Mutex> mutex_;
   std::unordered_set<v8::TracingController::TraceStateObserver*> observers_;
-  Mode mode_ = DISABLED;
+  std::atomic_bool recording_{false};
 
   // Disallow copy and assign
   TracingController(const TracingController&) = delete;

src/libplatform/tracing/tracing-controller.cc

@@ -78,13 +78,16 @@ uint64_t TracingController::AddTraceEvent(
     std::unique_ptr<v8::ConvertableToTraceFormat>* arg_convertables,
     unsigned int flags) {
   uint64_t handle = 0;
-  if (mode_ != DISABLED) {
+  if (recording_.load(std::memory_order_acquire)) {
     TraceObject* trace_object = trace_buffer_->AddTraceEvent(&handle);
     if (trace_object) {
-      trace_object->Initialize(
-          phase, category_enabled_flag, name, scope, id, bind_id, num_args,
-          arg_names, arg_types, arg_values, arg_convertables, flags,
-          CurrentTimestampMicroseconds(), CurrentCpuTimestampMicroseconds());
+      {
+        base::MutexGuard lock(mutex_.get());
+        trace_object->Initialize(
+            phase, category_enabled_flag, name, scope, id, bind_id, num_args,
+            arg_names, arg_types, arg_values, arg_convertables, flags,
+            CurrentTimestampMicroseconds(), CurrentCpuTimestampMicroseconds());
+      }
     }
   }
   return handle;
@@ -98,13 +101,16 @@ uint64_t TracingController::AddTraceEventWithTimestamp(
     std::unique_ptr<v8::ConvertableToTraceFormat>* arg_convertables,
     unsigned int flags, int64_t timestamp) {
   uint64_t handle = 0;
-  if (mode_ != DISABLED) {
+  if (recording_.load(std::memory_order_acquire)) {
     TraceObject* trace_object = trace_buffer_->AddTraceEvent(&handle);
     if (trace_object) {
-      trace_object->Initialize(phase, category_enabled_flag, name, scope, id,
-                               bind_id, num_args, arg_names, arg_types,
-                               arg_values, arg_convertables, flags, timestamp,
-                               CurrentCpuTimestampMicroseconds());
+      {
+        base::MutexGuard lock(mutex_.get());
+        trace_object->Initialize(phase, category_enabled_flag, name, scope, id,
+                                 bind_id, num_args, arg_names, arg_types,
+                                 arg_values, arg_convertables, flags, timestamp,
+                                 CurrentCpuTimestampMicroseconds());
+      }
     }
   }
   return handle;
@@ -139,7 +145,7 @@ void TracingController::StartTracing(TraceConfig* trace_config) {
   std::unordered_set<v8::TracingController::TraceStateObserver*> observers_copy;
   {
     base::MutexGuard lock(mutex_.get());
-    mode_ = RECORDING_MODE;
+    recording_.store(true, std::memory_order_release);
     UpdateCategoryGroupEnabledFlags();
     observers_copy = observers_;
   }
@@ -149,11 +155,11 @@ void TracingController::StartTracing(TraceConfig* trace_config) {
 }
 
 void TracingController::StopTracing() {
-  if (mode_ == DISABLED) {
+  bool expected = true;
+  if (!recording_.compare_exchange_strong(expected, false)) {
     return;
   }
   DCHECK(trace_buffer_);
-  mode_ = DISABLED;
   UpdateCategoryGroupEnabledFlags();
   std::unordered_set<v8::TracingController::TraceStateObserver*> observers_copy;
   {
@@ -163,13 +169,16 @@ void TracingController::StopTracing() {
   for (auto o : observers_copy) {
     o->OnTraceDisabled();
   }
-  trace_buffer_->Flush();
+  {
+    base::MutexGuard lock(mutex_.get());
+    trace_buffer_->Flush();
+  }
 }
 
 void TracingController::UpdateCategoryGroupEnabledFlag(size_t category_index) {
   unsigned char enabled_flag = 0;
   const char* category_group = g_category_groups[category_index];
-  if (mode_ == RECORDING_MODE &&
+  if (recording_.load(std::memory_order_acquire) &&
       trace_config_->IsCategoryGroupEnabled(category_group)) {
     enabled_flag |= ENABLED_FOR_RECORDING;
   }
@@ -178,7 +187,8 @@ void TracingController::UpdateCategoryGroupEnabledFlag(size_t category_index) {
   // TODO(primiano): this is a temporary workaround for catapult:#2341,
   // to guarantee that metadata events are always added even if the category
   // filter is "-*". See crbug.com/618054 for more details and long-term fix.
-  if (mode_ == RECORDING_MODE && !strcmp(category_group, "__metadata")) {
+  if (recording_.load(std::memory_order_acquire) &&
+      !strcmp(category_group, "__metadata")) {
     enabled_flag |= ENABLED_FOR_RECORDING;
   }
 
@@ -188,7 +198,7 @@ void TracingController::UpdateCategoryGroupEnabledFlag(size_t category_index) {
 }
 
 void TracingController::UpdateCategoryGroupEnabledFlags() {
-  size_t category_index = base::Relaxed_Load(&g_category_index);
+  size_t category_index = base::Acquire_Load(&g_category_index);
   for (size_t i = 0; i < category_index; i++) UpdateCategoryGroupEnabledFlag(i);
 }
 
@@ -248,7 +258,7 @@ void TracingController::AddTraceStateObserver(
   {
     base::MutexGuard lock(mutex_.get());
     observers_.insert(observer);
-    if (mode_ != RECORDING_MODE) return;
+    if (!recording_.load(std::memory_order_acquire)) return;
   }
   // Fire the observer if recording is already in progress.
   observer->OnTraceEnabled();

src/tracing/trace-event.h

@@ -646,9 +646,11 @@ class ScopedTracer {
   ScopedTracer() : p_data_(nullptr) {}
 
   ~ScopedTracer() {
-    if (p_data_ && *data_.category_group_enabled)
+    if (p_data_ && base::Relaxed_Load(reinterpret_cast<const base::Atomic8*>(
+                       data_.category_group_enabled))) {
       TRACE_EVENT_API_UPDATE_TRACE_EVENT_DURATION(
           data_.category_group_enabled, data_.name, data_.event_handle);
+    }
   }
 
   void Initialize(const uint8_t* category_group_enabled, const char* name,

test/cctest/cctest.status

@@ -90,7 +90,6 @@
   'test-cpu-profiler/JsNativeJsSample': [SKIP],
   'test-cpu-profiler/NativeAccessorUninitializedIC': [SKIP],
   'test-cpu-profiler/SampleWhenFrameIsNotSetup': [SKIP],
-  'test-cpu-profiler/TracingCpuProfiler': [SKIP],
   'test-sampler/LibSamplerCollectSample': [SKIP],
 
   # BUG(7202). The test is flaky.

test/cctest/libplatform/test-tracing.cc

@@ -4,6 +4,7 @@
 #include <limits>
 
 #include "include/libplatform/v8-tracing.h"
+#include "src/base/platform/platform.h"
 #include "src/libplatform/default-platform.h"
 #include "src/tracing/trace-event.h"
 #include "test/cctest/cctest.h"
@@ -439,6 +440,59 @@ TEST(TracingObservers) {
   i::V8::SetPlatformForTesting(old_platform);
 }
 
+class TraceWritingThread : public base::Thread {
+ public:
+  TraceWritingThread(
+      v8::platform::tracing::TracingController* tracing_controller)
+      : base::Thread(base::Thread::Options("TraceWritingThread")),
+        tracing_controller_(tracing_controller) {}
+
+  void Run() override {
+    for (int i = 0; i < 1000; i++) {
+      TRACE_EVENT0("v8", "v8.Test");
+      tracing_controller_->AddTraceEvent('A', nullptr, "v8", "", 1, 1, 0,
+                                         nullptr, nullptr, nullptr, nullptr, 0);
+      tracing_controller_->AddTraceEventWithTimestamp('A', nullptr, "v8", "", 1,
+                                                      1, 0, nullptr, nullptr,
+                                                      nullptr, nullptr, 0, 0);
+      base::OS::Sleep(base::TimeDelta::FromMilliseconds(1));
+    }
+  }
+
+ private:
+  v8::platform::tracing::TracingController* tracing_controller_;
+};
+
+TEST(AddTraceEventMultiThreaded) {
+  v8::Platform* old_platform = i::V8::GetCurrentPlatform();
+  std::unique_ptr<v8::Platform> default_platform(
+      v8::platform::NewDefaultPlatform());
+  i::V8::SetPlatformForTesting(default_platform.get());
+
+  auto tracing = base::make_unique<v8::platform::tracing::TracingController>();
+  v8::platform::tracing::TracingController* tracing_controller = tracing.get();
+  static_cast<v8::platform::DefaultPlatform*>(default_platform.get())
+      ->SetTracingController(std::move(tracing));
+
+  MockTraceWriter* writer = new MockTraceWriter();
+  TraceBuffer* ring_buffer =
+      TraceBuffer::CreateTraceBufferRingBuffer(1, writer);
+  tracing_controller->Initialize(ring_buffer);
+  TraceConfig* trace_config = new TraceConfig();
+  trace_config->AddIncludedCategory("v8");
+  tracing_controller->StartTracing(trace_config);
+
+  TraceWritingThread thread(tracing_controller);
+  thread.StartSynchronously();
+
+  base::OS::Sleep(base::TimeDelta::FromMilliseconds(100));
+  tracing_controller->StopTracing();
+
+  thread.Join();
+
+  i::V8::SetPlatformForTesting(old_platform);
+}
+
 }  // namespace tracing
 }  // namespace platform
 }  // namespace v8