Update tracing framework to optionally use a ringbuffer.

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 d9d700797644838932af5bc2d55922bc8a73bd26..17986405e85411f20bb480b75c63919f93ceebd3 100644
--- a/base/debug/trace_event_impl.cc
+++ b/base/debug/trace_event_impl.cc
@@ -67,6 +67,7 @@ const char* g_categories[TRACE_EVENT_MAX_CATEGORIES] = {
   "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;
@@ -81,9 +82,150 @@ 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
@@ -238,17 +380,6 @@ void TraceEvent::AppendValueAsJSON(unsigned char type,
   }
 }
 
-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();
@@ -511,15 +642,13 @@ TraceLog::Options TraceLog::TraceOptionsFromString(const std::string& options) {
        ++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);
@@ -527,6 +656,7 @@ TraceLog::Options TraceLog::TraceOptionsFromString(const std::string& options) {
 
 TraceLog::TraceLog()
     : enable_count_(0),
+      logged_events_(NULL),
       dispatching_to_observer_list_(false),
       watch_category_(NULL),
       trace_options_(RECORD_UNTIL_FULL),
@@ -547,6 +677,8 @@ TraceLog::TraceLog()
 #else
   SetProcessID(static_cast<int>(GetCurrentProcId()));
 #endif
+
+  logged_events_.reset(GetTraceBuffer());
 }
 
 TraceLog::~TraceLog() {
@@ -682,7 +814,11 @@ void TraceLog::SetEnabled(const std::vector<std::string>& included_categories,
     }
     return;
   }
-  trace_options_ = options;
+
+  if (options != trace_options_) {
+    trace_options_ = options;
+    logged_events_.reset(GetTraceBuffer());
+  }
 
   if (dispatching_to_observer_list_) {
     DLOG(ERROR) <<
@@ -695,7 +831,6 @@ void TraceLog::SetEnabled(const std::vector<std::string>& included_categories,
                     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
@@ -811,7 +946,7 @@ void TraceLog::RemoveEnabledStateObserver(
 }
 
 float TraceLog::GetBufferPercentFull() const {
-  return (float)((double)logged_events_.size()/(double)kTraceEventBufferSize);
+  return (float)((double)logged_events_->Size()/(double)kTraceEventBufferSize);
 }
 
 void TraceLog::SetNotificationCallback(
@@ -820,27 +955,40 @@ void TraceLog::SetNotificationCallback(
   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);
   }
 }
@@ -892,7 +1040,7 @@ void TraceLog::AddTraceEventWithThreadIdAndTimestamp(
     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()->
@@ -925,13 +1073,12 @@ void TraceLog::AddTraceEventWithThreadIdAndTimestamp(
       }
     }
 
-    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)
@@ -974,24 +1121,19 @@ void TraceLog::AddTraceEventEtw(char phase,
 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);
@@ -1017,13 +1159,12 @@ void TraceLog::AddThreadNameMetadataEvents() {
       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));
     }
   }
 }