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 0f520b922de6a93e53b09ec0a57534b7190e367a..36e665d4f1e520f65d078d50ff403d60c550d6ec 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,6 +82,123 @@ LazyInstance<ThreadLocalPointer<const char> >::Leaky
     g_current_thread_name = LAZY_INSTANCE_INITIALIZER;
 
 const char kRecordUntilFull[] = "record-until-full";
+const char kRecordContinuously[] = "record-continuously";
+
+class TraceBufferRingBuffer : public TraceBuffer {
+ public:
+  TraceBufferRingBuffer()
+      : logged_events_newest_(0),
+        logged_events_oldest_(0) {
+  }
+
+  ~TraceBufferRingBuffer() {}
+
+  void AddEvent(const TraceEvent& event) OVERRIDE {
+    if (logged_events_newest_ < logged_events_.size())
+      logged_events_[logged_events_newest_] = event;
+    else
+      logged_events_.push_back(event);
+
+    logged_events_newest_++;
+    if (logged_events_newest_ >= kTraceEventBufferSize)
+      logged_events_newest_ = 0;
+    if (logged_events_newest_ == logged_events_oldest_) {
+      logged_events_oldest_++;
+      if (logged_events_oldest_ >= kTraceEventBufferSize) {
+        logged_events_oldest_ = 0;
+      }
+    }
+  }
+
+  bool HasMoreEvents() const OVERRIDE {
+    return logged_events_oldest_ != logged_events_newest_;
+  }
+
+  const TraceEvent& NextEvent() OVERRIDE {
+    DCHECK(HasMoreEvents());
+
+    int cur = logged_events_oldest_;

[jar (doing other things), 2013/03/13 18:42:30]

nit: avoid abreviations such as |cur| which I'm guessing is meant to mean
"current".  Better might |next|.

[dsinclair, 2013/03/13 19:27:27]

Done.

+    logged_events_oldest_++;
+    if (logged_events_oldest_ >= kTraceEventBufferSize)
+      logged_events_oldest_ = 0;
+    return logged_events_[cur];
+  }
+
+  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 idx = logged_events_oldest_;
+    while (true) {
+      if (idx == logged_events_newest_)
+        break;

[jar (doing other things), 2013/03/13 18:42:30]

nit: How about replacing last three lines with:
while(idx != logged_events_newest_)

[dsinclair, 2013/03/13 19:27:27]

Done.

+
+      if (category == logged_events_[idx].category_enabled() &&
+          strcmp(event_name.c_str(), logged_events_[idx].name()) == 0) {
+        ++notify_count;
+      }
+
+      idx++;
+      if (idx >= kTraceEventBufferSize)
+        idx = 0;
+    }
+    return notify_count;
+  }
+
+ private:
+  uint32 logged_events_newest_;

[jar (doing other things), 2013/03/13 18:42:30]

nit: This is not really the index of the newest, but rather the first unused
entry in the circular buffer.  Possibly a better name would be:

unused_event_index_

[dsinclair, 2013/03/13 19:27:27]

Done.

+  uint32 logged_events_oldest_;

[jar (doing other things), 2013/03/13 18:42:30]

nit: Since this points to a singular event, better might be:

oldest_event_index_

[dsinclair, 2013/03/13 19:27:27]

Done.

+
+  DISALLOW_COPY_AND_ASSIGN(TraceBufferRingBuffer);
+};
+
+class TraceBufferVector : public TraceBuffer {
+ public:
+  TraceBufferVector() : current_iteration_index_(0) {
+  }
+
+  ~TraceBufferVector() {
+  }
+
+  void AddEvent(const TraceEvent& event) OVERRIDE {
+    // Note, we don't check IsFull here as the code to add the metadata
+    // will do an AddEvent, if the buffer is full we'd lose the metadata.

[jar (doing other things), 2013/03/13 18:42:30]

nit: "AddEvent, if the" --> "AddEvent.  If the"

I also don't understand the assertion about losing metadata.  This sure looks
like it will keep pushing, and growing the vector in any case, which may be
undesirable.  Perhaps at least a DCHECK(!IsFull()) would be nice.

[dsinclair, 2013/03/13 19:27:27]

Clarified the comment.

+    logged_events_.push_back(event);
+  }
+
+  bool HasMoreEvents() const OVERRIDE {
+    return current_iteration_index_ < Size();
+  }
+
+  const TraceEvent& NextEvent() OVERRIDE {
+    DCHECK(HasMoreEvents());
+    return logged_events_[current_iteration_index_++];
+  }
+
+  bool IsFull() const OVERRIDE {
+    return Size() == kTraceEventBufferSize;

[jar (doing other things), 2013/03/13 18:42:30]

I'm not clear on the meaning, given that you push without checking... but
suspect it woul be much safer to use:
return Size() >= kTraceEventBufferSize

[dsinclair, 2013/03/13 19:27:27]

Done.

+  }
+
+  size_t CountEnabledByName(const unsigned char* category,
+                            const std::string& event_name) const OVERRIDE {
+    size_t notify_count = 0;
+    for (size_t idx = 0; idx < logged_events_.size(); idx++) {

[jar (doing other things), 2013/03/13 18:42:30]

nit: Rather than abbreviate |idx|, use |index|, or acceptable is |i| for such a
simple counter.  For complicated iterators, it is common to use |it|, but that
is about the only common abbreviation I've seen.

[dsinclair, 2013/03/13 19:27:27]

Done.

+      if (category == logged_events_[idx].category_enabled() &&
+          strcmp(event_name.c_str(), logged_events_[idx].name()) == 0) {
+        ++notify_count;
+      }
+    }
+    return notify_count;
+  }
+
+ private:
+  size_t current_iteration_index_;
+
+  DISALLOW_COPY_AND_ASSIGN(TraceBufferVector);
+};
 
 }  // namespace
 
@@ -238,17 +356,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();
@@ -284,6 +391,19 @@ void TraceEvent::AppendAsJSON(std::string* out) const {
 
 ////////////////////////////////////////////////////////////////////////////////
 //
+// TraceBuffer
+//
+////////////////////////////////////////////////////////////////////////////////
+
+TraceBuffer::TraceBuffer() {
+  logged_events_.reserve(1024);
+}
+
+TraceBuffer::~TraceBuffer() {
+}
+
+////////////////////////////////////////////////////////////////////////////////
+//
 // TraceResultBuffer
 //
 ////////////////////////////////////////////////////////////////////////////////
@@ -511,15 +631,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 +645,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 +666,8 @@ TraceLog::TraceLog()
 #else
   SetProcessID(static_cast<int>(GetCurrentProcId()));
 #endif
+
+  logged_events_.reset(GetTraceBuffer());
 }
 
 TraceLog::~TraceLog() {
@@ -682,7 +803,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 +820,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 +935,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 +944,43 @@ 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 (true) {
+    if (!previous_logged_events->HasMoreEvents())

[jar (doing other things), 2013/03/13 18:42:30]

nit: again, why not put test into while()

[dsinclair, 2013/03/13 19:27:27]

Done.

+      break;
+
     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);
   }
 }
@@ -889,7 +1029,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 +1065,12 @@ void TraceLog::AddTraceEventWithThreadIdAndTimestamp(
     if (flags & TRACE_EVENT_FLAG_MANGLE_ID)
       id ^= process_id_hash_;
 
-    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)
@@ -980,14 +1119,9 @@ void TraceLog::SetWatchEvent(const std::string& category_name,
     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.
@@ -1017,13 +1151,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,

[nduca, 2013/03/13 17:04:40]

a nice followup would maybe be to initialize inplace, e.g. tmp =
logged_events_->AddEvent()
tmp.init(constructor args)

but since we did this before, its not a regression to land as is.

[dsinclair, 2013/03/13 19:27:27]

Ack.

+          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));
     }
   }
 }