Revert of [counters] RuntimeStats: fix wrong bookkeeping when dynamically...

Revert of [counters] RuntimeStats: fix wrong bookkeeping when dynamically changing counters. (patchset #10 id:180001 of https://codereview.chromium.org/2511093002/ )

Reason for revert:
Wronged it even more.

Original issue's description:
> [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=
>
> Committed: https://crrev.com/f6c74d964d9387df4bed3d8c1ded51eb9e8aa6e8
> Cr-Commit-Position: refs/heads/master@{#41142}

TBR=ishell@chromium.org
# Skipping CQ checks because original CL landed less than 1 days ago.
NOPRESUBMIT=true
NOTREECHECKS=true
NOTRY=true
BUG=

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

src/base/platform/elapsed-timer.h

@@ -52,13 +52,12 @@ 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() { return Restart(Now()); }
-
-  TimeDelta Restart(TimeTicks now) {
+  TimeDelta Restart() {
     DCHECK(IsStarted());
-    TimeDelta elapsed = now - start_ticks_;
+    TimeTicks ticks = Now();
+    TimeDelta elapsed = ticks - start_ticks_;
     DCHECK(elapsed.InMicroseconds() >= 0);
-    start_ticks_ = now;
+    start_ticks_ = ticks;
     DCHECK(IsStarted());
     return elapsed;
   }
@@ -72,14 +71,6 @@ 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.
@@ -88,13 +79,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,53 +10,6 @@
 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()->Snapshot();
+    current_timer_.Value()->Elapsed();
   }
   for (const RuntimeCallStats::CounterId counter_id :
        RuntimeCallStats::counters) {

src/counters.h

@@ -506,12 +506,37 @@ class RuntimeCallTimer {
  private:
   friend class RuntimeCallStats;
 
-  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);
+  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();
+  }
 
   const char* name() { return counter_->name; }
 
@@ -721,8 +746,6 @@ class RuntimeCallTimer {
   V(PrototypeObject_DeleteProperty)                 \
   V(RecompileConcurrent)                            \
   V(RecompileSynchronous)                           \
-  V(TestCounter1)                                   \
-  V(TestCounter2)                                   \
   /* Dummy counter for the unexpected stub miss. */ \
   V(UnexpectedStubMiss)
 
@@ -794,7 +817,7 @@ class RuntimeCallTimer {
   V(StoreIC_StoreTransitionDH)                   \
   V(StoreIC_StoreViaSetter)
 
-class V8_EXPORT_PRIVATE RuntimeCallStats : public ZoneObject {
+class RuntimeCallStats : public ZoneObject {
  public:
   typedef RuntimeCallCounter RuntimeCallStats::*CounterId;
 
@@ -869,36 +892,6 @@ class V8_EXPORT_PRIVATE 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)        \
@@ -1310,6 +1303,36 @@ 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,11 +4,9 @@
 
 #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 {
@@ -44,38 +42,6 @@ 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
 
 
@@ -229,209 +195,6 @@ 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