[counters] RuntimeStats: fix wrong bookkeeping when dynamically changing counters

RuntimeTimerScopes always subtract their own time from the parent timer's
counter to properly account for the own time. Once a scope is destructed it
adds it own timer to the current active counter. However, if the current
counter is changed with CorrectCurrentCounterId we will attribute all the
subtimers to the previous counter, and add the own time to the new counter.
This way it is possible to end up with negative times in certain counters but
the overall would still be correct.

BUG=

Review-Url: https://codereview.chromium.org/2511093002
Cr-Commit-Position: refs/heads/master@{#41142}

src/base/platform/elapsed-timer.h

@@ -52,12 +52,13 @@ class ElapsedTimer final {
   // and then starting the timer again, but does so in one single operation,
   // avoiding the need to obtain the clock value twice. It may only be called
   // on a previously started timer.
-  TimeDelta Restart() {
+  TimeDelta Restart() { return Restart(Now()); }
+
+  TimeDelta Restart(TimeTicks now) {
     DCHECK(IsStarted());
-    TimeTicks ticks = Now();
-    TimeDelta elapsed = ticks - start_ticks_;
+    TimeDelta elapsed = now - start_ticks_;
     DCHECK(elapsed.InMicroseconds() >= 0);
-    start_ticks_ = ticks;
+    start_ticks_ = now;
     DCHECK(IsStarted());
     return elapsed;
   }
@@ -71,6 +72,14 @@ class ElapsedTimer final {
     return elapsed;
   }
 
+  // Move the start_ticks_ to adjust the current timer.
+  void Subtract(TimeDelta delta) {
+    DCHECK(IsStarted());
+    // If the delta is negative we want to make the elapsed time smaller, hence
+    // we have to move the start_ticks_ in the opposite direction.
+    start_ticks_ += delta;
+  }
+
   // Returns |true| if the specified |time_delta| has elapsed since the
   // previous start, or |false| if not. This method may only be called on
   // a previously started timer.
@@ -79,13 +88,13 @@ class ElapsedTimer final {
     return Elapsed() >= time_delta;
   }
 
- private:
   static V8_INLINE TimeTicks Now() {
     TimeTicks now = TimeTicks::HighResolutionNow();
     DCHECK(!now.IsNull());
     return now;
   }
 
+ private:
   TimeTicks start_ticks_;
 #ifdef DEBUG
   bool started_;

src/counters-inl.h

@@ -10,6 +10,53 @@
 namespace v8 {
 namespace internal {
 
+void RuntimeCallTimer::Start(RuntimeCallCounter* counter,
+                             RuntimeCallTimer* parent) {
+  counter_ = counter;
+  parent_.SetValue(parent);
+  if (FLAG_runtime_stats !=
+      v8::tracing::TracingCategoryObserver::ENABLED_BY_SAMPLING) {
+    timer_.Start();
+  }
+}
+
+RuntimeCallTimer* RuntimeCallTimer::Stop() {
+  if (!timer_.IsStarted()) return parent();
+  base::TimeDelta delta = timer_.Elapsed();
+  timer_.Stop();
+  counter_->count++;
+  counter_->time += delta;
+  if (parent()) {
+    // Adjust parent timer so that it does not include sub timer's time.
+    parent()->Subtract(delta);
+  }
+  return parent();
+}
+
+void RuntimeCallTimer::Subtract(base::TimeDelta delta) {
+  // Adjust the current timer instead of directly subtracting the sub-timers
+  // from the current counter. This way we can easily change the counter of an
+  // active timer scope. Otherwise we would end up subtracting the time from the
+  // previous counter and add the own time to the newly changed counter.
+  timer_.Subtract(delta);
+}
+
+void RuntimeCallTimer::Snapshot() {
+  base::TimeTicks now = base::TimeTicks::HighResolutionNow();
+  RuntimeCallTimer* timer = this;
+  base::TimeDelta delta = base::TimeDelta::FromMicroseconds(0);
+  // Walk up the timer chain until the the timer doesn't have a parent.
+  while (timer != nullptr) {
+    // Iteration 1:   subtract 0 from the current timer (this).
+    // Iteration n+1: subtract subtimer's time (delta) from the the current
+    //                timer.
+    timer->Subtract(delta);
+    delta = timer->timer_.Restart(now);
+    timer->counter_->time += delta;
+    timer = timer->parent();
+  }
+}
+
 RuntimeCallTimerScope::RuntimeCallTimerScope(
     Isolate* isolate, RuntimeCallStats::CounterId counter_id) {
   if (V8_UNLIKELY(FLAG_runtime_stats)) {

src/counters.cc

@@ -354,7 +354,7 @@ void RuntimeCallStats::CorrectCurrentCounterId(RuntimeCallStats* stats,
 void RuntimeCallStats::Print(std::ostream& os) {
   RuntimeCallStatEntries entries;
   if (current_timer_.Value() != nullptr) {
-    current_timer_.Value()->Elapsed();
+    current_timer_.Value()->Snapshot();
   }
   for (const RuntimeCallStats::CounterId counter_id :
        RuntimeCallStats::counters) {

src/counters.h

@@ -506,37 +506,12 @@ class RuntimeCallTimer {
  private:
   friend class RuntimeCallStats;
 
-  inline void Start(RuntimeCallCounter* counter, RuntimeCallTimer* parent) {
-    counter_ = counter;
-    parent_.SetValue(parent);
-    if (FLAG_runtime_stats !=
-        v8::tracing::TracingCategoryObserver::ENABLED_BY_SAMPLING) {
-      timer_.Start();
-    }
-  }
-
-  inline RuntimeCallTimer* Stop() {
-    if (!timer_.IsStarted()) return parent();
-    base::TimeDelta delta = timer_.Elapsed();
-    timer_.Stop();
-    counter_->count++;
-    counter_->time += delta;
-    if (parent()) {
-      // Adjust parent timer so that it does not include sub timer's time.
-      parent()->counter_->time -= delta;
-    }
-    return parent();
-  }
-
-  inline void Elapsed() {
-    base::TimeDelta delta = timer_.Elapsed();
-    counter_->time += delta;
-    if (parent()) {
-      parent()->counter_->time -= delta;
-      parent()->Elapsed();
-    }
-    timer_.Restart();
-  }
+  inline void Start(RuntimeCallCounter* counter, RuntimeCallTimer* parent);
+  inline RuntimeCallTimer* Stop();
+  // Synchronize the currently active timer stack. Walk up the stack by stopping
+  // and restarting each timer.
+  inline void Snapshot();
+  inline void Subtract(base::TimeDelta delta);
 
   const char* name() { return counter_->name; }
 
@@ -746,6 +721,8 @@ class RuntimeCallTimer {
   V(PrototypeObject_DeleteProperty)                 \
   V(RecompileConcurrent)                            \
   V(RecompileSynchronous)                           \
+  V(TestCounter1)                                   \
+  V(TestCounter2)                                   \
   /* Dummy counter for the unexpected stub miss. */ \
   V(UnexpectedStubMiss)
 
@@ -817,7 +794,7 @@ class RuntimeCallTimer {
   V(StoreIC_StoreTransitionDH)                   \
   V(StoreIC_StoreViaSetter)
 
-class RuntimeCallStats : public ZoneObject {
+class V8_EXPORT_PRIVATE RuntimeCallStats : public ZoneObject {
  public:
   typedef RuntimeCallCounter RuntimeCallStats::*CounterId;
 
@@ -892,6 +869,36 @@ class RuntimeCallStats : public ZoneObject {
   CHANGE_CURRENT_RUNTIME_COUNTER(isolate->counters()->runtime_call_stats(), \
                                  Handler_##counter_name)
 
+// A RuntimeCallTimerScopes wraps around a RuntimeCallTimer to measure the
+// the time of C++ scope.
+class RuntimeCallTimerScope {
+ public:
+  inline RuntimeCallTimerScope(Isolate* isolate,
+                               RuntimeCallStats::CounterId counter_id);
+  // This constructor is here just to avoid calling GetIsolate() when the
+  // stats are disabled and the isolate is not directly available.
+  inline RuntimeCallTimerScope(HeapObject* heap_object,
+                               RuntimeCallStats::CounterId counter_id);
+  inline RuntimeCallTimerScope(RuntimeCallStats* stats,
+                               RuntimeCallStats::CounterId counter_id);
+
+  inline ~RuntimeCallTimerScope() {
+    if (V8_UNLIKELY(stats_ != nullptr)) {
+      RuntimeCallStats::Leave(stats_, &timer_);
+    }
+  }
+
+ private:
+  V8_INLINE void Initialize(RuntimeCallStats* stats,
+                            RuntimeCallStats::CounterId counter_id) {
+    stats_ = stats;
+    RuntimeCallStats::Enter(stats_, &timer_, counter_id);
+  }
+
+  RuntimeCallStats* stats_ = nullptr;
+  RuntimeCallTimer timer_;
+};
+
 #define HISTOGRAM_RANGE_LIST(HR)                                              \
   /* Generic range histograms */                                              \
   HR(detached_context_age_in_gc, V8.DetachedContextAgeInGC, 0, 20, 21)        \
@@ -1303,36 +1310,6 @@ class Counters {
   DISALLOW_IMPLICIT_CONSTRUCTORS(Counters);
 };
 
-// A RuntimeCallTimerScopes wraps around a RuntimeCallTimer to measure the
-// the time of C++ scope.
-class RuntimeCallTimerScope {
- public:
-  inline RuntimeCallTimerScope(Isolate* isolate,
-                               RuntimeCallStats::CounterId counter_id);
-  // This constructor is here just to avoid calling GetIsolate() when the
-  // stats are disabled and the isolate is not directly available.
-  inline RuntimeCallTimerScope(HeapObject* heap_object,
-                               RuntimeCallStats::CounterId counter_id);
-  inline RuntimeCallTimerScope(RuntimeCallStats* stats,
-                               RuntimeCallStats::CounterId counter_id);
-
-  inline ~RuntimeCallTimerScope() {
-    if (V8_UNLIKELY(stats_ != nullptr)) {
-      RuntimeCallStats::Leave(stats_, &timer_);
-    }
-  }
-
- private:
-  V8_INLINE void Initialize(RuntimeCallStats* stats,
-                            RuntimeCallStats::CounterId counter_id) {
-    stats_ = stats;
-    RuntimeCallStats::Enter(stats_, &timer_, counter_id);
-  }
-
-  RuntimeCallStats* stats_ = nullptr;
-  RuntimeCallTimer timer_;
-};
-
 }  // namespace internal
 }  // namespace v8
 

test/unittests/counters-unittest.cc

@@ -4,9 +4,11 @@
 
 #include <vector>
 
+#include "src/counters-inl.h"
 #include "src/counters.h"
 #include "src/handles-inl.h"
 #include "src/objects-inl.h"
+#include "src/tracing/tracing-category-observer.h"
 #include "testing/gtest/include/gtest/gtest.h"
 
 namespace v8 {
@@ -42,6 +44,38 @@ class AggregatedMemoryHistogramTest : public ::testing::Test {
   MockHistogram mock_;
 };
 
+class RuntimeCallStatsTest : public ::testing::Test {
+ public:
+  RuntimeCallStatsTest() {
+    FLAG_runtime_stats =
+        v8::tracing::TracingCategoryObserver::ENABLED_BY_NATIVE;
+  }
+  virtual ~RuntimeCallStatsTest() {}
+
+  RuntimeCallStats* stats() { return &stats_; }
+  RuntimeCallStats::CounterId counter_id() {
+    return &RuntimeCallStats::TestCounter1;
+  }
+  RuntimeCallStats::CounterId counter_id2() {
+    return &RuntimeCallStats::TestCounter2;
+  }
+  RuntimeCallCounter* counter() { return &(stats()->*counter_id()); }
+  RuntimeCallCounter* counter2() { return &(stats()->*counter_id2()); }
+  void Sleep(int32_t milliseconds) {
+    base::ElapsedTimer timer;
+    base::TimeDelta delta = base::TimeDelta::FromMilliseconds(milliseconds);
+    timer.Start();
+    while (!timer.HasExpired(delta)) {
+      base::OS::Sleep(base::TimeDelta::FromMicroseconds(0));
+    }
+  }
+
+  const uint32_t kEpsilonMs = 10;
+
+ private:
+  RuntimeCallStats stats_;
+};
+
 }  // namespace
 
 
@@ -195,6 +229,209 @@ TEST_F(AggregatedMemoryHistogramTest, ManySamples2) {
   }
 }
 
+#define EXPECT_IN_RANGE(start, value, end) \
+  EXPECT_LE(start, value);                 \
+  EXPECT_GE(end, value)
+
+TEST_F(RuntimeCallStatsTest, RuntimeCallTimer) {
+  RuntimeCallTimer timer;
+
+  RuntimeCallStats::Enter(stats(), &timer, counter_id());
+  EXPECT_EQ(counter(), timer.counter());
+  EXPECT_EQ(nullptr, timer.parent());
+  EXPECT_TRUE(timer.timer().IsStarted());
+  EXPECT_EQ(&timer, stats()->current_timer());
+
+  Sleep(100);
+
+  RuntimeCallStats::Leave(stats(), &timer);
+  EXPECT_FALSE(timer.timer().IsStarted());
+  EXPECT_EQ(1, counter()->count);
+  EXPECT_IN_RANGE(100, counter()->time.InMilliseconds(), 100 + kEpsilonMs);
+}
+
+TEST_F(RuntimeCallStatsTest, RuntimeCallTimerSubTimer) {
+  RuntimeCallTimer timer;
+  RuntimeCallTimer timer2;
+
+  RuntimeCallStats::Enter(stats(), &timer, counter_id());
+  EXPECT_TRUE(timer.timer().IsStarted());
+  EXPECT_FALSE(timer2.timer().IsStarted());
+  EXPECT_EQ(counter(), timer.counter());
+  EXPECT_EQ(nullptr, timer.parent());
+  EXPECT_EQ(&timer, stats()->current_timer());
+
+  Sleep(50);
+
+  RuntimeCallStats::Enter(stats(), &timer2, counter_id2());
+  EXPECT_TRUE(timer.timer().IsStarted());
+  EXPECT_TRUE(timer2.timer().IsStarted());
+  EXPECT_EQ(counter(), timer.counter());
+  EXPECT_EQ(counter2(), timer2.counter());
+  EXPECT_EQ(nullptr, timer.parent());
+  EXPECT_EQ(&timer, timer2.parent());
+  EXPECT_EQ(&timer2, stats()->current_timer());
+
+  Sleep(100);
+  RuntimeCallStats::Leave(stats(), &timer2);
+
+  // The subtimer subtracts its time from the parent timer.
+  EXPECT_TRUE(timer.timer().IsStarted());
+  EXPECT_FALSE(timer2.timer().IsStarted());
+  EXPECT_EQ(0, counter()->count);
+  EXPECT_EQ(1, counter2()->count);
+  EXPECT_EQ(0, counter()->time.InMilliseconds());
+  EXPECT_IN_RANGE(100, counter2()->time.InMilliseconds(), 100 + kEpsilonMs);
+  EXPECT_EQ(&timer, stats()->current_timer());
+
+  Sleep(100);
+
+  RuntimeCallStats::Leave(stats(), &timer);
+  EXPECT_FALSE(timer.timer().IsStarted());
+  EXPECT_EQ(1, counter()->count);
+  EXPECT_EQ(1, counter2()->count);
+  EXPECT_IN_RANGE(150, counter()->time.InMilliseconds(), 150 + kEpsilonMs);
+  EXPECT_IN_RANGE(100, counter2()->time.InMilliseconds(), 100 + kEpsilonMs);
+  EXPECT_EQ(nullptr, stats()->current_timer());
+}
+
+TEST_F(RuntimeCallStatsTest, RuntimeCallTimerRecursive) {
+  RuntimeCallTimer timer;
+  RuntimeCallTimer timer2;
+
+  RuntimeCallStats::Enter(stats(), &timer, counter_id());
+  EXPECT_EQ(counter(), timer.counter());
+  EXPECT_EQ(nullptr, timer.parent());
+  EXPECT_TRUE(timer.timer().IsStarted());
+  EXPECT_EQ(&timer, stats()->current_timer());
+
+  RuntimeCallStats::Enter(stats(), &timer2, counter_id());
+  EXPECT_EQ(counter(), timer2.counter());
+  EXPECT_EQ(&timer, timer2.parent());
+  EXPECT_TRUE(timer2.timer().IsStarted());
+  EXPECT_EQ(&timer2, stats()->current_timer());
+
+  Sleep(50);
+
+  RuntimeCallStats::Leave(stats(), &timer2);
+  EXPECT_FALSE(timer2.timer().IsStarted());
+  EXPECT_TRUE(timer.timer().IsStarted());
+  EXPECT_EQ(1, counter()->count);
+  EXPECT_IN_RANGE(50, counter()->time.InMilliseconds(), 50 + kEpsilonMs);
+
+  Sleep(100);
+
+  RuntimeCallStats::Leave(stats(), &timer);
+  EXPECT_FALSE(timer.timer().IsStarted());
+  EXPECT_EQ(2, counter()->count);
+  EXPECT_IN_RANGE(150, counter()->time.InMilliseconds(), 150 + 2 * kEpsilonMs);
+}
+
+TEST_F(RuntimeCallStatsTest, RuntimeCallTimerScope) {
+  {
+    RuntimeCallTimerScope scope(stats(), counter_id());
+    Sleep(50);
+  }
+  Sleep(100);
+  EXPECT_EQ(1, counter()->count);
+  EXPECT_IN_RANGE(50, counter()->time.InMilliseconds(), 50 + kEpsilonMs);
+  {
+    RuntimeCallTimerScope scope(stats(), counter_id());
+    Sleep(50);
+  }
+  EXPECT_EQ(2, counter()->count);
+  EXPECT_IN_RANGE(100, counter()->time.InMilliseconds(), 100 + 2 * kEpsilonMs);
+}
+
+TEST_F(RuntimeCallStatsTest, RuntimeCallTimerScopeRecursive) {
+  {
+    RuntimeCallTimerScope scope(stats(), counter_id());
+    Sleep(50);
+    EXPECT_EQ(0, counter()->count);
+    EXPECT_EQ(0, counter()->time.InMilliseconds());
+    {
+      RuntimeCallTimerScope scope(stats(), counter_id());
+      Sleep(50);
+    }
+    EXPECT_EQ(1, counter()->count);
+    EXPECT_IN_RANGE(50, counter()->time.InMilliseconds(), 50 + kEpsilonMs);
+  }
+  EXPECT_EQ(2, counter()->count);
+  EXPECT_IN_RANGE(100, counter()->time.InMilliseconds(), 100 + 2 * kEpsilonMs);
+}
+
+TEST_F(RuntimeCallStatsTest, RenameTimer) {
+  {
+    RuntimeCallTimerScope scope(stats(), counter_id());
+    Sleep(50);
+    EXPECT_EQ(0, counter()->count);
+    EXPECT_EQ(0, counter2()->count);
+    EXPECT_EQ(0, counter()->time.InMilliseconds());
+    EXPECT_EQ(0, counter2()->time.InMilliseconds());
+    {
+      RuntimeCallTimerScope scope(stats(), counter_id());
+      Sleep(100);
+    }
+    CHANGE_CURRENT_RUNTIME_COUNTER(stats(), TestCounter2);
+    EXPECT_EQ(1, counter()->count);
+    EXPECT_EQ(0, counter2()->count);
+    EXPECT_IN_RANGE(100, counter()->time.InMilliseconds(), 100 + kEpsilonMs);
+    EXPECT_IN_RANGE(0, counter2()->time.InMilliseconds(), 0);
+  }
+  EXPECT_EQ(1, counter()->count);
+  EXPECT_EQ(1, counter2()->count);
+  EXPECT_IN_RANGE(100, counter()->time.InMilliseconds(), 100 + kEpsilonMs);
+  EXPECT_IN_RANGE(50, counter2()->time.InMilliseconds(), 50 + kEpsilonMs);
+}
+
+TEST_F(RuntimeCallStatsTest, PrintAndSnapshot) {
+  {
+    RuntimeCallTimerScope scope(stats(), counter_id());
+    Sleep(100);
+    EXPECT_EQ(0, counter()->count);
+    EXPECT_EQ(0, counter()->time.InMilliseconds());
+    {
+      RuntimeCallTimerScope scope(stats(), counter_id2());
+      EXPECT_EQ(0, counter2()->count);
+      EXPECT_EQ(0, counter2()->time.InMilliseconds());
+      Sleep(50);
+
+      // This calls Snapshot on the current active timer and sychronizes and
+      // commits the whole timer stack.
+      std::ostringstream out;
+      stats()->Print(out);
+      EXPECT_EQ(0, counter()->count);
+      EXPECT_EQ(0, counter2()->count);
+      EXPECT_IN_RANGE(100, counter()->time.InMilliseconds(), 100 + kEpsilonMs);
+      EXPECT_IN_RANGE(50, counter2()->time.InMilliseconds(), 50 + kEpsilonMs);
+      // Calling Print several times shouldn't have a (big) impact on the
+      // measured times.
+      stats()->Print(out);
+      EXPECT_EQ(0, counter()->count);
+      EXPECT_EQ(0, counter2()->count);
+      EXPECT_IN_RANGE(100, counter()->time.InMilliseconds(), 100 + kEpsilonMs);
+      EXPECT_IN_RANGE(50, counter2()->time.InMilliseconds(), 50 + kEpsilonMs);
+
+      Sleep(50);
+      stats()->Print(out);
+      EXPECT_EQ(0, counter()->count);
+      EXPECT_EQ(0, counter2()->count);
+      EXPECT_IN_RANGE(100, counter()->time.InMilliseconds(), 100 + kEpsilonMs);
+      EXPECT_IN_RANGE(100, counter2()->time.InMilliseconds(), 100 + kEpsilonMs);
+      Sleep(50);
+    }
+    Sleep(50);
+    EXPECT_EQ(0, counter()->count);
+    EXPECT_EQ(1, counter2()->count);
+    EXPECT_IN_RANGE(100, counter()->time.InMilliseconds(), 100 + kEpsilonMs);
+    EXPECT_IN_RANGE(150, counter2()->time.InMilliseconds(), 150 + kEpsilonMs);
+    Sleep(50);
+  }
+  EXPECT_EQ(1, counter()->count);
+  EXPECT_EQ(1, counter2()->count);
+  EXPECT_IN_RANGE(200, counter()->time.InMilliseconds(), 200 + kEpsilonMs);
+  EXPECT_IN_RANGE(150, counter2()->time.InMilliseconds(), 150 + 2 * kEpsilonMs);
+}
 
 }  // namespace internal
 }  // namespace v8