Thread-local trace-event buffers

base/debug/trace_event_impl.cc

Index: base/debug/trace_event_impl.cc
diff --git a/base/debug/trace_event_impl.cc b/base/debug/trace_event_impl.cc
index cc22424f15e505c96dac6cdc356b404be6e87406..56eaad5a0277592d6b9849e93bcf21c992f5fb3a 100644
--- a/base/debug/trace_event_impl.cc
+++ b/base/debug/trace_event_impl.cc
@@ -14,6 +14,7 @@
 #include "base/format_macros.h"
 #include "base/lazy_instance.h"
 #include "base/memory/singleton.h"
+#include "base/message_loop/message_loop.h"
 #include "base/process/process_metrics.h"
 #include "base/stl_util.h"
 #include "base/strings/string_split.h"
@@ -27,7 +28,6 @@
 #include "base/third_party/dynamic_annotations/dynamic_annotations.h"
 #include "base/threading/platform_thread.h"
 #include "base/threading/thread_id_name_manager.h"
-#include "base/threading/thread_local.h"
 #include "base/time/time.h"
 
 #if defined(OS_WIN)
@@ -48,16 +48,17 @@ BASE_EXPORT TRACE_EVENT_API_ATOMIC_WORD g_trace_state[3];
 namespace base {
 namespace debug {
 
+namespace {
+
 // Controls the number of trace events we will buffer in-memory
 // before throwing them away.
 const size_t kTraceEventBufferSize = 500000;
+const size_t kTraceEventThreadLocalBufferSize = 1024;
 const size_t kTraceEventBatchSize = 1000;
 const size_t kTraceEventInitialBufferSize = 1024;
 
 #define MAX_CATEGORY_GROUPS 100
 
-namespace {
-
 // Parallel arrays g_category_groups and g_category_group_enabled are separate
 // so that a pointer to a member of g_category_group_enabled can be easily
 // converted to an index into g_category_groups. This allows macros to deal
@@ -95,8 +96,6 @@ size_t NextIndex(size_t index) {
   return index;
 }
 
-}  // namespace
-
 class TraceBufferRingBuffer : public TraceBuffer {
  public:
   TraceBufferRingBuffer()
@@ -257,6 +256,8 @@ class TraceBufferDiscardsEvents : public TraceBuffer {
   }
 };
 
+}  // namespace
+
 ////////////////////////////////////////////////////////////////////////////////
 //
 // TraceEvent
@@ -741,6 +742,85 @@ TraceBucketData::~TraceBucketData() {
 //
 ////////////////////////////////////////////////////////////////////////////////
 
+class TraceLog::ThreadLocalEventBuffer
+    : public MessageLoop::DestructionObserver {
+ public:
+  ThreadLocalEventBuffer(TraceLog* trace_log);
+  virtual ~ThreadLocalEventBuffer();
+
+  bool AddEvent(const TraceEvent& event, NotificationHelper* notifier);
+
+ private:
+  // MessageLoop::DestructionObserver
+  virtual void WillDestroyCurrentMessageLoop() OVERRIDE;
+
+  bool FlushWhileLocked(NotificationHelper* notifier);
+
+  void CheckThread() {
+    DCHECK(trace_log_->thread_local_event_buffer_.Get() == this);
+  }
+
+  TraceLog* trace_log_;
+  std::vector<TraceEvent> logged_events_;
+};

[dsinclair, 2013/08/13 21:04:42]

DISABLE_COPY_AND_ASSIGN?

[Xianzhu, 2013/08/14 21:28:33]

Done.

+
+TraceLog::ThreadLocalEventBuffer::ThreadLocalEventBuffer(TraceLog* trace_log)
+    : trace_log_(trace_log) {
+  logged_events_.reserve(kTraceEventThreadLocalBufferSize);
+
+  MessageLoop* message_loop = MessageLoop::current();
+  DCHECK(message_loop);
+  message_loop->AddDestructionObserver(this);
+
+  AutoLock lock(trace_log->lock_);
+  trace_log->thread_message_loops_.insert(message_loop);
+}
+
+TraceLog::ThreadLocalEventBuffer::~ThreadLocalEventBuffer() {
+  CheckThread();
+  NotificationHelper notifier(trace_log_);
+  {
+    AutoLock lock(trace_log_->lock_);
+    FlushWhileLocked(&notifier);
+    trace_log_->thread_message_loops_.erase(MessageLoop::current());
+    if (trace_log_->flush_message_loop_) {
+      trace_log_->flush_message_loop_->PostTask(
+          FROM_HERE,
+          Bind(&TraceLog::FlushNextThreadOrFinish, Unretained(trace_log_)));
+    }
+  }
+  notifier.SendNotificationIfAny();
+  trace_log_->thread_local_event_buffer_.Set(NULL);
+}
+
+bool TraceLog::ThreadLocalEventBuffer::AddEvent(const TraceEvent& event,
+                                         NotificationHelper* notifier) {
+  CheckThread();
+  logged_events_.push_back(event);
+  if (logged_events_.size() >= kTraceEventThreadLocalBufferSize) {
+    AutoLock lock(trace_log_->lock_);
+    return FlushWhileLocked(notifier);
+  }
+  return true;
+}
+
+void TraceLog::ThreadLocalEventBuffer::WillDestroyCurrentMessageLoop() {
+  delete this;
+}
+
+bool TraceLog::ThreadLocalEventBuffer::FlushWhileLocked(
+    NotificationHelper* notifier) {
+  bool success = true;
+  for (size_t i = 0; i < logged_events_.size(); ++i) {
+    success = trace_log_->AddEventToMainBufferWhileLocked(logged_events_[i],
+                                                          notifier);
+    if (!success)
+      break;
+  }
+  logged_events_.resize(0);
+  return success;
+}
+
 TraceLog::NotificationHelper::NotificationHelper(TraceLog* trace_log)
     : trace_log_(trace_log),
       notification_(0) {
@@ -751,6 +831,7 @@ TraceLog::NotificationHelper::~NotificationHelper() {
 
 void TraceLog::NotificationHelper::AddNotificationWhileLocked(
     int notification) {
+  trace_log_->lock_.AssertAcquired();
   if (trace_log_->notification_callback_.is_null())
     return;
   if (notification_ == 0)
@@ -794,16 +875,30 @@ TraceLog::Options TraceLog::TraceOptionsFromString(const std::string& options) {
   return static_cast<Options>(ret);
 }
 
+namespace {
+
+struct EchoToConsoleContext {
+  hash_map<int, std::stack<TimeTicks> > thread_event_start_times;
+  hash_map<std::string, int> thread_colors;
+};
+
+}  // namespace
+
 TraceLog::TraceLog()
     : enable_count_(0),
       num_traces_recorded_(0),
-      event_callback_(NULL),
+      buffer_is_full_(0),
+      event_callback_(0),
       dispatching_to_observer_list_(false),
       process_sort_index_(0),
-      watch_category_(NULL),
+      echo_to_console_context_(0),
+      process_id_hash_(0),
+      process_id_(0),
+      watch_category_(0),
       trace_options_(RECORD_UNTIL_FULL),
       sampling_thread_handle_(0),
-      category_filter_(CategoryFilter::kDefaultCategoryFilterString) {
+      category_filter_(CategoryFilter::kDefaultCategoryFilterString),
+      flush_message_loop_(NULL) {
   // Trace is enabled or disabled on one thread while other threads are
   // accessing the enabled flag. We don't care whether edge-case events are
   // traced or not, so we allow races on the enabled flag to keep the trace
@@ -839,6 +934,7 @@ TraceLog::TraceLog()
 }
 
 TraceLog::~TraceLog() {
+  delete reinterpret_cast<EchoToConsoleContext*>(echo_to_console_context_);
 }
 
 const unsigned char* TraceLog::GetCategoryGroupEnabled(
@@ -961,7 +1057,9 @@ void TraceLog::SetEnabled(const CategoryFilter& category_filter,
 
     if (options != trace_options_) {
       trace_options_ = options;
+      EnableEchoToConsole(options & ECHO_TO_CONSOLE);
       logged_events_.reset(GetTraceBuffer());
+      subtle::NoBarrier_Store(&buffer_is_full_, 0);
     }
 
     if (dispatching_to_observer_list_) {
@@ -1039,7 +1137,7 @@ void TraceLog::SetDisabled() {
     }
 
     category_filter_.Clear();
-    watch_category_ = NULL;
+    subtle::NoBarrier_Store(&watch_category_, 0);
     watch_event_name_ = "";
     UpdateCategoryGroupEnabledFlags();
     AddMetadataEvents();
@@ -1105,22 +1203,58 @@ TraceBuffer* TraceLog::GetTraceBuffer() {
   return new TraceBufferVector();
 }
 
+bool TraceLog::AddEventToMainBufferWhileLocked(const TraceEvent& trace_event,
+                                               NotificationHelper* notifier) {
+  lock_.AssertAcquired();
+  logged_events_->AddEvent(trace_event);
+  if (logged_events_->IsFull()) {
+    subtle::NoBarrier_Store(&buffer_is_full_,
+                            static_cast<subtle::AtomicWord>(1));
+    notifier->AddNotificationWhileLocked(TRACE_BUFFER_FULL);
+    return false;
+  }
+  return true;
+}
+
 void TraceLog::SetEventCallback(EventCallback cb) {
-  AutoLock lock(lock_);
-  event_callback_ = cb;
+  subtle::NoBarrier_Store(&event_callback_,
+                          reinterpret_cast<subtle::AtomicWord>(cb));
 };
 
 void TraceLog::Flush(const TraceLog::OutputCallback& cb) {
   // Ignore memory allocations from here down.
   INTERNAL_TRACE_MEMORY(TRACE_DISABLED_BY_DEFAULT("memory"),
                         TRACE_MEMORY_IGNORE);
+  {
+    AutoLock lock(lock_);
+    DCHECK(!flush_message_loop_);
+    flush_message_loop_ = MessageLoop::current();
+    DCHECK(flush_message_loop_);
+    flush_output_callback_ = cb;
+  }
+  FlushNextThreadOrFinish();
+}
+
+void TraceLog::FlushNextThreadOrFinish() {
   scoped_ptr<TraceBuffer> previous_logged_events;
   {
     AutoLock lock(lock_);
+    hash_set<MessageLoop*>::const_iterator next_message_loop =
+        thread_message_loops_.begin();
+    if (next_message_loop != thread_message_loops_.end()) {
+      (*next_message_loop)->PostTask(
+          FROM_HERE,
+          Bind(&TraceLog::DestroyThreadLocalEventBuffer, Unretained(this)));
+      return;
+    }
+
     previous_logged_events.swap(logged_events_);
     logged_events_.reset(GetTraceBuffer());
+    subtle::NoBarrier_Store(&buffer_is_full_, 0);
   }  // release lock
 
+  flush_message_loop_ = NULL;
+
   while (previous_logged_events->HasMoreEvents()) {
     scoped_refptr<RefCountedString> json_events_str_ptr =
         new RefCountedString();
@@ -1136,10 +1270,15 @@ void TraceLog::Flush(const TraceLog::OutputCallback& cb) {
         break;
     }
 
-    cb.Run(json_events_str_ptr);
+    flush_output_callback_.Run(json_events_str_ptr);
   }
 }
 
+void TraceLog::DestroyThreadLocalEventBuffer() {
+  delete thread_local_event_buffer_.Get();
+  thread_local_event_buffer_.Set(NULL);
+}
+
 void TraceLog::AddTraceEvent(
     char phase,
     const unsigned char* category_group_enabled,
@@ -1178,7 +1317,7 @@ void TraceLog::AddTraceEventWithThreadIdAndTimestamp(
     id ^= process_id_hash_;
 
 #if defined(OS_ANDROID)
-  SendToATrace(phase, GetCategoryGroupName(category_group_enabled), name, id,
+  SendToATrace(phase, category_group_enabled, name, id,
                num_args, arg_names, arg_types, arg_values, convertable_values,
                flags);
 #endif
@@ -1187,13 +1326,22 @@ void TraceLog::AddTraceEventWithThreadIdAndTimestamp(
     return;
 
   TimeTicks now = timestamp - time_offset_;
-  EventCallback event_callback_copy;
 
   NotificationHelper notifier(this);
 
-  // Check and update the current thread name only if the event is for the
-  // current thread to avoid locks in most cases.
+  ThreadLocalEventBuffer* thread_local_event_buffer = NULL;
+
   if (thread_id == static_cast<int>(PlatformThread::CurrentId())) {
+    if (MessageLoop::current()) {
+      thread_local_event_buffer = thread_local_event_buffer_.Get();
+      if (!thread_local_event_buffer) {
+        thread_local_event_buffer = new ThreadLocalEventBuffer(this);
+        thread_local_event_buffer_.Set(thread_local_event_buffer);
+      }
+    }
+
+    // Check and update the current thread name only if the event is for the
+    // current thread to avoid locks in most cases.
     const char* new_name = ThreadIdNameManager::GetInstance()->
         GetName(thread_id);
     // Check if the thread name has been set or changed since the previous
@@ -1203,8 +1351,6 @@ void TraceLog::AddTraceEventWithThreadIdAndTimestamp(
     if (new_name != g_current_thread_name.Get().Get() &&
         new_name && *new_name) {
       g_current_thread_name.Get().Set(new_name);
-
-      AutoLock lock(lock_);
       hash_map<int, std::string>::iterator existing_name =
           thread_names_.find(thread_id);
       if (existing_name == thread_names_.end()) {
@@ -1226,67 +1372,97 @@ void TraceLog::AddTraceEventWithThreadIdAndTimestamp(
     }
   }
 
-  TraceEvent trace_event(thread_id,
-      now, phase, category_group_enabled, name, id,
-      num_args, arg_names, arg_types, arg_values,
-      convertable_values, flags);
+  if (!subtle::NoBarrier_Load(&buffer_is_full_)) {
+    TraceEvent trace_event(thread_id,
+        now, phase, category_group_enabled, name, id,
+        num_args, arg_names, arg_types, arg_values,
+        convertable_values, flags);
 
-  do {
-    AutoLock lock(lock_);
+    if (thread_local_event_buffer) {
+      thread_local_event_buffer->AddEvent(trace_event, &notifier);
+    } else {
+      AutoLock lock(lock_);
+      AddEventToMainBufferWhileLocked(trace_event, &notifier);
+    }
 
-    event_callback_copy = event_callback_;
-    if (logged_events_->IsFull())
-      break;
+    EchoEventToConsoleIfEnabled(trace_event);
+  }
 
-    logged_events_->AddEvent(trace_event);
+  if (reinterpret_cast<const unsigned char*>(subtle::NoBarrier_Load(
+      &watch_category_)) == category_group_enabled) {
+    AutoLock lock(lock_);
+    if (watch_event_name_ == name)
+      notifier.AddNotificationWhileLocked(EVENT_WATCH_NOTIFICATION);
+  }
 
-    if (trace_options_ & ECHO_TO_CONSOLE) {
-      TimeDelta duration;
-      if (phase == TRACE_EVENT_PHASE_END) {
-        duration = timestamp - thread_event_start_times_[thread_id].top();
-        thread_event_start_times_[thread_id].pop();
-      }
+  notifier.SendNotificationIfAny();
+  EventCallback event_callback = reinterpret_cast<EventCallback>(
+      subtle::NoBarrier_Load(&event_callback_));
+  if (event_callback) {
+    event_callback(phase, category_group_enabled, name, id,
+                   num_args, arg_names, arg_types, arg_values,
+                   flags);
+  }
+}
+
+void TraceLog::EnableEchoToConsole(bool enable) {
+  if (enable) {
+    EchoToConsoleContext* new_context = new EchoToConsoleContext();
+    if (subtle::NoBarrier_CompareAndSwap(
+            &echo_to_console_context_, 0,
+            reinterpret_cast<subtle::AtomicWord>(new_context))) {
+      // There is existing context, the new_context is not used.
+      delete new_context;
+    }
+  } else {
+    delete reinterpret_cast<EchoToConsoleContext*>(
+        subtle::NoBarrier_AtomicExchange(&echo_to_console_context_, 0));
+  }
+}
 
-      std::string thread_name = thread_names_[thread_id];
-      if (thread_colors_.find(thread_name) == thread_colors_.end())
-        thread_colors_[thread_name] = (thread_colors_.size() % 6) + 1;
+void TraceLog::EchoEventToConsoleIfEnabled(const TraceEvent& event) {

[dsinclair, 2013/08/13 21:04:42]

Could this, mostly, be moved to it's own CL? Then, this CL would just have the
code where the EchoToConsoleContext was added.

[Xianzhu, 2013/08/14 21:28:33]

Done.

+  EchoToConsoleContext* context = reinterpret_cast<EchoToConsoleContext*>(
+      subtle::NoBarrier_Load(&echo_to_console_context_));
+  if (!context)  // ECHO_TO_CONSOLE not enabled.
+    return;
 
-      std::ostringstream log;
-      log << base::StringPrintf("%s: \x1b[0;3%dm",
-                                thread_name.c_str(),
-                                thread_colors_[thread_name]);
+  AutoLock lock(lock_);
 
-      size_t depth = 0;
-      if (thread_event_start_times_.find(thread_id) !=
-          thread_event_start_times_.end())
-        depth = thread_event_start_times_[thread_id].size();
+  int thread_id = event.thread_id();
+  TimeDelta duration;
+  if (event.phase() == TRACE_EVENT_PHASE_END) {
+    duration = event.timestamp() -
+        context->thread_event_start_times[thread_id].top();
+    context->thread_event_start_times[thread_id].pop();
+  }
 
-      for (size_t i = 0; i < depth; ++i)
-        log << "| ";
+  std::string thread_name = thread_names_[thread_id];
+  if (context->thread_colors.find(thread_name) ==
+      context->thread_colors.end())
+    context->thread_colors[thread_name] =
+        (context->thread_colors.size() % 6) + 1;
 
-      trace_event.AppendPrettyPrinted(&log);
-      if (phase == TRACE_EVENT_PHASE_END)
-        log << base::StringPrintf(" (%.3f ms)", duration.InMillisecondsF());
+  std::ostringstream log;
+  log << base::StringPrintf("%s: \x1b[0;3%dm",
+                            thread_name.c_str(),
+                            context->thread_colors[thread_name]);
 
-      LOG(ERROR) << log.str() << "\x1b[0;m";
+  size_t depth = 0;
+  if (context->thread_event_start_times.find(thread_id) !=
+      context->thread_event_start_times.end())
+    depth = context->thread_event_start_times[thread_id].size();
 
-      if (phase == TRACE_EVENT_PHASE_BEGIN)
-        thread_event_start_times_[thread_id].push(timestamp);
-    }
+  for (size_t i = 0; i < depth; ++i)
+    log << "| ";
 
-    if (logged_events_->IsFull())
-      notifier.AddNotificationWhileLocked(TRACE_BUFFER_FULL);
+  event.AppendPrettyPrinted(&log);
+  if (event.phase() == TRACE_EVENT_PHASE_END)
+    log << base::StringPrintf(" (%.3f ms)", duration.InMillisecondsF());
 
-    if (watch_category_ == category_group_enabled && watch_event_name_ == name)
-      notifier.AddNotificationWhileLocked(EVENT_WATCH_NOTIFICATION);
-  } while (0); // release lock
+  LOG(ERROR) << log.str() << "\x1b[0;m";
 
-  notifier.SendNotificationIfAny();
-  if (event_callback_copy != NULL) {
-    event_callback_copy(phase, category_group_enabled, name, id,
-        num_args, arg_names, arg_types, arg_values,
-        flags);
-  }
+  if (event.phase() == TRACE_EVENT_PHASE_BEGIN)
+    context->thread_event_start_times[thread_id].push(event.timestamp());
 }
 
 void TraceLog::AddTraceEventEtw(char phase,
@@ -1319,7 +1495,8 @@ void TraceLog::SetWatchEvent(const std::string& category_name,
   size_t notify_count = 0;
   {
     AutoLock lock(lock_);
-    watch_category_ = category;
+    subtle::NoBarrier_Store(&watch_category_,
+                            reinterpret_cast<subtle::AtomicWord>(category));
     watch_event_name_ = event_name;
 
     // First, search existing events for watch event because we want to catch
@@ -1339,7 +1516,7 @@ void TraceLog::SetWatchEvent(const std::string& category_name,
 
 void TraceLog::CancelWatchEvent() {
   AutoLock lock(lock_);
-  watch_category_ = NULL;
+  subtle::NoBarrier_Store(&watch_category_, 0);
   watch_event_name_ = "";
 }