Fix races in trace events 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>
@@ skipping 88 matching lines @@
     "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};
 
 const char kEventNameWhitelist[] = "event_name_whitelist";
 
+#define MAX_TRACE_EVENT_FILTERS 32
+
+// List of TraceEventFilter objects from the most recent tracing session.
+base::LazyInstance<std::vector<std::unique_ptr<TraceLog::TraceEventFilter>>>::
+    Leaky g_category_group_filters = LAZY_INSTANCE_INITIALIZER;
+
+// Stores a bitmap of filters enabled for each category group.
+uint32_t g_category_group_filters_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(kEventNameWhitelist, &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};
-
 // This filter is used to record trace events as pseudo stack for the heap
 // profiler. It does not filter-out any events from the trace, ie. the behavior
 // of trace events being added to TraceLog remains same: the events are added
 // iff enabled for recording and not filtered-out by any other filter.
 class HeapProfilerFilter : public TraceLog::TraceEventFilter {
  public:
   HeapProfilerFilter() {}
 
   bool FilterTraceEvent(const TraceEvent& trace_event) const override {
     if (AllocationContextTracker::capture_mode() !=
@@ skipping 120 matching lines @@
   DCHECK(category_ptr >= category_begin);
   DCHECK(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;
 }
 
+template <typename Function>
+void ForEachCategoryGroupFilter(const unsigned char* category_group_enabled,
+                                Function filter_fn) {
+  uint32_t filter_bitmap = g_category_group_filters_enabled[GetCategoryIndex(
+      category_group_enabled)];
+  int index = 0;
+  while (filter_bitmap) {
+    if (filter_bitmap & 1 && g_category_group_filters.Get()[index])
+      filter_fn(g_category_group_filters.Get()[index].get());
+    filter_bitmap = filter_bitmap >> 1;
+    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 249 matching lines @@
     return &g_category_group_enabled[kCategoryAlreadyShutdown];
   }
   return tracelog->GetCategoryGroupEnabledInternal(category_group);
 }
 
 const char* TraceLog::GetCategoryGroupName(
     const unsigned char* category_group_enabled) {
   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
 
   // TODO(primiano): this is a temporary workaround for catapult:#2341,
   // to guarantee that metadata events are always added even if the category
   // filter is "-*". See crbug.com/618054 for more details and long-term fix.
   if (mode_ == RECORDING_MODE && !strcmp(category_group, "__metadata"))
     enabled_flag |= ENABLED_FOR_RECORDING;
 
-  // 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();
-
+  uint32_t enabled_filters_bitmap = 0;
+  unsigned index = 0;

[oystein (OOO til 10th of July), 2016/09/16 19:09:00]

nit: We don't use 'unsigned' as a bare type outside of Blink, just make it an
'int'.

[ssid, 2016/09/21 00:20:26]

Done.

   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() ==
-          TraceEventFilter::kEventWhitelistPredicate) {
-        new_filter = MakeUnique<EventNameFilter>(event_filter.filter_args());
-      } else if (event_filter.predicate_name() ==
-                 TraceEventFilter::kHeapProfilerPredicate) {
-        new_filter = MakeUnique<HeapProfilerFilter>();
-      } 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;
-      }
+      enabled_flag |= ENABLED_FOR_FILTERING;
+      DCHECK(g_category_group_filters.Get()[index]);
+      enabled_filters_bitmap |= 1 << index;
+    }
+    if (index++ >= MAX_TRACE_EVENT_FILTERS) {
+      NOTREACHED();
+      break;
     }
   }
+  g_category_group_filters_enabled[category_index] = enabled_filters_bitmap;
 
   g_category_group_enabled[category_index] = enabled_flag;
 }
 
 void TraceLog::UpdateCategoryGroupEnabledFlags() {
+  CreateFiltersForTraceConfig();
   size_t category_index = base::subtle::NoBarrier_Load(&g_category_index);
   for (size_t i = 0; i < category_index; i++)
     UpdateCategoryGroupEnabledFlag(i);
 }
 
+void TraceLog::CreateFiltersForTraceConfig() {
+  // Filters were already added and tracing could be enabled. Filters list
+  // cannot be changed when trace events are using them.
+  if (g_category_group_filters.Get().size())
+    return;
+
+  for (auto& event_filter : trace_config_.event_filters()) {
+    if (g_category_group_filters.Get().size() >= MAX_TRACE_EVENT_FILTERS) {
+      LOG(ERROR)
+          << "Too many trace event filters installed in the current session";
+      NOTREACHED();

[oystein (OOO til 10th of July), 2016/09/16 19:09:00]

Just stream the error message into NOTREACHED() instead.

[ssid, 2016/09/21 00:20:26]

Done.

+      break;
+    }
+
+    std::unique_ptr<TraceEventFilter> new_filter;
+    if (event_filter.predicate_name() ==
+        TraceEventFilter::kEventWhitelistPredicate) {
+      new_filter = MakeUnique<EventNameFilter>(event_filter.filter_args());
+    } else if (event_filter.predicate_name() ==
+               TraceEventFilter::kHeapProfilerPredicate) {
+      new_filter = MakeUnique<HeapProfilerFilter>();
+    } 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();
+    } else {
+      NOTREACHED();
+    }
+    g_category_group_filters.Get().push_back(std::move(new_filter));
+  }
+}
+
 void TraceLog::UpdateSyntheticDelaysFromTraceConfig() {
   ResetTraceEventSyntheticDelays();
   const TraceConfig::StringList& delays =
       trace_config_.GetSyntheticDelayValues();
   TraceConfig::StringList::const_iterator ci;
   for (ci = delays.begin(); ci != delays.end(); ++ci) {
     StringTokenizer tokens(*ci, ";");
     if (!tokens.GetNext())
       continue;
     TraceEventSyntheticDelay* delay =
@@ skipping 93 matching lines @@
     if (IsEnabled()) {
       if (new_options != old_options) {
         DLOG(ERROR) << "Attempting to re-enable tracing with a different "
                     << "set of options.";
       }
 
       if (mode != mode_) {
         DLOG(ERROR) << "Attempting to re-enable tracing with a different mode.";
       }
 
+      if (trace_config.event_filters().size()) {
+        DLOG(ERROR) << "Adding new filters while tracing was already enabled "

[oystein (OOO til 10th of July), 2016/09/16 19:09:00]

I think DLOG() is discouraged these days because it just spams the logs and are
never checked anywhere. I would just make it a DCHECK.

[ssid, 2016/09/21 00:20:26]

Done.

+                       "is not supported.";
+      }
+
       trace_config_.Merge(trace_config);
       UpdateCategoryGroupEnabledFlags();
       return;
     }
 
     if (dispatching_to_observer_list_) {
       DLOG(ERROR)
           << "Cannot manipulate TraceLog::Enabled state from an observer.";
       return;
     }
 
     mode_ = mode;
 
     if (new_options != old_options) {
       subtle::NoBarrier_Store(&trace_options_, new_options);
       UseNextTraceBuffer();
     }
 
     num_traces_recorded_++;
 
+    // Clear all filters from previous tracing session. These filters are not
+    // cleared at the end of tracing because some threads which hit trace event
+    // when disabling, could try to use the filters.
+    g_category_group_filters.Get().clear();
+
     trace_config_ = TraceConfig(trace_config);
     UpdateCategoryGroupEnabledFlags();
     UpdateSyntheticDelaysFromTraceConfig();
 
     if (new_options & kInternalEnableSampling) {
       sampling_thread_.reset(new TraceSamplingThread);
       sampling_thread_->RegisterSampleBucket(
           &g_trace_state[0], "bucket0",
           Bind(&TraceSamplingThread::DefaultSamplingCallback));
       sampling_thread_->RegisterSampleBucket(
@@ skipping 633 matching lines @@
   std::string console_message;
   std::unique_ptr<TraceEvent> filtered_trace_event;
   bool disabled_by_filters = false;
   if (*category_group_enabled & ENABLED_FOR_FILTERING) {
     std::unique_ptr<TraceEvent> new_trace_event(new TraceEvent);
     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());
-
     disabled_by_filters = true;
-    for (const auto& trace_event_filter : *filter_list) {
-      if (trace_event_filter->FilterTraceEvent(*new_trace_event))
-        disabled_by_filters = false;
-    }
-
+    ForEachCategoryGroupFilter(
+        category_group_enabled, [&new_trace_event, &disabled_by_filters](
+                                    TraceEventFilter* trace_event_filter) {
+          if (trace_event_filter->FilterTraceEvent(*new_trace_event))
+            disabled_by_filters = false;
+        });
     if (!disabled_by_filters)
       filtered_trace_event = std::move(new_trace_event);
   }
 
   // If enabled for recording, the event should be added only if one of the
   // filters indicates or category is not enabled for filtering.
   if ((*category_group_enabled & ENABLED_FOR_RECORDING) &&
       !disabled_by_filters) {
     OptionalAutoLock lock(&lock_);
 
@@ skipping 130 matching lines @@
 
   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));
-  }
+  const char* category_name = GetCategoryGroupName(category_group_enabled);
+  ForEachCategoryGroupFilter(
+      category_group_enabled,
+      [name, category_name](TraceEventFilter* trace_event_filter) {
+        trace_event_filter->EndEvent(name, category_name);
+      });
 }
 
 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;
 
@@ skipping 51 matching lines @@
   if (category_group_enabled_local & ENABLED_FOR_EVENT_CALLBACK) {
     EventCallback event_callback = reinterpret_cast<EventCallback>(
         subtle::NoBarrier_Load(&event_callback_));
     if (event_callback) {
       event_callback(
         now, TRACE_EVENT_PHASE_END, category_group_enabled, name,
         trace_event_internal::kGlobalScope, trace_event_internal::kNoId, 0,
         nullptr, nullptr, nullptr, TRACE_EVENT_FLAG_NONE);
     }
   }
+
+  if (category_group_enabled_local & ENABLED_FOR_FILTERING)
+    EndFilteredEvent(category_group_enabled, name, handle);
 }
 
 void TraceLog::SetWatchEvent(const std::string& category_name,
                              const std::string& event_name,
                              const WatchEventCallback& callback) {
   const unsigned char* category =
       GetCategoryGroupEnabled(category_name.c_str());
   AutoLock lock(lock_);
   subtle::NoBarrier_Store(&watch_category_,
                           reinterpret_cast<subtle::AtomicWord>(category));
@@ skipping 276 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