Thread-local trace-event buffers

base/debug/trace_event_impl.cc

 // Copyright (c) 2012 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "base/debug/trace_event_impl.h"
 
 #include <algorithm>
 
 #include "base/base_switches.h"
 #include "base/bind.h"
 #include "base/command_line.h"
 #include "base/debug/leak_annotations.h"
 #include "base/debug/trace_event.h"
 #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"
 #include "base/strings/string_tokenizer.h"
 #include "base/strings/string_util.h"
 #include "base/strings/stringprintf.h"
 #include "base/strings/utf_string_conversions.h"
 #include "base/synchronization/cancellation_flag.h"
 #include "base/synchronization/waitable_event.h"
 #include "base/sys_info.h"
 #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)
 #include "base/debug/trace_event_win.h"
 #endif
 
 class DeleteTraceLogForTesting {
  public:
   static void Delete() {
     Singleton<base::debug::TraceLog,
               LeakySingletonTraits<base::debug::TraceLog> >::OnExit(0);
   }
 };
 
 // The thread buckets for the sampling profiler.
 BASE_EXPORT TRACE_EVENT_API_ATOMIC_WORD g_trace_state[3];
 
 namespace base {
 namespace debug {
 
+namespace {
+
+// The overhead of TraceEvent above this threshold will be reported in the
+// trace.
+const int kOverheadReportThresholdInMicroseconds = 5;
+
 // 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
 // only with char enabled pointers from g_category_group_enabled, and we can
 // convert internally to determine the category name from the char enabled
 // pointer.
 const char* g_category_groups[MAX_CATEGORY_GROUPS] = {
   "tracing already shutdown",
   "tracing categories exhausted; must increase MAX_CATEGORY_GROUPS",
   "__metadata",
+  "trace-event-overhead"

[dsinclair, 2013/08/16 14:38:32]

This should probably be disabled-by-default-trace-event-overhead category if
we're always going to be saying it's always available.

[Xianzhu, 2013/08/16 19:41:03]

I'd like let it enabled by default to prevent the user from being surprised when
seeing a trace duration much longer than expected. The extra overhead for
reporting overhead is small.

 };
 
 // The enabled flag is char instead of bool so that the API can be used from C.
 unsigned char g_category_group_enabled[MAX_CATEGORY_GROUPS] = { 0 };
 const int g_category_already_shutdown = 0;
 const int g_category_categories_exhausted = 1;
 const int g_category_metadata = 2;
-const int g_num_builtin_categories = 3;
+const int g_category_trace_event_overhead = 3;
+const int g_num_builtin_categories = 4;
 int g_category_index = g_num_builtin_categories; // Skip default categories.
 
 // The name of the current thread. This is used to decide if the current
 // thread name has changed. We combine all the seen thread names into the
 // output name for the thread.
 LazyInstance<ThreadLocalPointer<const char> >::Leaky
     g_current_thread_name = LAZY_INSTANCE_INITIALIZER;
 
 const char kRecordUntilFull[] = "record-until-full";
 const char kRecordContinuously[] = "record-continuously";
 const char kEnableSampling[] = "enable-sampling";
 
 size_t NextIndex(size_t index) {
   index++;
   if (index >= kTraceEventBufferSize)
     index = 0;
   return index;
 }
 
-}  // namespace
-
 class TraceBufferRingBuffer : public TraceBuffer {
  public:
   TraceBufferRingBuffer()
       : unused_event_index_(0),
         oldest_event_index_(0) {
     logged_events_.reserve(kTraceEventInitialBufferSize);
   }
 
   virtual ~TraceBufferRingBuffer() {}
 
@@ skipping 61 matching lines @@
 class TraceBufferVector : public TraceBuffer {
  public:
   TraceBufferVector() : current_iteration_index_(0) {
     logged_events_.reserve(kTraceEventInitialBufferSize);
   }
 
   virtual ~TraceBufferVector() {
   }
 
   virtual void AddEvent(const TraceEvent& event) OVERRIDE {
-    // Note, we have two callers which need to be handled. The first is
-    // AddTraceEventWithThreadIdAndTimestamp() which checks Size() and does an
-    // early exit if full. The second is AddThreadNameMetadataEvents().
+    // Note, we have two callers which need to be handled:
+    // - AddEventToMainBufferWhileLocked() which has two cases:
+    //   - called directly from AddTraceEventWithThreadIdAndTimeStamp()
+    //     which checks if buffer is full and does an early exit if full;
+    //   - called from ThreadLocalEventBuffer::FlushWhileLocked();
+    // - AddThreadNameMetadataEvents().
     // We can not DECHECK(!IsFull()) because we have to add the metadata
-    // events even if the buffer is full.
+    // events and flush thread-local buffers even if the buffer is full.
     logged_events_.push_back(event);
   }
 
   virtual bool HasMoreEvents() const OVERRIDE {
     return current_iteration_index_ < Size();
   }
 
   virtual const TraceEvent& NextEvent() OVERRIDE {
     DCHECK(HasMoreEvents());
     return GetEventAt(current_iteration_index_++);
@@ skipping 54 matching lines @@
   }
 
   virtual size_t Size() const OVERRIDE { return 0; }
 
   virtual const TraceEvent& GetEventAt(size_t index) const OVERRIDE {
     NOTREACHED();
     return *static_cast<TraceEvent*>(NULL);
   }
 };
 
+// Stores the data that are used when ECHO_TO_CONSOLE is enabled.
+struct EchoToConsoleContext {
+  hash_map<int, std::stack<TimeTicks> > thread_event_start_times;
+  hash_map<std::string, int> thread_colors;
+};
+
+}  // namespace
+
 ////////////////////////////////////////////////////////////////////////////////
 //
 // TraceEvent
 //
 ////////////////////////////////////////////////////////////////////////////////
 
 namespace {
 
 size_t GetAllocLength(const char* str) { return str ? strlen(str) + 1 : 0; }
 
@@ skipping 464 matching lines @@
 
 TraceBucketData::~TraceBucketData() {
 }
 
 ////////////////////////////////////////////////////////////////////////////////
 //
 // TraceLog
 //
 ////////////////////////////////////////////////////////////////////////////////
 
+class TraceLog::ThreadLocalEventBuffer
+    : public MessageLoop::DestructionObserver {
+ public:
+  ThreadLocalEventBuffer(TraceLog* trace_log);
+  virtual ~ThreadLocalEventBuffer();
+
+  void AddEvent(const TraceEvent& event, NotificationHelper* notifier);
+  void ReportOverhead(const TimeTicks& event_timestamp);
+
+ private:
+  // MessageLoop::DestructionObserver
+  virtual void WillDestroyCurrentMessageLoop() OVERRIDE;
+
+  void FlushWhileLocked(NotificationHelper* notifier);
+
+  void CheckThisIsCurrentBuffer() {
+    DCHECK(trace_log_->thread_local_event_buffer_.Get() == this);
+  }
+
+  // Since TraceLog is a leaky singleton, trace_log_ will always be valid
+  // as long as the thread exists.
+  TraceLog* trace_log_;
+  std::vector<TraceEvent> logged_events_;
+  int event_count_;
+  TimeDelta overhead_;
+
+  DISALLOW_COPY_AND_ASSIGN(ThreadLocalEventBuffer);
+};
+
+TraceLog::ThreadLocalEventBuffer::ThreadLocalEventBuffer(TraceLog* trace_log)
+    : trace_log_(trace_log),
+      event_count_(0) {
+  logged_events_.reserve(kTraceEventThreadLocalBufferSize);
+
+  if (g_category_group_enabled[g_category_trace_event_overhead]) {
+    logged_events_.push_back(TraceEvent(
+        static_cast<int>(PlatformThread::CurrentId()),
+        TimeTicks::NowFromSystemTraceTime(),
+        TRACE_EVENT_PHASE_ASYNC_BEGIN,
+        &g_category_group_enabled[g_category_trace_event_overhead],
+        "local-event-buffer",
+        0, 0, NULL, NULL, NULL, NULL, 0));
+  }
+
+  // ThreadLocalEventBuffer is created only if the thread has message loop, so
+  // the following message_loop won't be NULL.
+  MessageLoop* message_loop = MessageLoop::current();
+  message_loop->AddDestructionObserver(this);
+
+  AutoLock lock(trace_log->lock_);
+  trace_log->thread_message_loops_.insert(message_loop);
+}
+
+TraceLog::ThreadLocalEventBuffer::~ThreadLocalEventBuffer() {
+  CheckThisIsCurrentBuffer();
+
+  if (g_category_group_enabled[g_category_trace_event_overhead]) {
+    const char* arg_names[2] = { "event_count", "average_overhead_sec" };
+    unsigned char arg_types[2];
+    unsigned long long arg_values[2];
+    trace_event_internal::SetTraceValue(event_count_,
+                                        &arg_types[0], &arg_values[0]);
+    trace_event_internal::SetTraceValue(overhead_.InSecondsF() / event_count_,

[dsinclair, 2013/08/16 14:38:32]

Why seconds? Do we really expect this to be outside the millisecond range?

[Xianzhu, 2013/08/16 19:41:03]

Done.

+                                        &arg_types[1], &arg_values[1]);
+    logged_events_.push_back(TraceEvent(
+        static_cast<int>(PlatformThread::CurrentId()),
+        TimeTicks::NowFromSystemTraceTime(),
+        TRACE_EVENT_PHASE_ASYNC_END,
+        &g_category_group_enabled[g_category_trace_event_overhead],
+        "local-event-buffer",
+        0,
+        2, arg_names, arg_types, arg_values,
+        NULL, 0));
+  }
+
+  NotificationHelper notifier(trace_log_);
+  {
+    AutoLock lock(trace_log_->lock_);
+    FlushWhileLocked(&notifier);
+    trace_log_->thread_message_loops_.erase(MessageLoop::current());
+  }
+  notifier.SendNotificationIfAny();
+}
+
+void TraceLog::ThreadLocalEventBuffer::AddEvent(const TraceEvent& event,
+                                                NotificationHelper* notifier) {
+  CheckThisIsCurrentBuffer();
+  logged_events_.push_back(event);
+  if (logged_events_.size() >= kTraceEventThreadLocalBufferSize) {
+    AutoLock lock(trace_log_->lock_);
+    FlushWhileLocked(notifier);
+  }
+}
+
+void TraceLog::ThreadLocalEventBuffer::ReportOverhead(
+    const TimeTicks& event_timestamp) {
+  if (g_category_group_enabled[g_category_trace_event_overhead]) {
+    event_count_++;
+    TimeTicks now = TimeTicks::NowFromSystemTraceTime();
+    TimeDelta overhead = now - event_timestamp;
+    if (overhead.InMicroseconds() >= kOverheadReportThresholdInMicroseconds) {
+      int thread_id = static_cast<int>(PlatformThread::CurrentId());
+      // TODO(wangxianzhu): Use X event when it's ready.
+      logged_events_.push_back(TraceEvent(
+          thread_id,
+          event_timestamp,
+          TRACE_EVENT_PHASE_BEGIN,
+          &g_category_group_enabled[g_category_trace_event_overhead],
+          "overhead",
+          0, 0, NULL, NULL, NULL, NULL, 0));
+      logged_events_.push_back(TraceEvent(
+          thread_id,
+          now,
+          TRACE_EVENT_PHASE_END,
+          &g_category_group_enabled[g_category_trace_event_overhead],
+          "overhead",
+          0, 0, NULL, NULL, NULL, NULL, 0));
+    }
+    overhead_ += overhead;
+  }
+}
+
+void TraceLog::ThreadLocalEventBuffer::WillDestroyCurrentMessageLoop() {
+  delete this;
+}
+
+void TraceLog::ThreadLocalEventBuffer::FlushWhileLocked(
+    NotificationHelper* notifier) {
+  trace_log_->lock_.AssertAcquired();
+  for (size_t i = 0; i < logged_events_.size(); ++i) {
+    trace_log_->AddEventToMainBufferWhileLocked(logged_events_[i],
+                                                notifier);
+  }
+  logged_events_.resize(0);
+}
+
 TraceLog::NotificationHelper::NotificationHelper(TraceLog* trace_log)
     : trace_log_(trace_log),
       notification_(0) {
 }
 
 TraceLog::NotificationHelper::~NotificationHelper() {
 }
 
 void TraceLog::NotificationHelper::AddNotificationWhileLocked(
     int notification) {
+  trace_log_->lock_.AssertAcquired();
   if (trace_log_->notification_callback_.is_null())
     return;
   if (notification_ == 0)
     callback_copy_ = trace_log_->notification_callback_;
   notification_ |= notification;
 }
 
 void TraceLog::NotificationHelper::SendNotificationIfAny() {
   if (notification_)
     callback_copy_.Run(notification_);
@@ skipping 26 matching lines @@
   }
   if (!(ret & RECORD_UNTIL_FULL) && !(ret & RECORD_CONTINUOUSLY))
     ret |= RECORD_UNTIL_FULL;  // Default when no options are specified.
 
   return static_cast<Options>(ret);
 }
 
 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
   // macros fast.
   // TODO(jbates): ANNOTATE_BENIGN_RACE_SIZED crashes windows TSAN bots:
   // ANNOTATE_BENIGN_RACE_SIZED(g_category_group_enabled,
   //                            sizeof(g_category_group_enabled),
   //                           "trace_event category enabled");
   for (int i = 0; i < MAX_CATEGORY_GROUPS; ++i) {
     ANNOTATE_BENIGN_RACE(&g_category_group_enabled[i],
@@ skipping 15 matching lines @@
       category_string = "*";
 
     SetEnabled(CategoryFilter(category_string), ECHO_TO_CONSOLE);
   }
 #endif
 
   logged_events_.reset(GetTraceBuffer());
 }
 
 TraceLog::~TraceLog() {
+  delete reinterpret_cast<EchoToConsoleContext*>(echo_to_console_context_);
 }
 
 const unsigned char* TraceLog::GetCategoryGroupEnabled(
     const char* category_group) {
   TraceLog* tracelog = GetInstance();
   if (!tracelog) {
     DCHECK(!g_category_group_enabled[g_category_already_shutdown]);
     return &g_category_group_enabled[g_category_already_shutdown];
   }
   return tracelog->GetCategoryGroupEnabledInternal(category_group);
@@ skipping 79 matching lines @@
       category_group_enabled =
           &g_category_group_enabled[g_category_categories_exhausted];
     }
   }
   return category_group_enabled;
 }
 
 void TraceLog::GetKnownCategoryGroups(
     std::vector<std::string>* category_groups) {
   AutoLock lock(lock_);
+  category_groups->push_back(
+      g_category_groups[g_category_trace_event_overhead]);
   for (int i = g_num_builtin_categories; i < g_category_index; i++)
     category_groups->push_back(g_category_groups[i]);
 }
 
 void TraceLog::SetEnabled(const CategoryFilter& category_filter,
                           Options options) {
   std::vector<EnabledStateObserver*> observer_list;
   {
     AutoLock lock(lock_);
 
     if (enable_count_++ > 0) {
       if (options != trace_options_) {
         DLOG(ERROR) << "Attemting to re-enable tracing with a different "
                     << "set of options.";
       }
 
       category_filter_.Merge(category_filter);
       UpdateCategoryGroupEnabledFlags();
       return;
     }
 
     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_) {
       DLOG(ERROR) <<
           "Cannot manipulate TraceLog::Enabled state from an observer.";
       return;
     }
 
     num_traces_recorded_++;
 
@@ skipping 57 matching lines @@
       // Stop the sampling thread.
       sampling_thread_->Stop();
       lock_.Release();
       PlatformThread::Join(sampling_thread_handle_);
       lock_.Acquire();
       sampling_thread_handle_ = PlatformThreadHandle();
       sampling_thread_.reset();
     }
 
     category_filter_.Clear();
-    watch_category_ = NULL;
+    subtle::NoBarrier_Store(&watch_category_, 0);
     watch_event_name_ = "";
     UpdateCategoryGroupEnabledFlags();
     AddMetadataEvents();
 
     dispatching_to_observer_list_ = true;
     observer_list = enabled_state_observer_list_;
   }
 
   // Dispatch to observers outside the lock in case the observer triggers a
   // trace event.
@@ skipping 45 matching lines @@
 }
 
 TraceBuffer* TraceLog::GetTraceBuffer() {
   if (trace_options_ & RECORD_CONTINUOUSLY)
     return new TraceBufferRingBuffer();
   else if (trace_options_ & ECHO_TO_CONSOLE)
     return new TraceBufferDiscardsEvents();
   return new TraceBufferVector();
 }
 
+bool TraceLog::AddEventToMainBufferWhileLocked(const TraceEvent& trace_event,
+                                               NotificationHelper* notifier) {
+  // Don't check buffer_is_full_ because we want the remaining thread-local
+  // events to be flushed into the main buffer with this method, otherwise
+  // we may lose some early events of a thread that generates events sparsely.
+  lock_.AssertAcquired();
+  logged_events_->AddEvent(trace_event);
+  if (!subtle::NoBarrier_Load(&buffer_is_full_) && 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));
 };
 
+// Flush works as the following:
+// 1. Flush is called in threadA whose message loop is saved in
+//    flush_message_loop_;
+// 2. In the thread, FlushNextThreadOrFinish gets the first message loop from
+//    thread_message_loops_. If any, post a task to run
+//    FlushCurrentThreadAndContinue() in the thread message loop; otherwise
+//    finish the flush (step 4);
+// 3. FlushCurrentThreadAndContinue(), deletes the thread local event buffer:
+//    - The last batch of events of the thread are flushed into the main
+//      buffer;
+//    - The message loop will be removed from thread_message_loops_;
+//    and post FlushNextThreadOrFinish() in flush_message_loop_ to continue the
+//    flush procedure (step 2);
+// 4. When all thread local buffers have been flushed (and deleted), finish
+//    the flush by calling the OutputCallback with all events converted into
+//    JSON format.
 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()) {
+      // Destroy the next thread local buffer. The buffer will be flushed into
+      // the main event buffer and the message loop will be removed from
+      // thread_message_loops.
+      (*next_message_loop)->PostTask(
+          FROM_HERE,
+          Bind(&TraceLog::FlushCurrentThreadAndContinue,
+               Unretained(this)));
+      return;
+    }
+
+    // All thread local buffers have been flushed (and destroyed).
+    // From here to the end of the function finishes the whole flush procedure.
     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();
 
     for (size_t i = 0; i < kTraceEventBatchSize; ++i) {
       if (i > 0)
         *(&(json_events_str_ptr->data())) += ",";
 
       previous_logged_events->NextEvent().AppendAsJSON(
           &(json_events_str_ptr->data()));
 
       if (!previous_logged_events->HasMoreEvents())
         break;
     }
 
-    cb.Run(json_events_str_ptr);
+    flush_output_callback_.Run(json_events_str_ptr);
   }
 }
 
+// Run in each of the thread holding a local event buffer.

[dsinclair, 2013/08/16 14:38:32]

s/thread/threads

[Xianzhu, 2013/08/16 19:41:03]

Done.

+void TraceLog::FlushCurrentThreadAndContinue() {
+  delete thread_local_event_buffer_.Get();
+  thread_local_event_buffer_.Set(NULL);
+
+  // Continue the flush procedure.
+  flush_message_loop_->PostTask(FROM_HERE,

[dsinclair, 2013/08/16 14:38:32]

Having this here makes the flow a lot simpler to follow.

+                                Bind(&TraceLog::FlushNextThreadOrFinish,
+                                     Unretained(this)));
+}
+
 void TraceLog::AddTraceEvent(
     char phase,
     const unsigned char* category_group_enabled,
     const char* name,
     unsigned long long id,
     int num_args,
     const char** arg_names,
     const unsigned char* arg_types,
     const unsigned long long* arg_values,
     scoped_ptr<ConvertableToTraceFormat> convertable_values[],
@@ skipping 27 matching lines @@
 #if defined(OS_ANDROID)
   SendToATrace(phase, GetCategoryGroupName(category_group_enabled), name, id,
                num_args, arg_names, arg_types, arg_values, convertable_values,
                flags);
 #endif
 
   if (!IsCategoryGroupEnabled(category_group_enabled))
     return;
 
   TimeTicks now = timestamp - time_offset_;
-  EventCallback event_callback_copy;
 
   NotificationHelper notifier(this);
 
+  ThreadLocalEventBuffer* thread_local_event_buffer = NULL;
+  // A ThreadLocalEventBuffer needs the message loop
+  // - to know when the thread exits;
+  // - to handle the final flush.
+  // For a thread without a message loop, the trace events will be added into
+  // the main buffer directly.
+  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.
   if (thread_id == static_cast<int>(PlatformThread::CurrentId())) {
     const char* new_name = ThreadIdNameManager::GetInstance()->
         GetName(thread_id);
     // Check if the thread name has been set or changed since the previous
     // call (if any), but don't bother if the new name is empty. Note this will
     // not detect a thread name change within the same char* buffer address: we
     // favor common case performance over corner case correctness.
     if (new_name != g_current_thread_name.Get().Get() &&
@@ skipping 15 matching lines @@
                                existing_names.end(),
                                new_name) != existing_names.end();
         if (!found) {
           existing_name->second.push_back(',');
           existing_name->second.append(new_name);
         }
       }
     }
   }
 
-  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;
+    EchoToConsoleContext* echo_to_console_context =
+        reinterpret_cast<EchoToConsoleContext*>(subtle::NoBarrier_Load(
+            &echo_to_console_context_));
+    if (echo_to_console_context) {
+      // ECHO_TO_CONSOLE is enabled.
+      AutoLock lock(lock_);
 
-    logged_events_->AddEvent(trace_event);
-
-    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();
+        duration = timestamp -
+            echo_to_console_context->thread_event_start_times[thread_id].top();
+        echo_to_console_context->thread_event_start_times[thread_id].pop();
       }
 
       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;
+      if (echo_to_console_context->thread_colors.find(thread_name) ==
+          echo_to_console_context->thread_colors.end())
+        echo_to_console_context->thread_colors[thread_name] =
+            (echo_to_console_context->thread_colors.size() % 6) + 1;
 
       std::ostringstream log;
-      log << base::StringPrintf("%s: \x1b[0;3%dm",
-                                thread_name.c_str(),
-                                thread_colors_[thread_name]);
+      log << base::StringPrintf(
+          "%s: \x1b[0;3%dm",
+          thread_name.c_str(),
+          echo_to_console_context->thread_colors[thread_name]);
 
       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();
+      if (echo_to_console_context->thread_event_start_times.find(thread_id) !=
+          echo_to_console_context->thread_event_start_times.end()) {
+        depth = echo_to_console_context->thread_event_start_times[thread_id]
+            .size();
+      }
 
       for (size_t i = 0; i < depth; ++i)
         log << "| ";
 
       trace_event.AppendPrettyPrinted(&log);
       if (phase == TRACE_EVENT_PHASE_END)
         log << base::StringPrintf(" (%.3f ms)", duration.InMillisecondsF());
 
       LOG(ERROR) << log.str() << "\x1b[0;m";
 
-      if (phase == TRACE_EVENT_PHASE_BEGIN)
-        thread_event_start_times_[thread_id].push(timestamp);
+      if (phase == TRACE_EVENT_PHASE_BEGIN) {
+        echo_to_console_context->thread_event_start_times[thread_id].push(
+            timestamp);
+      }
     }
+  }
 
-    if (logged_events_->IsFull())
-      notifier.AddNotificationWhileLocked(TRACE_BUFFER_FULL);
-
-    if (watch_category_ == category_group_enabled && watch_event_name_ == name)
+  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);
-  } while (0); // release lock
+  }
 
   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);
+  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);
+  }
+
+  if (thread_local_event_buffer)
+    thread_local_event_buffer->ReportOverhead(timestamp);
+}
+
+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));
   }
 }
 
 void TraceLog::AddTraceEventEtw(char phase,
                                 const char* name,
                                 const void* id,
                                 const char* extra) {
 #if defined(OS_WIN)
   TraceEventETWProvider::Trace(name, phase, id, extra);
 #endif
@@ skipping 13 matching lines @@
                            TRACE_EVENT_FLAG_COPY, "id", id, "extra", extra);
 }
 
 void TraceLog::SetWatchEvent(const std::string& category_name,
                              const std::string& event_name) {
   const unsigned char* category = GetCategoryGroupEnabled(
       category_name.c_str());
   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
     // it even if it has already occurred.
     notify_count = logged_events_->CountEnabledByName(category, event_name);
   }  // release lock
 
   // Send notification for each event found.
   for (size_t i = 0; i < notify_count; ++i) {
     NotificationHelper notifier(this);
     lock_.Acquire();
     notifier.AddNotificationWhileLocked(EVENT_WATCH_NOTIFICATION);
     lock_.Release();
     notifier.SendNotificationIfAny();
   }
 }
 
 void TraceLog::CancelWatchEvent() {
   AutoLock lock(lock_);
-  watch_category_ = NULL;
+  subtle::NoBarrier_Store(&watch_category_, 0);
   watch_event_name_ = "";
 }
 
 namespace {
 
 template <typename T>
 void AddMetadataEventToBuffer(
     TraceBuffer* logged_events,
     int thread_id,
     const char* metadata_name, const char* arg_name,
@@ skipping 330 matching lines @@
         0,                       // num_args
         NULL,                    // arg_names
         NULL,                    // arg_types
         NULL,                    // arg_values
         NULL,                    // convertable values
         TRACE_EVENT_FLAG_NONE);  // flags
   }
 }
 
 }  // namespace trace_event_internal