implement SetWatchEvent and WaitForEvent for trace-based-tests

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"
 #include "base/debug/trace_event.h"
 #include "base/file_util.h"
 #include "base/format_macros.h"
 #include "base/lazy_instance.h"
 #include "base/memory/singleton.h"
 #include "base/process_util.h"
+#include "base/stl_util.h"
 #include "base/stringprintf.h"
 #include "base/string_tokenizer.h"
+#include "base/string_util.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_local.h"
+#include "base/time.h"
 #include "base/utf_string_conversions.h"
-#include "base/stl_util.h"
-#include "base/sys_info.h"
-#include "base/third_party/dynamic_annotations/dynamic_annotations.h"
-#include "base/time.h"
 
 #if defined(OS_WIN)
 #include "base/debug/trace_event_win.h"
 #endif
 
 class DeleteTraceLogForTesting {
  public:
   static void Delete() {
     Singleton<base::debug::TraceLog,
               StaticMemorySingletonTraits<base::debug::TraceLog> >::OnExit(0);
@@ skipping 274 matching lines @@
 void TraceResultBuffer::Finish() {
   output_callback_.Run("]");
 }
 
 ////////////////////////////////////////////////////////////////////////////////
 //
 // TraceLog
 //
 ////////////////////////////////////////////////////////////////////////////////
 
+TraceLog::NotificationHelper::NotificationHelper(TraceLog* trace_log)
+    : trace_log_(trace_log)
+    , notification_(0) {
+}
+
+TraceLog::NotificationHelper::~NotificationHelper() {
+}
+
+void TraceLog::NotificationHelper::AddNotificationWhileLocked(
+    int notification) {
+  if (notification_ == 0) {
+    callback_copy_ = trace_log_->notification_callback_;
+    ++trace_log_->notification_thread_count_;

[ccameron, 2012/08/21 01:06:34]

[RW-lock evangelism]: With a separate reader-writer lock for the callback, we
could discard this count-tracking.

+  }
+  notification_ |= notification;
+}
+
+void TraceLog::NotificationHelper::SendNotificationIfAny() {
+  if (notification_) {

[ccameron, 2012/08/21 01:06:34]

[RW-lock evangelism]: With a separate reader-writer lock for the callback, we
would do AutoReaderLock lock(trace_log_->callback_lock_)

+    callback_copy_.Run(notification_);
+    callback_copy_.Reset();
+
+    AutoLock lock(trace_log_->lock_);
+    --trace_log_->notification_thread_count_;
+    // Signal other waiters (if any) in case they are waiting for the
+    // callback object to be unreferenced.
+    if (trace_log_->notification_thread_count_ == 0)
+      trace_log_->notification_condition_.Signal();
+  }
+}
+
 // static
 TraceLog* TraceLog::GetInstance() {
   return Singleton<TraceLog, StaticMemorySingletonTraits<TraceLog> >::get();
 }
 
 TraceLog::TraceLog()
     : enabled_(false)
-    , dispatching_to_observer_list_(false) {
+    , notification_condition_(&lock_)
+    , notification_thread_count_(0)
+    , dispatching_to_observer_list_(false)
+    , watch_category_(NULL)
+    , watch_count_(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");
@@ skipping 62 matching lines @@
   for (int i = 0; i < g_category_index; i++) {
     if (strcmp(g_categories[i], name) == 0)
       return &g_category_enabled[i];
   }
 
   // Create a new category
   DCHECK(g_category_index < TRACE_EVENT_MAX_CATEGORIES) <<
       "must increase TRACE_EVENT_MAX_CATEGORIES";
   if (g_category_index < TRACE_EVENT_MAX_CATEGORIES) {
     int new_index = g_category_index++;
-    g_categories[new_index] = name;
+    // Don't hold on to the name pointer, so that we can create categories with
+    // strings not known at compile time (this is required by SetWatchEvent).
+    const char* new_name = base::strdup(name);
+    ANNOTATE_LEAKING_OBJECT_PTR(new_name);
+    g_categories[new_index] = new_name;
     DCHECK(!g_category_enabled[new_index]);
     if (enabled_) {
       // Note that if both included and excluded_categories are empty, the else
       // clause below excludes nothing, thereby enabling this category.
       if (!included_categories_.empty())
         EnableMatchingCategory(new_index, included_categories_, 1);
       else
         EnableMatchingCategory(new_index, excluded_categories_, 0);
     } else {
       g_category_enabled[new_index] = 0;
@@ skipping 64 matching lines @@
     std::vector<std::string>* included_out,
     std::vector<std::string>* excluded_out) {
   AutoLock lock(lock_);
   if (enabled_) {
     *included_out = included_categories_;
     *excluded_out = excluded_categories_;
   }
 }
 
 void TraceLog::SetDisabled() {
-  {
-    AutoLock lock(lock_);
-    if (!enabled_)
-      return;
+  AutoLock lock(lock_);
+  if (!enabled_)
+    return;
 
-    if (dispatching_to_observer_list_) {
-      DLOG(ERROR)
-          << "Cannot manipulate TraceLog::Enabled state from an observer.";
-      return;
-    }
+  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_,
-                      OnTraceLogWillDisable());
-    dispatching_to_observer_list_ = false;
+  dispatching_to_observer_list_ = true;
+  FOR_EACH_OBSERVER(EnabledStateChangedObserver, enabled_state_observer_list_,
+                    OnTraceLogWillDisable());
+  dispatching_to_observer_list_ = false;
 
-    enabled_ = false;
-    included_categories_.clear();
-    excluded_categories_.clear();
-    for (int i = 0; i < g_category_index; i++)
-      g_category_enabled[i] = 0;
-    AddThreadNameMetadataEvents();
-    AddClockSyncMetadataEvents();
-  }  // release lock
-  Flush();
+  enabled_ = false;
+  included_categories_.clear();
+  excluded_categories_.clear();
+  watch_category_ = NULL;
+  watch_event_name_ = "";
+  for (int i = 0; i < g_category_index; i++)
+    g_category_enabled[i] = 0;
+  AddThreadNameMetadataEvents();
+  AddClockSyncMetadataEvents();
 }
 
 void TraceLog::SetEnabled(bool enabled) {
   if (enabled)
     SetEnabled(std::vector<std::string>(), std::vector<std::string>());
   else
     SetDisabled();
 }
 
 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);
 }
 
-void TraceLog::SetOutputCallback(const TraceLog::OutputCallback& cb) {
+void TraceLog::SetNotificationCallback(
+    const TraceLog::NotificationCallback& cb) {
   AutoLock lock(lock_);

[ccameron, 2012/08/21 01:06:34]

[RW-lock evangelism]: With a separate reader-writer lock for the callback, this
would be AutoWriterLock lock(callback_lock_)

-  output_callback_ = cb;
+  // Wait until other threads are done using the callback.
+  while (notification_thread_count_ > 0)
+    notification_condition_.Wait();
+  notification_callback_ = cb;
 }
 
-void TraceLog::SetBufferFullCallback(const TraceLog::BufferFullCallback& cb) {
-  AutoLock lock(lock_);
-  buffer_full_callback_ = cb;
-}
-
-void TraceLog::Flush() {
+void TraceLog::Flush(const TraceLog::OutputCallback& cb) {
   std::vector<TraceEvent> previous_logged_events;
-  OutputCallback output_callback_copy;
   {
     AutoLock lock(lock_);
     previous_logged_events.swap(logged_events_);
-    output_callback_copy = output_callback_;
   }  // release lock
 
-  if (output_callback_copy.is_null())
-    return;
-
   for (size_t i = 0;
        i < previous_logged_events.size();
        i += kTraceEventBatchSize) {
     scoped_refptr<RefCountedString> json_events_str_ptr =
         new RefCountedString();
     TraceEvent::AppendEventsAsJSON(previous_logged_events,
                                    i,
                                    kTraceEventBatchSize,
                                    &(json_events_str_ptr->data()));
-    output_callback_copy.Run(json_events_str_ptr);
+    cb.Run(json_events_str_ptr);
   }
 }
 
 int TraceLog::AddTraceEvent(char phase,
                             const unsigned char* category_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,
                             int threshold_begin_id,
                             long long threshold,
                             unsigned char flags) {
   DCHECK(name);
   TimeTicks now = TimeTicks::NowFromSystemTraceTime();
-  BufferFullCallback buffer_full_callback_copy;
+  NotificationHelper notifier(this);
   int ret_begin_id = -1;
   {
     AutoLock lock(lock_);
     if (!*category_enabled)
       return -1;
     if (logged_events_.size() >= kTraceEventBufferSize)
       return -1;
 
     int thread_id = static_cast<int>(PlatformThread::CurrentId());
 
@@ skipping 45 matching lines @@
     if (flags & TRACE_EVENT_FLAG_MANGLE_ID)
       id ^= process_id_hash_;
 
     ret_begin_id = static_cast<int>(logged_events_.size());
     logged_events_.push_back(
         TraceEvent(thread_id,
                    now, phase, category_enabled, name, id,
                    num_args, arg_names, arg_types, arg_values,
                    flags));
 
-    if (logged_events_.size() == kTraceEventBufferSize) {
-      buffer_full_callback_copy = buffer_full_callback_;
+    if (logged_events_.size() == kTraceEventBufferSize)
+      notifier.AddNotificationWhileLocked(TRACE_BUFFER_FULL);
+
+    if (watch_category_ == category_enabled && watch_event_name_ == name &&
+        --watch_count_ == 0) {
+      notifier.AddNotificationWhileLocked(EVENT_WATCH_NOTIFICATION);
+      // Clear watch state now so that only the one notification occurs.
+      watch_category_ = NULL;
+      watch_event_name_ = "";
     }
   }  // release lock
 
-  if (!buffer_full_callback_copy.is_null())
-    buffer_full_callback_copy.Run();
+  notifier.SendNotificationIfAny();
 
   return ret_begin_id;
 }
 
 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
   INTERNAL_TRACE_EVENT_ADD(phase, "ETW Trace Event", name,
                            TRACE_EVENT_FLAG_COPY, "id", id, "extra", extra);
 }
 
 void TraceLog::AddTraceEventEtw(char phase,
                                 const char* name,
                                 const void* id,
                                 const std::string& extra)
 {
 #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 char* category_name,
+                             const char* event_name,
+                             int num_occurrences) {
+  DCHECK(num_occurrences > 0);
+  const unsigned char* category = GetCategoryEnabled(category_name);
+  NotificationHelper notifier(this);
+  {
+    AutoLock lock(lock_);
+    watch_category_ = category;
+    watch_event_name_ = event_name;
+    watch_count_ = num_occurrences;
+
+    // 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, logged_events_[i].name()) == 0 &&
+          --watch_count_ == 0) {
+        notifier.AddNotificationWhileLocked(EVENT_WATCH_NOTIFICATION);
+        // Clear watch state now so that only the one notification occurs.
+        watch_category_ = NULL;
+        watch_event_name_ = "";
+        break;
+      }
+    }
+  }  // release lock
+
+  notifier.SendNotificationIfAny();
+}
+
+void TraceLog::CancelWatchEvent() {
+  AutoLock lock(lock_);
+  watch_category_ = NULL;
+  watch_event_name_ = "";
+  watch_count_ = 0;
+}
+
 void TraceLog::AddClockSyncMetadataEvents() {
 #if defined(OS_ANDROID)
   // Since Android does not support sched_setaffinity, we cannot establish clock
   // sync unless the scheduler clock is set to global. If the trace_clock file
   // can't be read, we will assume the kernel doesn't support tracing and do
   // nothing.
   std::string clock_mode;
   if (!file_util::ReadFileToString(
           FilePath("/sys/kernel/debug/tracing/trace_clock"),
           &clock_mode))
@@ skipping 61 matching lines @@
   // Create a FNV hash from the process ID for XORing.
   // See http://isthe.com/chongo/tech/comp/fnv/ for algorithm details.
   unsigned long long offset_basis = 14695981039346656037ull;
   unsigned long long fnv_prime = 1099511628211ull;
   unsigned long long pid = static_cast<unsigned long long>(process_id_);
   process_id_hash_ = (offset_basis ^ pid) * fnv_prime;
 }
 
 }  // namespace debug
 }  // namespace base