Tracing pre-filtering

base/trace_event/trace_log.cc

 // Copyright 2015 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/trace_event/trace_log.h"
 
 #include <algorithm>
 #include <cmath>
 #include <memory>
 #include <utility>
 
 #include "base/base_switches.h"
 #include "base/bind.h"
 #include "base/command_line.h"
 #include "base/debug/leak_annotations.h"
 #include "base/lazy_instance.h"
 #include "base/location.h"
 #include "base/macros.h"
+#include "base/memory/ptr_util.h"
 #include "base/memory/ref_counted_memory.h"
 #include "base/memory/singleton.h"
 #include "base/process/process_metrics.h"
 #include "base/stl_util.h"
 #include "base/strings/string_split.h"
 #include "base/strings/string_tokenizer.h"
 #include "base/strings/stringprintf.h"
 #include "base/sys_info.h"
 #include "base/third_party/dynamic_annotations/dynamic_annotations.h"
 #include "base/threading/platform_thread.h"
@@ skipping 66 matching lines @@
 // convert internally to determine the category name from the char enabled
 // pointer.
 const char* g_category_groups[MAX_CATEGORY_GROUPS] = {
     "toplevel",
     "tracing already shutdown",
     "tracing categories exhausted; must increase MAX_CATEGORY_GROUPS",
     "__metadata"};
 
 // The enabled flag is char instead of bool so that the API can be used from C.
 unsigned char g_category_group_enabled[MAX_CATEGORY_GROUPS] = {0};
+
+class EventNameFilter : public TraceLog::TraceEventFilter {
+ public:
+  EventNameFilter(const base::DictionaryValue* filter_args) {
+    const base::ListValue* whitelist = nullptr;
+    if (filter_args->GetList("event_name_whitelist", &whitelist)) {
+      for (size_t i = 0; i < whitelist->GetSize(); ++i) {
+        std::string event_name;
+        if (!whitelist->GetString(i, &event_name))
+          continue;
+
+        whitelist_.insert(event_name);
+      }
+    }
+  }
+
+  bool FilterTraceEvent(const TraceEvent& trace_event) const override {
+    return ContainsKey(whitelist_, trace_event.name());
+  }
+
+ private:
+  std::unordered_set<std::string> whitelist_;
+};
+
+base::LazyInstance<
+    std::list<std::unique_ptr<TraceLog::TraceEventFilter>>>::Leaky
+    g_category_group_filter[MAX_CATEGORY_GROUPS] = {LAZY_INSTANCE_INITIALIZER};
+
+TraceLog::TraceEventFilterConstructorForTesting
+    g_trace_event_filter_constructor_for_testing = nullptr;

[Primiano Tucci (use gerrit), 2016/05/31 15:41:24]

I'd move this to be a static field of SetTraceEventFilterCons. Otherwise In
order to follow the testing code I have to jump up and down in this file.

+
 // Indexes here have to match the g_category_groups array indexes above.
 const int g_category_already_shutdown = 1;
 const int g_category_categories_exhausted = 2;
 const int g_category_metadata = 3;
 const int g_num_builtin_categories = 4;
 // Skip default categories.
 base::subtle::AtomicWord g_category_index = g_num_builtin_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
@@ skipping 57 matching lines @@
                 size_t event_index,
                 TraceEventHandle* handle) {
   DCHECK(chunk_seq);
   DCHECK(chunk_index <= TraceBufferChunk::kMaxChunkIndex);
   DCHECK(event_index < TraceBufferChunk::kTraceBufferChunkSize);
   handle->chunk_seq = chunk_seq;
   handle->chunk_index = static_cast<uint16_t>(chunk_index);
   handle->event_index = static_cast<uint16_t>(event_index);
 }
 
+uintptr_t GetCategoryIndex(const unsigned char* category_group_enabled) {
+  // Calculate the index of the category group by finding
+  // category_group_enabled in g_category_group_enabled array.
+  uintptr_t category_begin =
+      reinterpret_cast<uintptr_t>(g_category_group_enabled);
+  uintptr_t category_ptr = reinterpret_cast<uintptr_t>(category_group_enabled);
+  DCHECK(category_ptr >= category_begin &&
+         category_ptr < reinterpret_cast<uintptr_t>(g_category_group_enabled +
+                                                    MAX_CATEGORY_GROUPS))
+      << "out of bounds category pointer";
+  uintptr_t category_index =
+      (category_ptr - category_begin) / sizeof(g_category_group_enabled[0]);
+
+  return category_index;
+}
+
 }  // namespace
 
 // A helper class that allows the lock to be acquired in the middle of the scope
 // and unlocks at the end of scope if locked.
 class TraceLog::OptionalAutoLock {
  public:
   explicit OptionalAutoLock(Lock* lock) : lock_(lock), locked_(false) {}
 
   ~OptionalAutoLock() {
     if (locked_)
@@ skipping 246 matching lines @@
   TraceLog* tracelog = GetInstance();
   if (!tracelog) {
     DCHECK(!g_category_group_enabled[g_category_already_shutdown]);
     return &g_category_group_enabled[g_category_already_shutdown];
   }
   return tracelog->GetCategoryGroupEnabledInternal(category_group);
 }
 
 const char* TraceLog::GetCategoryGroupName(
     const unsigned char* category_group_enabled) {
-  // Calculate the index of the category group by finding
-  // category_group_enabled in g_category_group_enabled array.
-  uintptr_t category_begin =
-      reinterpret_cast<uintptr_t>(g_category_group_enabled);
-  uintptr_t category_ptr = reinterpret_cast<uintptr_t>(category_group_enabled);
-  DCHECK(category_ptr >= category_begin &&
-         category_ptr < reinterpret_cast<uintptr_t>(g_category_group_enabled +
-                                                    MAX_CATEGORY_GROUPS))
-      << "out of bounds category pointer";
-  uintptr_t category_index =
-      (category_ptr - category_begin) / sizeof(g_category_group_enabled[0]);
-  return g_category_groups[category_index];
+  return g_category_groups[GetCategoryIndex(category_group_enabled)];
+}
+
+std::list<std::unique_ptr<TraceLog::TraceEventFilter>>* GetCategoryGroupFilter(
+    const unsigned char* category_group_enabled) {
+  return g_category_group_filter[GetCategoryIndex(category_group_enabled)]
+      .Pointer();
 }
 
 void TraceLog::UpdateCategoryGroupEnabledFlag(size_t category_index) {
   unsigned char enabled_flag = 0;
   const char* category_group = g_category_groups[category_index];
   if (mode_ == RECORDING_MODE &&
       trace_config_.IsCategoryGroupEnabled(category_group)) {
     enabled_flag |= ENABLED_FOR_RECORDING;
   }
 
   if (event_callback_ &&
       event_callback_trace_config_.IsCategoryGroupEnabled(category_group)) {
     enabled_flag |= ENABLED_FOR_EVENT_CALLBACK;
   }
 
 #if defined(OS_WIN)
   if (base::trace_event::TraceEventETWExport::IsCategoryGroupEnabled(
           category_group)) {
     enabled_flag |= ENABLED_FOR_ETW_EXPORT;
   }
 #endif
 
+  // Having a filter is an exceptional case, so we avoid
+  // the LazyInstance creation in the common case.
+  if (!(g_category_group_filter[category_index] == nullptr))
+    g_category_group_filter[category_index].Get().clear();
+
+  for (const auto& event_filter : trace_config_.event_filters()) {
+    if (event_filter.IsCategoryGroupEnabled(category_group)) {
+      std::unique_ptr<TraceEventFilter> new_filter;
+
+      if (event_filter.predicate_name() == "event_whitelist_predicate") {
+        new_filter =
+            WrapUnique(new EventNameFilter(event_filter.filter_args()));
+      } else if (event_filter.predicate_name() == "testing_predicate") {
+        CHECK(g_trace_event_filter_constructor_for_testing);
+        new_filter = g_trace_event_filter_constructor_for_testing();
+      }
+
+      if (new_filter) {
+        g_category_group_filter[category_index].Get().push_back(
+            std::move(new_filter));
+        enabled_flag |= ENABLED_FOR_FILTERING;
+      }
+    }
+  }
+
   g_category_group_enabled[category_index] = enabled_flag;
 }
 
 void TraceLog::UpdateCategoryGroupEnabledFlags() {
   size_t category_index = base::subtle::NoBarrier_Load(&g_category_index);
   for (size_t i = 0; i < category_index; i++)
     UpdateCategoryGroupEnabledFlag(i);
 }
 
 void TraceLog::UpdateSyntheticDelaysFromTraceConfig() {
@@ skipping 771 matching lines @@
 #if defined(OS_WIN)
   // This is done sooner rather than later, to avoid creating the event and
   // acquiring the lock, which is not needed for ETW as it's already threadsafe.
   if (*category_group_enabled & ENABLED_FOR_ETW_EXPORT)
     TraceEventETWExport::AddEvent(phase, category_group_enabled, name, id,
                                   num_args, arg_names, arg_types, arg_values,
                                   convertable_values);
 #endif  // OS_WIN
 
   std::string console_message;
-  if (*category_group_enabled & ENABLED_FOR_RECORDING) {
+  std::unique_ptr<TraceEvent> filtered_trace_event;
+  if (*category_group_enabled & ENABLED_FOR_FILTERING) {
+    std::unique_ptr<TraceEvent> new_trace_event(new TraceEvent);

[Primiano Tucci (use gerrit), 2016/05/31 15:41:24]

Can we avoid this to be heap allocated? What I found recently in the context of
TracingV2 is that malloc/new is not really fast. By looking at the code here it
seems filtered_trace_event could just be on the stack (+ a boolean to tell
whether it was actually filtered or not)

Post edit: Ohh I think i see why you did this, because of the signature of
TraceEvent::MoveFrom.
Ok that is my fault I think. There is no value in taking a unique_ptr there.
It should be TraceEvent::MoveFrom(TraceEvent&&).
Let's do something. Keep the new here temporarily but add a todo+bug to make
TraceEvent a proper move type. It should be a quick CL, but better to keep it
separate, there is enough stuff here :)

+    new_trace_event->Initialize(thread_id, offset_event_timestamp, thread_now,
+                                phase, category_group_enabled, name, scope, id,
+                                bind_id, num_args, arg_names, arg_types,
+                                arg_values, convertable_values, flags);
+
+    auto filter_list = GetCategoryGroupFilter(category_group_enabled);
+    DCHECK(!filter_list->empty());
+
+    bool should_add_event = false;
+    for (const auto& trace_event_filter : *filter_list) {
+      if (trace_event_filter->FilterTraceEvent(*new_trace_event))
+        should_add_event = true;
+    }
+
+    if (should_add_event)
+      filtered_trace_event = std::move(new_trace_event);
+  }
+
+  // Add the trace event if we're either *just* recording (and not filtering)
+  // or if we one of our filters indicates the event should be added.
+  if (((*category_group_enabled & ENABLED_FOR_RECORDING) &&
+       (*category_group_enabled & ENABLED_FOR_FILTERING) == 0) ||
+      filtered_trace_event) {
     OptionalAutoLock lock(&lock_);
 
     TraceEvent* trace_event = NULL;
     if (thread_local_event_buffer) {
       trace_event = thread_local_event_buffer->AddTraceEvent(&handle);
     } else {
       lock.EnsureAcquired();
       trace_event = AddEventToThreadSharedChunkWhileLocked(&handle, true);
     }
 
     if (trace_event) {
-      trace_event->Initialize(thread_id,
-                              offset_event_timestamp,
-                              thread_now,
-                              phase,
-                              category_group_enabled,
-                              name,
-                              scope,
-                              id,
-                              bind_id,
-                              num_args,
-                              arg_names,
-                              arg_types,
-                              arg_values,
-                              convertable_values,
-                              flags);
+      if (filtered_trace_event) {
+        trace_event->MoveFrom(std::move(filtered_trace_event));
+      } else {
+        trace_event->Initialize(thread_id, offset_event_timestamp, thread_now,
+                                phase, category_group_enabled, name, scope, id,
+                                bind_id, num_args, arg_names, arg_types,
+                                arg_values, convertable_values, flags);
+      }
 
 #if defined(OS_ANDROID)
       trace_event->SendToATrace();
 #endif
     }
 
     if (trace_options() & kInternalEchoToConsole) {
       console_message = EventToConsoleMessage(
           phase == TRACE_EVENT_PHASE_COMPLETE ? TRACE_EVENT_PHASE_BEGIN : phase,
           timestamp, trace_event);
@@ skipping 116 matching lines @@
     log << base::StringPrintf(" (%.3f ms)", duration.InMillisecondsF());
 
   log << "\x1b[0;m";
 
   if (phase == TRACE_EVENT_PHASE_BEGIN)
     thread_event_start_times_[thread_id].push(timestamp);
 
   return log.str();
 }
 
+void TraceLog::EndFilteredEvent(const unsigned char* category_group_enabled,
+                                const char* name,
+                                TraceEventHandle handle) {
+  auto filter_list = GetCategoryGroupFilter(category_group_enabled);
+  DCHECK(!filter_list->empty());
+
+  for (const auto& trace_event_filter : *filter_list) {
+    trace_event_filter->EndEvent(name,
+                                 GetCategoryGroupName(category_group_enabled));
+  }
+}
+
 void TraceLog::UpdateTraceEventDuration(
     const unsigned char* category_group_enabled,
     const char* name,
     TraceEventHandle handle) {
   char category_group_enabled_local = *category_group_enabled;
   if (!category_group_enabled_local)
     return;
 
   // Avoid re-entrance of AddTraceEvent. This may happen in GPU process when
   // ECHO_TO_CONSOLE is enabled: AddTraceEvent -> LOG(ERROR) ->
@@ skipping 149 matching lines @@
 void TraceLog::WaitSamplingEventForTesting() {
   if (!sampling_thread_)
     return;
   sampling_thread_->WaitSamplingEventForTesting();
 }
 
 void TraceLog::DeleteForTesting() {
   internal::DeleteTraceLogForTesting::Delete();
 }
 
+void TraceLog::SetTraceEventFilterConstructorForTesting(

[Primiano Tucci (use gerrit), 2016/05/31 15:41:24]

Drop this and jusd to TraceEventFilter::factory_for_testing = .... in the
unittest

+    TraceEventFilterConstructorForTesting predicate) {
+  g_trace_event_filter_constructor_for_testing = predicate;
+}
+
 TraceEvent* TraceLog::GetEventByHandle(TraceEventHandle handle) {
   return GetEventByHandleInternal(handle, NULL);
 }
 
 TraceEvent* TraceLog::GetEventByHandleInternal(TraceEventHandle handle,
                                                OptionalAutoLock* lock) {
   if (!handle.chunk_seq)
     return NULL;
 
   if (thread_local_event_buffer_.Get()) {
@@ skipping 171 matching lines @@
 }
 
 ScopedTraceBinaryEfficient::~ScopedTraceBinaryEfficient() {
   if (*category_group_enabled_) {
     TRACE_EVENT_API_UPDATE_TRACE_EVENT_DURATION(category_group_enabled_, name_,
                                                 event_handle_);
   }
 }
 
 }  // namespace trace_event_internal