Configure synthetic delays through TraceLog

Make it possible to configure synthetic delays using trace categories.
For example, the category filter "DELAY(gpu.SwapBuffers;16)" would make
swap buffers take at least 16 ms to complete.
    
BUG=307841

Review URL: https://codereview.chromium.org/98953002

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@244207 0039d316-1c4b-4281-b951-d872f2087c98

5 files changed, 141 insertions, 4 deletions

diff --git a/base/debug/trace_event_impl.cc b/base/debug/trace_event_impl.cc
index f17990e..b3e0cb8 100644
--- a/base/debug/trace_event_impl.cc
+++ b/base/debug/trace_event_impl.cc
@@ -11,6 +11,7 @@
 #include "base/command_line.h"
 #include "base/debug/leak_annotations.h"
 #include "base/debug/trace_event.h"
+#include "base/debug/trace_event_synthetic_delay.h"
 #include "base/format_macros.h"
 #include "base/json/string_escape.h"
 #include "base/lazy_instance.h"
@@ -72,6 +73,8 @@ const int kThreadFlushTimeoutMs = 3000;
 // These categories will cause deadlock when ECHO_TO_CONSOLE. crbug.com/325575.
 const char kEchoToConsoleCategoryFilter[] = "-ipc,-task";
 
+const char kSyntheticDelayCategoryFilterPrefix[] = "DELAY(";
+
 #define MAX_CATEGORY_GROUPS 100
 
 // Parallel arrays g_category_groups and g_category_group_enabled are separate
@@ -1209,6 +1212,31 @@ void TraceLog::UpdateCategoryGroupEnabledFlags() {
     UpdateCategoryGroupEnabledFlag(i);
 }
 
+void TraceLog::UpdateSyntheticDelaysFromCategoryFilter() {
+  ResetTraceEventSyntheticDelays();
+  const CategoryFilter::DelayValueList& delays =
+      category_filter_.GetSyntheticDelayValues();
+  CategoryFilter::DelayValueList::const_iterator ci;
+  for (ci = delays.begin(); ci != delays.end(); ++ci) {
+    TraceEventSyntheticDelay* delay =
+        TraceEventSyntheticDelay::Lookup(ci->first);
+    StringTokenizer tokens(ci->second, ";");
+    while (tokens.GetNext()) {
+      double target_duration;
+      if (StringToDouble(tokens.token(), &target_duration)) {
+        delay->SetTargetDuration(
+            TimeDelta::FromMicroseconds(target_duration * 1e6));
+      } else if (tokens.token() == "static") {
+        delay->SetMode(TraceEventSyntheticDelay::STATIC);
+      } else if (tokens.token() == "oneshot") {
+        delay->SetMode(TraceEventSyntheticDelay::ONE_SHOT);
+      } else if (tokens.token() == "alternating") {
+        delay->SetMode(TraceEventSyntheticDelay::ALTERNATING);
+      }
+    }
+  }
+}
+
 const unsigned char* TraceLog::GetCategoryGroupEnabledInternal(
     const char* category_group) {
   DCHECK(!strchr(category_group, '"')) <<
@@ -1303,6 +1331,7 @@ void TraceLog::SetEnabled(const CategoryFilter& category_filter,
 
     category_filter_ = CategoryFilter(category_filter);
     UpdateCategoryGroupEnabledFlags();
+    UpdateSyntheticDelaysFromCategoryFilter();
 
     if (options & ENABLE_SAMPLING) {
       sampling_thread_.reset(new TraceSamplingThread);
@@ -2176,7 +2205,8 @@ CategoryFilter::CategoryFilter(const std::string& filter_string) {
 CategoryFilter::CategoryFilter(const CategoryFilter& cf)
     : included_(cf.included_),
       disabled_(cf.disabled_),
-      excluded_(cf.excluded_) {
+      excluded_(cf.excluded_),
+      delays_(cf.delays_) {
 }
 
 CategoryFilter::~CategoryFilter() {
@@ -2189,6 +2219,7 @@ CategoryFilter& CategoryFilter::operator=(const CategoryFilter& rhs) {
   included_ = rhs.included_;
   disabled_ = rhs.disabled_;
   excluded_ = rhs.excluded_;
+  delays_ = rhs.delays_;
   return *this;
 }
 
@@ -2201,8 +2232,20 @@ void CategoryFilter::Initialize(const std::string& filter_string) {
     // Ignore empty categories.
     if (category.empty())
       continue;
-    // Excluded categories start with '-'.
-    if (category.at(0) == '-') {
+    // Synthetic delays are of the form 'DELAY(delay;option;option;...)'.
+    if (category.find(kSyntheticDelayCategoryFilterPrefix) == 0 &&
+        category.at(category.size() - 1) == ')') {
+      category = category.substr(
+          strlen(kSyntheticDelayCategoryFilterPrefix),
+          category.size() - strlen(kSyntheticDelayCategoryFilterPrefix) - 1);
+      size_t name_length = category.find(';');
+      if (name_length != std::string::npos && name_length > 0 &&
+          name_length != category.size() - 1) {
+        delays_.push_back(DelayValue(category.substr(0, name_length),
+                                     category.substr(name_length + 1)));
+      }
+    } else if (category.at(0) == '-') {
+      // Excluded categories start with '-'.
       // Remove '-' from category string.
       category = category.substr(1);
       excluded_.push_back(category);
@@ -2229,11 +2272,26 @@ void CategoryFilter::WriteString(const StringList& values,
   }
 }
 
+void CategoryFilter::WriteString(const DelayValueList& delays,
+                                 std::string* out) const {
+  bool prepend_comma = !out->empty();
+  int token_cnt = 0;
+  for (DelayValueList::const_iterator ci = delays.begin();
+       ci != delays.end(); ++ci) {
+    if (token_cnt > 0 || prepend_comma)
+      StringAppendF(out, ",");
+    StringAppendF(out, "%s%s;%s)", kSyntheticDelayCategoryFilterPrefix,
+                  ci->first.c_str(), ci->second.c_str());
+    ++token_cnt;
+  }
+}
+
 std::string CategoryFilter::ToString() const {
   std::string filter_string;
   WriteString(included_, &filter_string, true);
   WriteString(disabled_, &filter_string, true);
   WriteString(excluded_, &filter_string, false);
+  WriteString(delays_, &filter_string);
   return filter_string;
 }
 
@@ -2289,6 +2347,9 @@ void CategoryFilter::Merge(const CategoryFilter& nested_filter) {
   excluded_.insert(excluded_.end(),
                    nested_filter.excluded_.begin(),
                    nested_filter.excluded_.end());
+  delays_.insert(delays_.end(),
+                 nested_filter.delays_.begin(),
+                 nested_filter.delays_.end());
 }
 
 void CategoryFilter::Clear() {
@@ -2297,6 +2358,11 @@ void CategoryFilter::Clear() {
   excluded_.clear();
 }
 
+const CategoryFilter::DelayValueList&
+    CategoryFilter::GetSyntheticDelayValues() const {
+  return delays_;
+}
+
 }  // namespace debug
 }  // namespace base
 
diff --git a/base/debug/trace_event_impl.h b/base/debug/trace_event_impl.h
index 7dd4a00..e84ccbe 100644
--- a/base/debug/trace_event_impl.h
+++ b/base/debug/trace_event_impl.h
@@ -283,6 +283,9 @@ class BASE_EXPORT TraceResultBuffer {
 
 class BASE_EXPORT CategoryFilter {
  public:
+  typedef std::pair<std::string, std::string> DelayValue;
+  typedef std::vector<DelayValue> DelayValueList;
+
   // The default category filter, used when none is provided.
   // Allows all categories through, except if they end in the suffix 'Debug' or
   // 'Test'.
@@ -298,6 +301,16 @@ class BASE_EXPORT CategoryFilter {
   // Example: CategoryFilter("-excluded_category1,-excluded_category2");
   // Example: CategoryFilter("-*,webkit"); would disable everything but webkit.
   // Example: CategoryFilter("-webkit"); would enable everything but webkit.
+  //
+  // Category filters can also be used to configure synthetic delays.
+  //
+  // Example: CategoryFilter("DELAY(gpu.SwapBuffers;16)"); would make swap
+  //          buffers always take at least 16 ms.
+  // Example: CategoryFilter("DELAY(gpu.SwapBuffers;16;oneshot)"); would
+  //          make swap buffers take at least 16 ms the first time it is called.
+  // Example: CategoryFilter("DELAY(gpu.SwapBuffers;16;alternating)"); would
+  //          make swap buffers take at least 16 ms every other time it is
+  //          called.
   explicit CategoryFilter(const std::string& filter_string);
 
   CategoryFilter(const CategoryFilter& cf);
@@ -317,6 +330,9 @@ class BASE_EXPORT CategoryFilter {
   // disabled by this category filter.
   bool IsCategoryGroupEnabled(const char* category_group) const;
 
+  // Return a list of the synthetic delays specified in this category filter.
+  const DelayValueList& GetSyntheticDelayValues() const;
+
   // Merges nested_filter with the current CategoryFilter
   void Merge(const CategoryFilter& nested_filter);
 
@@ -340,6 +356,7 @@ class BASE_EXPORT CategoryFilter {
   void WriteString(const StringList& values,
                    std::string* out,
                    bool included) const;
+  void WriteString(const DelayValueList& delays, std::string* out) const;
   bool HasIncludedPatterns() const;
 
   bool DoesCategoryGroupContainCategory(const char* category_group,
@@ -348,6 +365,7 @@ class BASE_EXPORT CategoryFilter {
   StringList included_;
   StringList disabled_;
   StringList excluded_;
+  DelayValueList delays_;
 };
 
 class TraceSamplingThread;
@@ -606,6 +624,10 @@ class BASE_EXPORT TraceLog {
   void UpdateCategoryGroupEnabledFlags();
   void UpdateCategoryGroupEnabledFlag(int category_index);
 
+  // Configure synthetic delays based on the values set in the current
+  // category filter.
+  void UpdateSyntheticDelaysFromCategoryFilter();
+
   class ThreadLocalEventBuffer;
   class OptionalAutoLock;
 
diff --git a/base/debug/trace_event_synthetic_delay.cc b/base/debug/trace_event_synthetic_delay.cc
index 0d07a70..ab18809 100644
--- a/base/debug/trace_event_synthetic_delay.cc
+++ b/base/debug/trace_event_synthetic_delay.cc
@@ -190,8 +190,10 @@ base::TimeTicks TraceEventSyntheticDelayRegistry::Now() {
 void TraceEventSyntheticDelayRegistry::ResetAllDelays() {
   AutoLock lock(lock_);
   int delay_count = base::subtle::Acquire_Load(&delay_count_);
-  for (int i = 0; i < delay_count; ++i)
+  for (int i = 0; i < delay_count; ++i) {
     delays_[i].SetTargetDuration(base::TimeDelta());
+    delays_[i].SetClock(this);
+  }
 }
 
 void ResetTraceEventSyntheticDelays() {
diff --git a/base/debug/trace_event_synthetic_delay_unittest.cc b/base/debug/trace_event_synthetic_delay_unittest.cc
index 2642b16..7833e7b 100644
--- a/base/debug/trace_event_synthetic_delay_unittest.cc
+++ b/base/debug/trace_event_synthetic_delay_unittest.cc
@@ -21,6 +21,9 @@ class TraceEventSyntheticDelayTest : public testing::Test,
                                      public TraceEventSyntheticDelayClock {
  public:
   TraceEventSyntheticDelayTest() {}
+  virtual ~TraceEventSyntheticDelayTest() {
+    ResetTraceEventSyntheticDelays();
+  }
 
   // TraceEventSyntheticDelayClock implementation.
   virtual base::TimeTicks Now() OVERRIDE {
diff --git a/base/debug/trace_event_unittest.cc b/base/debug/trace_event_unittest.cc
index d71b242..1753b24 100644
--- a/base/debug/trace_event_unittest.cc
+++ b/base/debug/trace_event_unittest.cc
@@ -9,6 +9,7 @@
 #include "base/bind.h"
 #include "base/command_line.h"
 #include "base/debug/trace_event.h"
+#include "base/debug/trace_event_synthetic_delay.h"
 #include "base/json/json_reader.h"
 #include "base/json/json_writer.h"
 #include "base/memory/ref_counted_memory.h"
@@ -2634,5 +2635,48 @@ TEST_F(TraceEventTestFixture, TimeOffset) {
   }
 }
 
+TEST_F(TraceEventTestFixture, ConfigureSyntheticDelays) {
+  BeginSpecificTrace("DELAY(test.Delay;0.05)");
+
+  base::TimeTicks start = base::TimeTicks::Now();
+  {
+    TRACE_EVENT_SYNTHETIC_DELAY("test.Delay");
+  }
+  base::TimeDelta duration = base::TimeTicks::Now() - start;
+  EXPECT_GE(duration.InMilliseconds(), 50);
+
+  EndTraceAndFlush();
+}
+
+TEST_F(TraceEventTestFixture, BadSyntheticDelayConfigurations) {
+  const char* configs[] = {
+    "",
+    "DELAY(",
+    "DELAY(;",
+    "DELAY(;)",
+    "DELAY(test.Delay)",
+    "DELAY(test.Delay;)"
+  };
+  for (size_t i = 0; i < arraysize(configs); i++) {
+    BeginSpecificTrace(configs[i]);
+    EndTraceAndFlush();
+    CategoryFilter filter = TraceLog::GetInstance()->GetCurrentCategoryFilter();
+    EXPECT_EQ(0u, filter.GetSyntheticDelayValues().size());
+  }
+}
+
+TEST_F(TraceEventTestFixture, SyntheticDelayConfigurationMerging) {
+  CategoryFilter filter1("DELAY(test.Delay1;16)");
+  CategoryFilter filter2("DELAY(test.Delay2;32)");
+  filter1.Merge(filter2);
+  EXPECT_EQ(2u, filter1.GetSyntheticDelayValues().size());
+}
+
+TEST_F(TraceEventTestFixture, SyntheticDelayConfigurationToString) {
+  const char config[] = "DELAY(test.Delay;16;oneshot)";
+  CategoryFilter filter(config);
+  EXPECT_EQ(config, filter.ToString());
+}
+
 }  // namespace debug
 }  // namespace base