Update tracing framework to optionally use a ringbuffer.

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/bind.h"
 #include "base/debug/leak_annotations.h"
@@ skipping 49 matching lines @@
 // Parallel arrays g_categories and g_category_enabled are separate so that
 // a pointer to a member of g_category_enabled can be easily converted to an
 // index into g_categories. This allows macros to deal only with char enabled
 // pointers from g_category_enabled, and we can convert internally to determine
 // the category name from the char enabled pointer.
 const char* g_categories[TRACE_EVENT_MAX_CATEGORIES] = {
   "tracing already shutdown",
   "tracing categories exhausted; must increase TRACE_EVENT_MAX_CATEGORIES",
   "__metadata",
 };
+
 // The enabled flag is char instead of bool so that the API can be used from C.
 unsigned char g_category_enabled[TRACE_EVENT_MAX_CATEGORIES] = { 0 };
 const int g_category_already_shutdown = 0;
 const int g_category_categories_exhausted = 1;
 const int g_category_metadata = 2;
 int g_category_index = 3; // skip initial 3 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";
 
 }  // namespace
 
+class TraceBufferRingBuffer : public TraceBuffer {
+ public:
+  TraceBufferRingBuffer()
+      : unused_event_index_(0),
+        oldest_event_index_(0) {
+    logged_events_.reserve(1024);
+  }
+
+  ~TraceBufferRingBuffer() {}
+
+  void AddEvent(const TraceEvent& event) OVERRIDE {
+    if (unused_event_index_ < Size())
+      logged_events_[unused_event_index_] = event;
+    else
+      logged_events_.push_back(event);
+
+    unused_event_index_++;
+    if (unused_event_index_ >= kTraceEventBufferSize)
+      unused_event_index_ = 0;
+    if (unused_event_index_ == oldest_event_index_) {
+      oldest_event_index_++;
+      if (oldest_event_index_ >= kTraceEventBufferSize) {
+        oldest_event_index_ = 0;
+      }
+    }
+  }
+
+  bool HasMoreEvents() const OVERRIDE {
+    return oldest_event_index_ != unused_event_index_;
+  }
+
+  const TraceEvent& NextEvent() OVERRIDE {
+    DCHECK(HasMoreEvents());
+
+    int next = oldest_event_index_;
+    oldest_event_index_++;
+    if (oldest_event_index_ >= kTraceEventBufferSize)
+      oldest_event_index_ = 0;

[jar (doing other things), 2013/03/15 19:13:30]

nit: This three line snippet could be pulled into a helper function (static
method?) nicely.  It seems sad to see it repeated four times at line 145, 124,
109, and 105 (and have to read it each time).

void IncrementIndex(size_t *index) {...}

or

size_t NextIndex(size_t index) {...}

The latter is perhaps a tad messier... but I don't like taking addresses of
stuff when I don't have to (compilers are confused too commonly).

[dsinclair, 2013/03/15 19:39:55]

Done.

+    return GetEventAt(next);
+  }
+
+  bool IsFull() const OVERRIDE {
+    return false;
+  }
+
+  size_t CountEnabledByName(const unsigned char* category,
+                            const std::string& event_name) const OVERRIDE {
+    size_t notify_count = 0;
+    size_t index = oldest_event_index_;
+    while (index != unused_event_index_) {
+      const TraceEvent& event = GetEventAt(index);
+      if (category == event.category_enabled() &&
+          strcmp(event_name.c_str(), event.name()) == 0) {
+        ++notify_count;
+      }
+
+      index++;
+      if (index >= kTraceEventBufferSize)
+        index = 0;
+    }
+    return notify_count;
+  }
+
+  const TraceEvent& GetEventAt(size_t index) const OVERRIDE {
+    DCHECK(index < logged_events_.size());
+    return logged_events_[index];
+  }
+
+  size_t Size() const OVERRIDE {
+    return logged_events_.size();
+  }
+
+ private:
+  uint32 unused_event_index_;
+  uint32 oldest_event_index_;
+  std::vector<TraceEvent> logged_events_;
+
+  DISALLOW_COPY_AND_ASSIGN(TraceBufferRingBuffer);
+};
+
+class TraceBufferVector : public TraceBuffer {
+ public:
+  TraceBufferVector()
+      : current_iteration_index_(0) {

[jar (doing other things), 2013/03/15 19:13:30]

nit: no need to wrap.. this will fit on previous line.

[dsinclair, 2013/03/15 19:39:55]

Done.

+    logged_events_.reserve(1024);

[jar (doing other things), 2013/03/15 19:13:30]

nit: Please use a named constant here, and in the sibling class:

kInitialEventBufferSize

Why bother reserving here? If the buffer is used, it will grow towards 50K.  Is
this a performance optimization to avoid a bunch of little allocations, since
you know it will grow large?

[dsinclair, 2013/03/15 19:39:55]

Done. It's a performance optimization as we know the buffer will get large once
it's turned on.

+  }
+
+  ~TraceBufferVector() {
+  }
+
+  void AddEvent(const TraceEvent& event) OVERRIDE {
+    // Note, this code assumes the caller is doing a !IsFull check before
+    // calling AddEvent. We don't DCHECK(!IsFull()) here as the code to add
+    // the metadata does an AddEvent, if we had the DCHECK we would fail

[jar (doing other things), 2013/03/15 19:13:30]

nit: this is a run-on sentence.  Please change the comma to a period.

That said, I don't understand the comment.  If you claim that a DCHECK would
fail here (if we had it), then the calling code sounds problematic.

Also, I *think* perhaps there is a typo on line 181 as you say "...does an
AddEvent."  I'm confused, because this code *is* AddEvent.  Did you mean to
mention a different function???

[dsinclair, 2013/03/15 19:39:55]

Done. Hopefully with more clarity this time.

+    // to add the metadata to the trace log when the buffer is full.
+    logged_events_.push_back(event);
+  }
+
+  bool HasMoreEvents() const OVERRIDE {
+    return current_iteration_index_ < Size();
+  }
+
+  const TraceEvent& NextEvent() OVERRIDE {
+    DCHECK(HasMoreEvents());
+    return GetEventAt(current_iteration_index_++);
+  }
+
+  bool IsFull() const OVERRIDE {
+    return Size() >= kTraceEventBufferSize;
+  }
+
+  size_t CountEnabledByName(const unsigned char* category,
+                            const std::string& event_name) const OVERRIDE {
+    size_t notify_count = 0;
+    for (size_t i = 0; i < Size(); i++) {
+      const TraceEvent& event = GetEventAt(i);
+      if (category == event.category_enabled() &&
+          strcmp(event_name.c_str(), event.name()) == 0) {
+        ++notify_count;
+      }
+    }
+    return notify_count;
+  }
+
+  const TraceEvent& GetEventAt(size_t index) const OVERRIDE {
+    DCHECK(index < logged_events_.size());
+    return logged_events_[index];
+  }
+
+  size_t Size() const OVERRIDE {
+    return logged_events_.size();
+  }
+
+ private:
+  size_t current_iteration_index_;
+  std::vector<TraceEvent> logged_events_;
+
+  DISALLOW_COPY_AND_ASSIGN(TraceBufferVector);
+};
+
 ////////////////////////////////////////////////////////////////////////////////
 //
 // TraceEvent
 //
 ////////////////////////////////////////////////////////////////////////////////
 
 namespace {
 
 size_t GetAllocLength(const char* str) { return str ? strlen(str) + 1 : 0; }
 
@@ skipping 134 matching lines @@
         start_pos += 2;
       }
       *out += "\"";
       break;
     default:
       NOTREACHED() << "Don't know how to print this value";
       break;
   }
 }
 
-void TraceEvent::AppendEventsAsJSON(const std::vector<TraceEvent>& events,
-                                    size_t start,
-                                    size_t count,
-                                    std::string* out) {
-  for (size_t i = 0; i < count && start + i < events.size(); ++i) {
-    if (i > 0)
-      *out += ",";
-    events[i + start].AppendAsJSON(out);
-  }
-}
-
 void TraceEvent::AppendAsJSON(std::string* out) const {
   int64 time_int64 = timestamp_.ToInternalValue();
   int process_id = TraceLog::GetInstance()->process_id();
   // Category name checked at category creation time.
   DCHECK(!strchr(name_, '"'));
   StringAppendF(out,
       "{\"cat\":\"%s\",\"pid\":%i,\"tid\":%i,\"ts\":%" PRId64 ","
       "\"ph\":\"%c\",\"name\":\"%s\",\"args\":{",
       TraceLog::GetCategoryName(category_enabled_),
       process_id,
@@ skipping 242 matching lines @@
 // content/browser/devtools/devtools_tracing_handler:TraceOptionsFromString
 TraceLog::Options TraceLog::TraceOptionsFromString(const std::string& options) {
   std::vector<std::string> split;
   base::SplitString(options, ',', &split);
   int ret = 0;
   for (std::vector<std::string>::iterator iter = split.begin();
        iter != split.end();
        ++iter) {
     if (*iter == kRecordUntilFull) {
       ret |= RECORD_UNTIL_FULL;
+    } else if (*iter == kRecordContinuously) {
+      ret |= RECORD_CONTINUOUSLY;
     } else {
       NOTREACHED();  // Unknown option provided.
     }
   }
-  // Check to see if any RECORD_* options are set, and if none, then provide
-  // a default.
-  // TODO(dsinclair): Remove this comment when we have more then one RECORD_*
-  // flag and the code's structure is then sensible.
-  if (!(ret & RECORD_UNTIL_FULL))
+  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),
+      logged_events_(NULL),
       dispatching_to_observer_list_(false),
       watch_category_(NULL),
       trace_options_(RECORD_UNTIL_FULL),
       sampling_thread_handle_(0) {
   // 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_enabled, sizeof(g_category_enabled),
   //                            "trace_event category enabled");
   for (int i = 0; i < TRACE_EVENT_MAX_CATEGORIES; ++i) {
     ANNOTATE_BENIGN_RACE(&g_category_enabled[i],
                          "trace_event category enabled");
   }
 #if defined(OS_NACL)  // NaCl shouldn't expose the process id.
   SetProcessID(0);
 #else
   SetProcessID(static_cast<int>(GetCurrentProcId()));
 #endif
+
+  logged_events_.reset(GetTraceBuffer());
 }
 
 TraceLog::~TraceLog() {
 }
 
 const unsigned char* TraceLog::GetCategoryEnabled(const char* name) {
   TraceLog* tracelog = GetInstance();
   if (!tracelog) {
     DCHECK(!g_category_enabled[g_category_already_shutdown]);
     return &g_category_enabled[g_category_already_shutdown];
@@ skipping 115 matching lines @@
                                   included_categories.end());
       EnableMatchingCategories(included_categories_, CATEGORY_ENABLED, 0);
     } else {
       // If either old or new included categories are empty, allow all events.
       included_categories_.clear();
       excluded_categories_.clear();
       EnableMatchingCategories(excluded_categories_, 0, CATEGORY_ENABLED);
     }
     return;
   }
-  trace_options_ = options;
+
+  if (options != trace_options_) {
+    trace_options_ = options;
+    logged_events_.reset(GetTraceBuffer());
+  }
 
   if (dispatching_to_observer_list_) {
     DLOG(ERROR) <<
         "Cannot manipulate TraceLog::Enabled state from an observer.";
     return;
   }
 
   dispatching_to_observer_list_ = true;
   FOR_EACH_OBSERVER(EnabledStateChangedObserver, enabled_state_observer_list_,
                     OnTraceLogWillEnable());
   dispatching_to_observer_list_ = false;
 
-  logged_events_.reserve(1024);
   included_categories_ = included_categories;
   excluded_categories_ = excluded_categories;
   // Note that if both included and excluded_categories are empty, the else
   // clause below excludes nothing, thereby enabling all categories.
   if (!included_categories_.empty())
     EnableMatchingCategories(included_categories_, CATEGORY_ENABLED, 0);
   else
     EnableMatchingCategories(excluded_categories_, 0, CATEGORY_ENABLED);
 
   if (options & ENABLE_SAMPLING) {
@@ skipping 95 matching lines @@
 void TraceLog::AddEnabledStateObserver(EnabledStateChangedObserver* listener) {
   enabled_state_observer_list_.AddObserver(listener);
 }
 
 void TraceLog::RemoveEnabledStateObserver(
     EnabledStateChangedObserver* listener) {
   enabled_state_observer_list_.RemoveObserver(listener);
 }
 
 float TraceLog::GetBufferPercentFull() const {
-  return (float)((double)logged_events_.size()/(double)kTraceEventBufferSize);
+  return (float)((double)logged_events_->Size()/(double)kTraceEventBufferSize);
 }
 
 void TraceLog::SetNotificationCallback(
     const TraceLog::NotificationCallback& cb) {
   AutoLock lock(lock_);
   notification_callback_ = cb;
 }
 
+TraceBuffer* TraceLog::GetTraceBuffer() {
+  if (trace_options_ & RECORD_CONTINUOUSLY)
+    return new TraceBufferRingBuffer();
+  return new TraceBufferVector();
+}
+
 void TraceLog::SetEventCallback(EventCallback cb) {
   AutoLock lock(lock_);
   event_callback_ = cb;
 };
 
 void TraceLog::Flush(const TraceLog::OutputCallback& cb) {
-  std::vector<TraceEvent> previous_logged_events;
+  scoped_ptr<TraceBuffer> previous_logged_events;
   {
     AutoLock lock(lock_);
     previous_logged_events.swap(logged_events_);
+    logged_events_.reset(GetTraceBuffer());
   }  // release lock
 
-  for (size_t i = 0;
-       i < previous_logged_events.size();
-       i += kTraceEventBatchSize) {
+  while (previous_logged_events->HasMoreEvents()) {
     scoped_refptr<RefCountedString> json_events_str_ptr =
         new RefCountedString();
-    TraceEvent::AppendEventsAsJSON(previous_logged_events,
-                                   i,
-                                   kTraceEventBatchSize,
-                                   &(json_events_str_ptr->data()));
+
+    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);
   }
 }
 
 void TraceLog::AddTraceEvent(char phase,
                              const unsigned char* category_enabled,
                              const char* name,
                              unsigned long long id,
                              int num_args,
                              const char** arg_names,
@@ skipping 31 matching lines @@
 
   TimeTicks now = timestamp - time_offset_;
   EventCallback event_callback_copy;
 
   NotificationHelper notifier(this);
 
   {
     AutoLock lock(lock_);
     if (*category_enabled != CATEGORY_ENABLED)
       return;
-    if (logged_events_.size() >= kTraceEventBufferSize)
+    if (logged_events_->IsFull())
       return;
 
     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() &&
         new_name && *new_name) {
@@ skipping 12 matching lines @@
         bool found = std::find(existing_names.begin(),
                                existing_names.end(),
                                new_name) != existing_names.end();
         if (!found) {
           existing_name->second.push_back(',');
           existing_name->second.append(new_name);
         }
       }
     }
 
-    logged_events_.push_back(
-        TraceEvent(thread_id,
-                   now, phase, category_enabled, name, id,
-                   num_args, arg_names, arg_types, arg_values,
-                   flags));
+    logged_events_->AddEvent(TraceEvent(thread_id,
+        now, phase, category_enabled, name, id,
+        num_args, arg_names, arg_types, arg_values,
+        flags));
 
-    if (logged_events_.size() == kTraceEventBufferSize)
+    if (logged_events_->IsFull())
       notifier.AddNotificationWhileLocked(TRACE_BUFFER_FULL);
 
     if (watch_category_ == category_enabled && watch_event_name_ == name)
       notifier.AddNotificationWhileLocked(EVENT_WATCH_NOTIFICATION);
 
     event_callback_copy = event_callback_;
   }  // release lock
 
   notifier.SendNotificationIfAny();
   if (event_callback_copy != NULL) {
@@ skipping 22 matching lines @@
 #if defined(OS_WIN)
   TraceEventETWProvider::Trace(name, phase, id, extra);
 #endif
   INTERNAL_TRACE_EVENT_ADD(phase, "ETW Trace Event", name,
                            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 = GetCategoryEnabled(category_name.c_str());
-  int notify_count = 0;
+  size_t notify_count = 0;
   {
     AutoLock lock(lock_);
     watch_category_ = 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.
-    for (size_t i = 0u; i < logged_events_.size(); ++i) {
-      if (category == logged_events_[i].category_enabled() &&
-          strcmp(event_name.c_str(), logged_events_[i].name()) == 0) {
-        ++notify_count;
-      }
-    }
+    // 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 (int i = 0; i < notify_count; ++i) {
+  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;
   watch_event_name_ = "";
 }
 
 void TraceLog::AddThreadNameMetadataEvents() {
   lock_.AssertAcquired();
   for(hash_map<int, std::string>::iterator it = thread_names_.begin();
       it != thread_names_.end();
       it++) {
     if (!it->second.empty()) {
       int num_args = 1;
       const char* arg_name = "name";
       unsigned char arg_type;
       unsigned long long arg_value;
       trace_event_internal::SetTraceValue(it->second, &arg_type, &arg_value);
-      logged_events_.push_back(
-          TraceEvent(it->first,
-                     TimeTicks(), TRACE_EVENT_PHASE_METADATA,
-                     &g_category_enabled[g_category_metadata],
-                     "thread_name", trace_event_internal::kNoEventId,
-                     num_args, &arg_name, &arg_type, &arg_value,
-                     TRACE_EVENT_FLAG_NONE));
+      logged_events_->AddEvent(TraceEvent(it->first,
+          TimeTicks(), TRACE_EVENT_PHASE_METADATA,
+          &g_category_enabled[g_category_metadata],
+          "thread_name", trace_event_internal::kNoEventId,
+          num_args, &arg_name, &arg_type, &arg_value,
+          TRACE_EVENT_FLAG_NONE));
     }
   }
 }
 
 void TraceLog::InstallWaitableEventForSamplingTesting(
     WaitableEvent* waitable_event) {
   sampling_thread_->InstallWaitableEventForSamplingTesting(waitable_event);
 }
 
 void TraceLog::DeleteForTesting() {
@@ skipping 61 matching lines @@
         0,                       // num_args
         NULL,                    // arg_names
         NULL,                    // arg_types
         NULL,                    // arg_values
         TRACE_EVENT_FLAG_NONE);  // flags
   }
 }
 
 }  // namespace trace_event_internal