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";
+
+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
 
 ////////////////////////////////////////////////////////////////////////////////
 //
 // TraceEvent
 //
 ////////////////////////////////////////////////////////////////////////////////
 
 namespace {
@@ skipping 137 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 15 matching lines @@
 
   // If id_ is set, print it out as a hex string so we don't loose any
   // bits (it might be a 64-bit pointer).
   if (flags_ & TRACE_EVENT_FLAG_HAS_ID)
     StringAppendF(out, ",\"id\":\"%" PRIx64 "\"", static_cast<uint64>(id_));
   *out += "}";
 }
 
 ////////////////////////////////////////////////////////////////////////////////
 //
+// TraceBuffer
+//
+////////////////////////////////////////////////////////////////////////////////
+
+TraceBuffer::TraceBuffer() {
+  logged_events_.reserve(1024);
+}
+
+TraceBuffer::~TraceBuffer() {
+}
+
+////////////////////////////////////////////////////////////////////////////////
+//
 // TraceResultBuffer
 //
 ////////////////////////////////////////////////////////////////////////////////
 
 TraceResultBuffer::OutputCallback
     TraceResultBuffer::SimpleOutput::GetCallback() {
   return Bind(&SimpleOutput::Append, Unretained(this));
 }
 
 void TraceResultBuffer::SimpleOutput::Append(
@@ skipping 207 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 (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);
   }
 }
 
 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 28 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 15 matching lines @@
         if (!found) {
           existing_name->second.push_back(',');
           existing_name->second.append(new_name);
         }
       }
     }
 
     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)
       notifier.AddNotificationWhileLocked(EVENT_WATCH_NOTIFICATION);
 
     event_callback_copy = event_callback_;
   }  // release lock
 
   notifier.SendNotificationIfAny();
   if (event_callback_copy != NULL) {
@@ skipping 28 matching lines @@
 
 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;
   {
     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) {
     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,

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