[tracing] Add filtering mode in TraceLog

base/trace_event/trace_event_unittest.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/trace_event/trace_event.h"
 
 #include <math.h>
 #include <stddef.h>
 #include <stdint.h>
 
@@ skipping 118 matching lines @@
   }
 
   void CancelTraceAsync(WaitableEvent* flush_complete_event) {
     TraceLog::GetInstance()->CancelTracing(
         base::Bind(&TraceEventTestFixture::OnTraceDataCollected,
                    base::Unretained(static_cast<TraceEventTestFixture*>(this)),
                    base::Unretained(flush_complete_event)));
   }
 
   void EndTraceAndFlushAsync(WaitableEvent* flush_complete_event) {
-    TraceLog::GetInstance()->SetDisabled();
+    TraceLog::GetInstance()->SetDisabled(TraceLog::RECORDING_MODE |
+                                         TraceLog::FILTERING_MODE);
     TraceLog::GetInstance()->Flush(
         base::Bind(&TraceEventTestFixture::OnTraceDataCollected,
                    base::Unretained(static_cast<TraceEventTestFixture*>(this)),
                    base::Unretained(flush_complete_event)));
   }
 
   void SetUp() override {
     const char* name = PlatformThread::GetName();
     old_thread_name_ = name ? strdup(name) : NULL;
 
@@ skipping 3049 matching lines @@
 TEST_F(TraceEventTestFixture, SyntheticDelayConfigurationToString) {
   const char filter[] = "DELAY(test.Delay;16;oneshot)";
   TraceConfig config(filter, "");
   EXPECT_EQ(filter, config.ToCategoryFilterString());
 }
 
 class TestEventFilter : public TraceLog::TraceEventFilter {
  public:
   bool FilterTraceEvent(const TraceEvent& trace_event) const override {
     filter_trace_event_hit_count_++;
-    return true;
+    return filter_return_value_;
   }
 
   void EndEvent(const char* category_group, const char* name) override {
     end_event_hit_count_++;
   }
 
+  static void set_filter_return_value(bool value) {
+    filter_return_value_ = value;
+  }
+
   static size_t filter_trace_event_hit_count() {
     return filter_trace_event_hit_count_;
   }
   static size_t end_event_hit_count() { return end_event_hit_count_; }
 
+  static void clear_counts() {
+    filter_trace_event_hit_count_ = 0;
+    end_event_hit_count_ = 0;
+  }
+
  private:
   static size_t filter_trace_event_hit_count_;
   static size_t end_event_hit_count_;
+  static bool filter_return_value_;
 };
 
 size_t TestEventFilter::filter_trace_event_hit_count_ = 0;
 size_t TestEventFilter::end_event_hit_count_ = 0;
+bool TestEventFilter::filter_return_value_ = false;
 
 std::unique_ptr<TraceLog::TraceEventFilter> ConstructTestEventFilter() {
   return WrapUnique(new TestEventFilter);
 }
 
+TEST_F(TraceEventTestFixture, TraceFilteringMode) {
+  const char config_json[] =
+      "{"
+      "  \"event_filters\": ["
+      "     {"
+      "       \"filter_predicate\": \"testing_predicate\", "
+      "       \"included_categories\": [\"*\"]"
+      "     }"
+      "  ]"
+      "}";
+
+  // Run RECORDING_MODE within FILTERING_MODE.
+  TestEventFilter::set_filter_return_value(true);
+  TraceLog::SetTraceEventFilterConstructorForTesting(ConstructTestEventFilter);
+  TraceLog::GetInstance()->SetEnabled(TraceConfig(config_json),
+                                      TraceLog::FILTERING_MODE);
+  EXPECT_EQ(TraceLog::FILTERING_MODE, TraceLog::GetInstance()->enabled_modes());

[Primiano Tucci (use gerrit), 2016/10/12 17:50:17]

can you add some comments every time you do setenabled/disabled to explain what
do you expect to happen?
Thanks

[ssid, 2016/10/12 19:04:43]

Done.

+  {

[Primiano Tucci (use gerrit), 2016/10/12 17:50:17]

why there are scope enclosers here? is it just for readability (in which case
fine)? or is there some other subtle thing going on?

[ssid, 2016/10/12 19:04:43]

I am measuring the end_event_hit_count. To check the number of EndEvent calls is
consistent.

+    void* ptr = this;
+    TRACE_EVENT0("c0", "name0");
+    TRACE_EVENT_ASYNC_BEGIN0("c1", "name1", ptr);
+    TRACE_EVENT_INSTANT0("c0", "name0", TRACE_EVENT_SCOPE_THREAD);
+    TRACE_EVENT_ASYNC_END0("c1", "name1", ptr);
+  }
+  TraceLog::GetInstance()->SetEnabled(TraceConfig("", ""),
+                                      TraceLog::RECORDING_MODE);
+  EXPECT_EQ(TraceLog::RECORDING_MODE | TraceLog::FILTERING_MODE,
+            TraceLog::GetInstance()->enabled_modes());
+  { TRACE_EVENT0("c2", "name2"); }

[Primiano Tucci (use gerrit), 2016/10/12 17:50:17]

here either use newlines (e.g. {\nTRACE...\n}) or drop the braces. don't feel
this adds much readability for one line

[ssid, 2016/10/12 19:04:43]

Um, this is a fight against git cl format :(

+  TraceLog::GetInstance()->SetDisabled();
+  EXPECT_EQ(TraceLog::FILTERING_MODE, TraceLog::GetInstance()->enabled_modes());
+  { TRACE_EVENT0("c0", "name0"); }
+  TraceLog::GetInstance()->SetDisabled(TraceLog::FILTERING_MODE);
+  EXPECT_EQ(0, TraceLog::GetInstance()->enabled_modes());
+
+  EndTraceAndFlush();
+  EXPECT_FALSE(FindMatchingValue("cat", "c0"));
+  EXPECT_FALSE(FindMatchingValue("cat", "c1"));
+  EXPECT_FALSE(FindMatchingValue("name", "name0"));
+  EXPECT_FALSE(FindMatchingValue("name", "name1"));
+  EXPECT_TRUE(FindMatchingValue("cat", "c2"));
+  EXPECT_TRUE(FindMatchingValue("name", "name2"));
+  EXPECT_EQ(6u, TestEventFilter::filter_trace_event_hit_count());
+  EXPECT_EQ(3u, TestEventFilter::end_event_hit_count());
+  Clear();
+  TestEventFilter::clear_counts();
+
+  // Run FILTERING_MODE within RECORDING_MODE.
+  TestEventFilter::set_filter_return_value(false);
+  TraceLog::GetInstance()->SetEnabled(TraceConfig("", ""),
+                                      TraceLog::RECORDING_MODE);
+  EXPECT_EQ(TraceLog::RECORDING_MODE, TraceLog::GetInstance()->enabled_modes());
+  { TRACE_EVENT0("c0", "name0"); }
+  TraceLog::GetInstance()->SetEnabled(TraceConfig(config_json),
+                                      TraceLog::FILTERING_MODE);
+  EXPECT_EQ(TraceLog::RECORDING_MODE | TraceLog::FILTERING_MODE,
+            TraceLog::GetInstance()->enabled_modes());
+  { TRACE_EVENT0("c1", "name1"); }
+  TraceLog::GetInstance()->SetDisabled(TraceLog::FILTERING_MODE);
+  EXPECT_EQ(TraceLog::RECORDING_MODE, TraceLog::GetInstance()->enabled_modes());
+  { TRACE_EVENT0("c2", "name2"); }
+  TraceLog::GetInstance()->SetDisabled();
+  EXPECT_EQ(0, TraceLog::GetInstance()->enabled_modes());
+
+  EndTraceAndFlush();
+  EXPECT_TRUE(FindMatchingValue("cat", "c0"));
+  EXPECT_TRUE(FindMatchingValue("cat", "c2"));
+  EXPECT_TRUE(FindMatchingValue("name", "name0"));
+  EXPECT_TRUE(FindMatchingValue("name", "name2"));
+  EXPECT_FALSE(FindMatchingValue("cat", "c1"));
+  EXPECT_FALSE(FindMatchingValue("name", "name1"));
+  EXPECT_EQ(1u, TestEventFilter::filter_trace_event_hit_count());
+  EXPECT_EQ(1u, TestEventFilter::end_event_hit_count());
+  Clear();
+  TestEventFilter::clear_counts();
+}
+
 TEST_F(TraceEventTestFixture, EventFiltering) {
   const char config_json[] =
       "{"
       "  \"included_categories\": ["
       "    \"filtered_cat\","
       "    \"unfiltered_cat\"],"
       "  \"event_filters\": ["
       "     {"
       "       \"filter_predicate\": \"testing_predicate\", "
       "       \"included_categories\": [\"filtered_cat\"]"
       "     }"
       "    "
       "  ]"
       "}";
 
+  TestEventFilter::set_filter_return_value(true);
   TraceLog::SetTraceEventFilterConstructorForTesting(ConstructTestEventFilter);
   TraceConfig trace_config(config_json);
-  TraceLog::GetInstance()->SetEnabled(trace_config, TraceLog::RECORDING_MODE);
+  TraceLog::GetInstance()->SetEnabled(
+      trace_config, TraceLog::RECORDING_MODE | TraceLog::FILTERING_MODE);
   ASSERT_TRUE(TraceLog::GetInstance()->IsEnabled());
 
   TRACE_EVENT0("filtered_cat", "a snake");
   TRACE_EVENT0("filtered_cat", "a mushroom");
   TRACE_EVENT0("unfiltered_cat", "a horse");
 
   // This is scoped so we can test the end event being filtered.
   { TRACE_EVENT0("filtered_cat", "another cat whoa"); }
 
   EndTraceAndFlush();
 
   EXPECT_EQ(3u, TestEventFilter::filter_trace_event_hit_count());
   EXPECT_EQ(1u, TestEventFilter::end_event_hit_count());
+  TestEventFilter::clear_counts();
 }
 
 TEST_F(TraceEventTestFixture, EventWhitelistFiltering) {
   std::string config_json = StringPrintf(
       "{"
       "  \"included_categories\": ["
       "    \"filtered_cat\","
       "    \"unfiltered_cat\"],"
       "  \"event_filters\": ["
       "     {"
       "       \"filter_predicate\": \"%s\", "
       "       \"included_categories\": [\"*\"], "
       "       \"excluded_categories\": [\"unfiltered_cat\"], "
       "       \"filter_args\": {"
       "           \"event_name_whitelist\": [\"a snake\", \"a dog\"]"
       "         }"
       "     }"
       "    "
       "  ]"
       "}",
       TraceLog::TraceEventFilter::kEventWhitelistPredicate);
 
   TraceConfig trace_config(config_json);
-  TraceLog::GetInstance()->SetEnabled(trace_config, TraceLog::RECORDING_MODE);
+  TraceLog::GetInstance()->SetEnabled(
+      trace_config, TraceLog::RECORDING_MODE | TraceLog::FILTERING_MODE);
   EXPECT_TRUE(TraceLog::GetInstance()->IsEnabled());
 
   TRACE_EVENT0("filtered_cat", "a snake");
   TRACE_EVENT0("filtered_cat", "a mushroom");
   TRACE_EVENT0("unfiltered_cat", "a cat");
 
   EndTraceAndFlush();
 
   EXPECT_TRUE(FindMatchingValue("name", "a snake"));
   EXPECT_FALSE(FindMatchingValue("name", "a mushroom"));
@@ skipping 10 matching lines @@
       "  \"event_filters\": ["
       "     {"
       "       \"filter_predicate\": \"%s\", "
       "       \"included_categories\": [\"*\"]"
       "     }"
       "  ]"
       "}",
       TraceLog::TraceEventFilter::kHeapProfilerPredicate);
 
   TraceConfig trace_config(config_json);
-  TraceLog::GetInstance()->SetEnabled(trace_config, TraceLog::RECORDING_MODE);
+  TraceLog::GetInstance()->SetEnabled(
+      trace_config, TraceLog::RECORDING_MODE | TraceLog::FILTERING_MODE);
   EXPECT_TRUE(TraceLog::GetInstance()->IsEnabled());
 
   TRACE_EVENT0("filtered_cat", "a snake");
   TRACE_EVENT0("excluded_cat", "a mushroom");
   TRACE_EVENT0("unfiltered_cat", "a cat");
 
   EndTraceAndFlush();
 
   // The predicate should not change behavior of the trace events.
   EXPECT_TRUE(FindMatchingValue("name", "a snake"));
   EXPECT_FALSE(FindMatchingValue("name", "a mushroom"));
   EXPECT_TRUE(FindMatchingValue("name", "a cat"));
 }
 
 TEST_F(TraceEventTestFixture, ClockSyncEventsAreAlwaysAddedToTrace) {
   BeginSpecificTrace("-*");
   TRACE_EVENT_CLOCK_SYNC_RECEIVER(1);
   EndTraceAndFlush();
   EXPECT_TRUE(FindNamePhase("clock_sync", "c"));
 }
 
 }  // namespace trace_event
 }  // namespace base