Use Begin/End semantics for synthetic delays

    
Currently synthetic delays use an Activate/Apply scheme were Activate
can be called several times and a single call to Apply will execute the
delay. Both calls need to happen on the same thread.
    
This patch changes this to a Begin/End model where the delay start point
is designated with Begin and executed with End. Both calls can happen on
any thread for a given delay. Calls can also be nested so that the inner
Begin/End pairs do nothing and only the outermost End will apply the
delay.
    
This change is primarily to make it easier to integrate synthetic delays
to asynchronous tasks such as texture uploads. One only needs to call
Begin for every queued task and then End in each individual tasks to
apply the delay automatically to a "burst" of work.
    
This patch also introduces parallel versions of Begin and End. They are
useful for several applying independent instances of the same delay.
    
We also add a function for resetting all registered synthetic delays.
This is needed for telemetry tests to reset delays to a clean slate
between pages.

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

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

3 files changed, 156 insertions, 111 deletions

diff --git a/base/debug/trace_event_synthetic_delay.cc b/base/debug/trace_event_synthetic_delay.cc
index 939d960..0d07a70 100644
--- a/base/debug/trace_event_synthetic_delay.cc
+++ b/base/debug/trace_event_synthetic_delay.cc
@@ -4,8 +4,6 @@
 
 #include "base/debug/trace_event_synthetic_delay.h"
 #include "base/memory/singleton.h"
-#include "base/threading/platform_thread.h"
-#include "base/threading/thread_local.h"
 
 namespace {
 const int kMaxSyntheticDelays = 32;
@@ -17,24 +15,12 @@ namespace debug {
 TraceEventSyntheticDelayClock::TraceEventSyntheticDelayClock() {}
 TraceEventSyntheticDelayClock::~TraceEventSyntheticDelayClock() {}
 
-// Thread-local state for each synthetic delay point. This allows the same delay
-// to be applied to multiple threads simultaneously.
-struct ThreadState {
-  ThreadState();
-
-  base::TimeTicks start_time;
-  unsigned trigger_count;
-  int generation;
-};
-
-ThreadState::ThreadState() : trigger_count(0u), generation(0) {}
-
 class TraceEventSyntheticDelayRegistry : public TraceEventSyntheticDelayClock {
  public:
   static TraceEventSyntheticDelayRegistry* GetInstance();
 
   TraceEventSyntheticDelay* GetOrCreateDelay(const char* name);
-  ThreadState* GetThreadState(int index);
+  void ResetAllDelays();
 
   // TraceEventSyntheticDelayClock implementation.
   virtual base::TimeTicks Now() OVERRIDE;
@@ -49,13 +35,11 @@ class TraceEventSyntheticDelayRegistry : public TraceEventSyntheticDelayClock {
   TraceEventSyntheticDelay dummy_delay_;
   base::subtle::Atomic32 delay_count_;
 
-  ThreadLocalPointer<ThreadState> thread_states_;
-
   DISALLOW_COPY_AND_ASSIGN(TraceEventSyntheticDelayRegistry);
 };
 
 TraceEventSyntheticDelay::TraceEventSyntheticDelay()
-    : mode_(STATIC), generation_(0), thread_state_index_(0), clock_(NULL) {}
+    : mode_(STATIC), begin_count_(0), trigger_count_(0), clock_(NULL) {}
 
 TraceEventSyntheticDelay::~TraceEventSyntheticDelay() {}
 
@@ -67,33 +51,30 @@ TraceEventSyntheticDelay* TraceEventSyntheticDelay::Lookup(
 
 void TraceEventSyntheticDelay::Initialize(
     const std::string& name,
-    TraceEventSyntheticDelayClock* clock,
-    int thread_state_index) {
+    TraceEventSyntheticDelayClock* clock) {
   name_ = name;
   clock_ = clock;
-  thread_state_index_ = thread_state_index;
 }
 
 void TraceEventSyntheticDelay::SetTargetDuration(
     base::TimeDelta target_duration) {
   AutoLock lock(lock_);
   target_duration_ = target_duration;
-  generation_++;
+  trigger_count_ = 0;
+  begin_count_ = 0;
 }
 
 void TraceEventSyntheticDelay::SetMode(Mode mode) {
   AutoLock lock(lock_);
   mode_ = mode;
-  generation_++;
 }
 
 void TraceEventSyntheticDelay::SetClock(TraceEventSyntheticDelayClock* clock) {
   AutoLock lock(lock_);
   clock_ = clock;
-  generation_++;
 }
 
-void TraceEventSyntheticDelay::Activate() {
+void TraceEventSyntheticDelay::Begin() {
   // Note that we check for a non-zero target duration without locking to keep
   // things quick for the common case when delays are disabled. Since the delay
   // calculation is done with a lock held, it will always be correct. The only
@@ -103,45 +84,59 @@ void TraceEventSyntheticDelay::Activate() {
   if (!target_duration_.ToInternalValue())
     return;
 
-  ThreadState* thread_state =
-      TraceEventSyntheticDelayRegistry::GetInstance()->
-          GetThreadState(thread_state_index_);
-  if (!thread_state->start_time.ToInternalValue())
-    thread_state->start_time = clock_->Now();
+  base::TimeTicks start_time = clock_->Now();
+  {
+    AutoLock lock(lock_);
+    if (++begin_count_ != 1)
+      return;
+    end_time_ = CalculateEndTimeLocked(start_time);
+  }
 }
 
-void TraceEventSyntheticDelay::Apply() {
+void TraceEventSyntheticDelay::BeginParallel(base::TimeTicks* out_end_time) {
+  // See note in Begin().
   ANNOTATE_BENIGN_RACE(&target_duration_, "Synthetic delay duration");
-  if (!target_duration_.ToInternalValue())
-    return;
-
-  ThreadState* thread_state =
-      TraceEventSyntheticDelayRegistry::GetInstance()->
-          GetThreadState(thread_state_index_);
-  if (!thread_state->start_time.ToInternalValue())
+  if (!target_duration_.ToInternalValue()) {
+    *out_end_time = base::TimeTicks();
     return;
-  base::TimeTicks now = clock_->Now();
-  base::TimeTicks start_time = thread_state->start_time;
-  base::TimeTicks end_time;
-  thread_state->start_time = base::TimeTicks();
+  }
 
+  base::TimeTicks start_time = clock_->Now();
   {
     AutoLock lock(lock_);
-    if (thread_state->generation != generation_) {
-      thread_state->trigger_count = 0;
-      thread_state->generation = generation_;
-    }
+    *out_end_time = CalculateEndTimeLocked(start_time);
+  }
+}
 
-    if (mode_ == ONE_SHOT && thread_state->trigger_count++)
-      return;
-    else if (mode_ == ALTERNATING && thread_state->trigger_count++ % 2)
-      return;
+void TraceEventSyntheticDelay::End() {
+  // See note in Begin().
+  ANNOTATE_BENIGN_RACE(&target_duration_, "Synthetic delay duration");
+  if (!target_duration_.ToInternalValue())
+    return;
 
-    end_time = start_time + target_duration_;
-    if (now >= end_time)
+  base::TimeTicks end_time;
+  {
+    AutoLock lock(lock_);
+    if (!begin_count_ || --begin_count_ != 0)
       return;
+    end_time = end_time_;
   }
-  ApplyDelay(end_time);
+  if (!end_time.is_null())
+    ApplyDelay(end_time);
+}
+
+void TraceEventSyntheticDelay::EndParallel(base::TimeTicks end_time) {
+  if (!end_time.is_null())
+    ApplyDelay(end_time);
+}
+
+base::TimeTicks TraceEventSyntheticDelay::CalculateEndTimeLocked(
+    base::TimeTicks start_time) {
+  if (mode_ == ONE_SHOT && trigger_count_++)
+    return base::TimeTicks();
+  else if (mode_ == ALTERNATING && trigger_count_++ % 2)
+    return base::TimeTicks();
+  return start_time + target_duration_;
 }
 
 void TraceEventSyntheticDelay::ApplyDelay(base::TimeTicks end_time) {
@@ -183,26 +178,24 @@ TraceEventSyntheticDelay* TraceEventSyntheticDelayRegistry::GetOrCreateDelay(
   if (delay_count >= kMaxSyntheticDelays)
     return &dummy_delay_;
 
-  delays_[delay_count].Initialize(std::string(name), this, delay_count);
+  delays_[delay_count].Initialize(std::string(name), this);
   base::subtle::Release_Store(&delay_count_, delay_count + 1);
   return &delays_[delay_count];
 }
 
-ThreadState* TraceEventSyntheticDelayRegistry::GetThreadState(int index) {
-  DCHECK(index >= 0 && index < kMaxSyntheticDelays);
-  if (index < 0 || index >= kMaxSyntheticDelays)
-    return NULL;
+base::TimeTicks TraceEventSyntheticDelayRegistry::Now() {
+  return base::TimeTicks::HighResNow();
+}
 
-  // Note that these thread states are leaked at program exit. They will only
-  // get allocated if synthetic delays are actually used.
-  ThreadState* thread_states = thread_states_.Get();
-  if (!thread_states)
-    thread_states_.Set((thread_states = new ThreadState[kMaxSyntheticDelays]));
-  return &thread_states[index];
+void TraceEventSyntheticDelayRegistry::ResetAllDelays() {
+  AutoLock lock(lock_);
+  int delay_count = base::subtle::Acquire_Load(&delay_count_);
+  for (int i = 0; i < delay_count; ++i)
+    delays_[i].SetTargetDuration(base::TimeDelta());
 }
 
-base::TimeTicks TraceEventSyntheticDelayRegistry::Now() {
-  return base::TimeTicks::HighResNow();
+void ResetTraceEventSyntheticDelays() {
+  TraceEventSyntheticDelayRegistry::GetInstance()->ResetAllDelays();
 }
 
 }  // namespace debug
@@ -213,10 +206,12 @@ namespace trace_event_internal {
 ScopedSyntheticDelay::ScopedSyntheticDelay(const char* name,
                                            base::subtle::AtomicWord* impl_ptr)
     : delay_impl_(GetOrCreateDelay(name, impl_ptr)) {
-  delay_impl_->Activate();
+  delay_impl_->BeginParallel(&end_time_);
 }
 
-ScopedSyntheticDelay::~ScopedSyntheticDelay() { delay_impl_->Apply(); }
+ScopedSyntheticDelay::~ScopedSyntheticDelay() {
+  delay_impl_->EndParallel(end_time_);
+}
 
 base::debug::TraceEventSyntheticDelay* GetOrCreateDelay(
     const char* name,
diff --git a/base/debug/trace_event_synthetic_delay.h b/base/debug/trace_event_synthetic_delay.h
index 8e0dfb1..06d6cde 100644
--- a/base/debug/trace_event_synthetic_delay.h
+++ b/base/debug/trace_event_synthetic_delay.h
@@ -17,18 +17,17 @@
 //
 // For delaying operations that span multiple scopes, use:
 //
-//   TRACE_EVENT_SYNTHETIC_DELAY_ACTIVATE("cc.Scheduler.BeginMainFrame");
+//   TRACE_EVENT_SYNTHETIC_DELAY_BEGIN("cc.Scheduler.BeginMainFrame");
 //   ...
-//   TRACE_EVENT_SYNTHETIC_DELAY_APPLY("cc.Scheduler.BeginMainFrame");
+//   TRACE_EVENT_SYNTHETIC_DELAY_END("cc.Scheduler.BeginMainFrame");
 //
-// Here ACTIVATE establishes the start time for the delay and APPLY executes the
-// delay based on the remaining time. ACTIVATE may be called one or multiple
-// times before APPLY. Only the first call will have an effect. If ACTIVATE
-// hasn't been called since the last call to APPLY, APPLY will be a no-op.
+// Here BEGIN establishes the start time for the delay and END executes the
+// delay based on the remaining time. If BEGIN is called multiple times in a
+// row, END should be called a corresponding number of times. Only the last
+// call to END will have an effect.
 //
-// Note that while the same delay can be applied in several threads
-// simultaneously, a single delay operation cannot begin on one thread and end
-// on another.
+// Note that a single delay may begin on one thread and end on another. This
+// implies that a single delay cannot not be applied in several threads at once.
 
 #ifndef BASE_DEBUG_TRACE_EVENT_SYNTHETIC_DELAY_H_
 #define BASE_DEBUG_TRACE_EVENT_SYNTHETIC_DELAY_H_
@@ -44,21 +43,22 @@
   trace_event_internal::ScopedSyntheticDelay INTERNAL_TRACE_EVENT_UID(delay)( \
       name, &INTERNAL_TRACE_EVENT_UID(impl_ptr));
 
-// Activate a named delay, establishing its timing start point. May be called
-// multiple times, but only the first call will have an effect.
-#define TRACE_EVENT_SYNTHETIC_DELAY_ACTIVATE(name)                       \
+// Begin a named delay, establishing its timing start point. May be called
+// multiple times as long as the calls to TRACE_EVENT_SYNTHETIC_DELAY_END are
+// balanced. Only the first call records the timing start point.
+#define TRACE_EVENT_SYNTHETIC_DELAY_BEGIN(name)                          \
   do {                                                                   \
     static base::subtle::AtomicWord impl_ptr = 0;                        \
-    trace_event_internal::GetOrCreateDelay(name, &impl_ptr)->Activate(); \
+    trace_event_internal::GetOrCreateDelay(name, &impl_ptr)->Begin();    \
   } while (false)
 
-// Apply a named delay. If TRACE_EVENT_SYNTHETIC_DELAY_ACTIVATE was called for
-// the same delay, that point in time is used as the delay start point. If not,
-// this call will be a no-op.
-#define TRACE_EVENT_SYNTHETIC_DELAY_APPLY(name)                       \
+// End a named delay. The delay is applied only if this call matches the
+// first corresponding call to TRACE_EVENT_SYNTHETIC_DELAY_BEGIN with the
+// same delay.
+#define TRACE_EVENT_SYNTHETIC_DELAY_END(name)                         \
   do {                                                                \
     static base::subtle::AtomicWord impl_ptr = 0;                     \
-    trace_event_internal::GetOrCreateDelay(name, &impl_ptr)->Apply(); \
+    trace_event_internal::GetOrCreateDelay(name, &impl_ptr)->End();   \
   } while (false)
 
 template <typename Type>
@@ -94,14 +94,24 @@ class TRACE_EVENT_API_CLASS_EXPORT TraceEventSyntheticDelay {
   void SetMode(Mode mode);
   void SetClock(TraceEventSyntheticDelayClock* clock);
 
-  // Establish the timing start point for the delay. No-op if the start point
-  // was already set.
-  void Activate();
+  // Begin the delay, establishing its timing start point. May be called
+  // multiple times as long as the calls to End() are balanced. Only the first
+  // call records the timing start point.
+  void Begin();
 
-  // Execute the delay based on the current time and how long ago the start
-  // point was established. If Activate wasn't called, this call will be a
-  // no-op.
-  void Apply();
+  // End the delay. The delay is applied only if this call matches the first
+  // corresponding call to Begin() with the same delay.
+  void End();
+
+  // Begin a parallel instance of the delay. Several parallel instances may be
+  // active simultaneously and will complete independently. The computed end
+  // time for the delay is stored in |out_end_time|, which should later be
+  // passed to EndParallel().
+  void BeginParallel(base::TimeTicks* out_end_time);
+
+  // End a previously started parallel delay. |end_time| is the delay end point
+  // computed by BeginParallel().
+  void EndParallel(base::TimeTicks end_time);
 
  private:
   TraceEventSyntheticDelay();
@@ -109,21 +119,25 @@ class TRACE_EVENT_API_CLASS_EXPORT TraceEventSyntheticDelay {
   friend class TraceEventSyntheticDelayRegistry;
 
   void Initialize(const std::string& name,
-                  TraceEventSyntheticDelayClock* clock,
-                  int thread_state_index);
+                  TraceEventSyntheticDelayClock* clock);
+  base::TimeTicks CalculateEndTimeLocked(base::TimeTicks start_time);
   void ApplyDelay(base::TimeTicks end_time);
 
   Lock lock_;
   Mode mode_;
   std::string name_;
-  int generation_;
+  int begin_count_;
+  int trigger_count_;
+  base::TimeTicks end_time_;
   base::TimeDelta target_duration_;
-  int thread_state_index_;
   TraceEventSyntheticDelayClock* clock_;
 
   DISALLOW_COPY_AND_ASSIGN(TraceEventSyntheticDelay);
 };
 
+// Set the target durations of all registered synthetic delay points to zero.
+TRACE_EVENT_API_CLASS_EXPORT void ResetTraceEventSyntheticDelays();
+
 }  // namespace debug
 }  // namespace base
 
@@ -138,6 +152,7 @@ class TRACE_EVENT_API_CLASS_EXPORT ScopedSyntheticDelay {
 
  private:
   base::debug::TraceEventSyntheticDelay* delay_impl_;
+  base::TimeTicks end_time_;
 
   DISALLOW_COPY_AND_ASSIGN(ScopedSyntheticDelay);
 };
diff --git a/base/debug/trace_event_synthetic_delay_unittest.cc b/base/debug/trace_event_synthetic_delay_unittest.cc
index a5daded..2642b16 100644
--- a/base/debug/trace_event_synthetic_delay_unittest.cc
+++ b/base/debug/trace_event_synthetic_delay_unittest.cc
@@ -44,15 +44,15 @@ class TraceEventSyntheticDelayTest : public testing::Test,
     return (Now() - start).InMilliseconds();
   }
 
-  int AsyncTestFunctionActivate() {
+  int AsyncTestFunctionBegin() {
     base::TimeTicks start = Now();
-    { TRACE_EVENT_SYNTHETIC_DELAY_ACTIVATE("test.AsyncDelay"); }
+    { TRACE_EVENT_SYNTHETIC_DELAY_BEGIN("test.AsyncDelay"); }
     return (Now() - start).InMilliseconds();
   }
 
-  int AsyncTestFunctionApply() {
+  int AsyncTestFunctionEnd() {
     base::TimeTicks start = Now();
-    { TRACE_EVENT_SYNTHETIC_DELAY_APPLY("test.AsyncDelay"); }
+    { TRACE_EVENT_SYNTHETIC_DELAY_END("test.AsyncDelay"); }
     return (Now() - start).InMilliseconds();
   }
 
@@ -90,28 +90,63 @@ TEST_F(TraceEventSyntheticDelayTest, AlternatingDelay) {
 
 TEST_F(TraceEventSyntheticDelayTest, AsyncDelay) {
   ConfigureDelay("test.AsyncDelay");
-  EXPECT_LT(AsyncTestFunctionActivate(), kShortDurationMs);
-  EXPECT_GE(AsyncTestFunctionApply(), kTargetDurationMs / 2);
+  EXPECT_LT(AsyncTestFunctionBegin(), kShortDurationMs);
+  EXPECT_GE(AsyncTestFunctionEnd(), kTargetDurationMs / 2);
 }
 
 TEST_F(TraceEventSyntheticDelayTest, AsyncDelayExceeded) {
   ConfigureDelay("test.AsyncDelay");
-  EXPECT_LT(AsyncTestFunctionActivate(), kShortDurationMs);
+  EXPECT_LT(AsyncTestFunctionBegin(), kShortDurationMs);
   AdvanceTime(base::TimeDelta::FromMilliseconds(kTargetDurationMs));
-  EXPECT_LT(AsyncTestFunctionApply(), kShortDurationMs);
+  EXPECT_LT(AsyncTestFunctionEnd(), kShortDurationMs);
 }
 
 TEST_F(TraceEventSyntheticDelayTest, AsyncDelayNoActivation) {
   ConfigureDelay("test.AsyncDelay");
-  EXPECT_LT(AsyncTestFunctionApply(), kShortDurationMs);
+  EXPECT_LT(AsyncTestFunctionEnd(), kShortDurationMs);
 }
 
-TEST_F(TraceEventSyntheticDelayTest, AsyncDelayMultipleActivations) {
+TEST_F(TraceEventSyntheticDelayTest, AsyncDelayNested) {
   ConfigureDelay("test.AsyncDelay");
-  EXPECT_LT(AsyncTestFunctionActivate(), kShortDurationMs);
-  AdvanceTime(base::TimeDelta::FromMilliseconds(kTargetDurationMs));
-  EXPECT_LT(AsyncTestFunctionActivate(), kShortDurationMs);
-  EXPECT_LT(AsyncTestFunctionApply(), kShortDurationMs);
+  EXPECT_LT(AsyncTestFunctionBegin(), kShortDurationMs);
+  EXPECT_LT(AsyncTestFunctionBegin(), kShortDurationMs);
+  EXPECT_LT(AsyncTestFunctionEnd(), kShortDurationMs);
+  EXPECT_GE(AsyncTestFunctionEnd(), kTargetDurationMs / 2);
+}
+
+TEST_F(TraceEventSyntheticDelayTest, AsyncDelayUnbalanced) {
+  ConfigureDelay("test.AsyncDelay");
+  EXPECT_LT(AsyncTestFunctionBegin(), kShortDurationMs);
+  EXPECT_GE(AsyncTestFunctionEnd(), kTargetDurationMs / 2);
+  EXPECT_LT(AsyncTestFunctionEnd(), kShortDurationMs);
+
+  EXPECT_LT(AsyncTestFunctionBegin(), kShortDurationMs);
+  EXPECT_GE(AsyncTestFunctionEnd(), kTargetDurationMs / 2);
+}
+
+TEST_F(TraceEventSyntheticDelayTest, ResetDelays) {
+  ConfigureDelay("test.Delay");
+  ResetTraceEventSyntheticDelays();
+  EXPECT_LT(TestFunction(), kShortDurationMs);
+}
+
+TEST_F(TraceEventSyntheticDelayTest, BeginParallel) {
+  TraceEventSyntheticDelay* delay = ConfigureDelay("test.AsyncDelay");
+  base::TimeTicks end_times[2];
+  base::TimeTicks start_time = Now();
+
+  delay->BeginParallel(&end_times[0]);
+  EXPECT_FALSE(end_times[0].is_null());
+
+  delay->BeginParallel(&end_times[1]);
+  EXPECT_FALSE(end_times[1].is_null());
+
+  delay->EndParallel(end_times[0]);
+  EXPECT_GE((Now() - start_time).InMilliseconds(), kTargetDurationMs);
+
+  start_time = Now();
+  delay->EndParallel(end_times[1]);
+  EXPECT_LT((Now() - start_time).InMilliseconds(), kShortDurationMs);
 }
 
 }  // namespace debug