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

test/unittests/counters-unittest.cc

 // Copyright 2014 the V8 project 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 <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 {
 namespace internal {
 
 namespace {
 
 class MockHistogram : public Histogram {
  public:
   void AddSample(int value) { samples_.push_back(value); }
@@ skipping 15 matching lines @@
     aggregated_.AddSample(current_ms, current_value);
   }
 
   std::vector<int>* samples() { return mock_.samples(); }
 
  private:
   AggregatedMemoryHistogram<MockHistogram> aggregated_;
   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;
+  }
+  RuntimeCallStats::CounterId counter_id3() {
+    return &RuntimeCallStats::TestCounter3;
+  }
+  RuntimeCallCounter* counter() { return &(stats()->*counter_id()); }
+  RuntimeCallCounter* counter2() { return &(stats()->*counter_id2()); }
+  RuntimeCallCounter* counter3() { return &(stats()->*counter_id3()); }
+  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 = 20;

[Michael Achenbach, 2016/11/24 09:48:46]

Hmm, is that rock solid?

+
+ private:
+  RuntimeCallStats stats_;
+};
+
 }  // namespace
 
 
 TEST_F(AggregatedMemoryHistogramTest, OneSample1) {
   FLAG_histogram_interval = 10;
   AddSample(10, 1000);
   AddSample(20, 1000);
   EXPECT_EQ(1U, samples()->size());
   EXPECT_EQ(1000, (*samples())[0]);
 }
@@ skipping 133 matching lines @@
   FLAG_histogram_interval = 10;
   const int kMaxSamples = 1000;
   AddSample(0, 0);
   AddSample(10 * (2 * kMaxSamples), 10 * (2 * kMaxSamples));
   EXPECT_EQ(static_cast<unsigned>(kMaxSamples), samples()->size());
   for (int i = 0; i < kMaxSamples; i++) {
     EXPECT_EQ(i * 10 + 5, (*samples())[i]);
   }
 }
 
+#define EXPECT_IN_RANGE(start, value, end) \
+  EXPECT_LE(start, value);                 \
+  EXPECT_GE(end, value)
+
+TEST_F(RuntimeCallStatsTest, RuntimeCallTimer) {
+  RuntimeCallTimer timer;
+
+  Sleep(50);
+  RuntimeCallStats::Enter(stats(), &timer, counter_id());
+  EXPECT_EQ(counter(), timer.counter());
+  EXPECT_EQ(nullptr, timer.parent());
+  EXPECT_TRUE(timer.IsStarted());
+  EXPECT_EQ(&timer, stats()->current_timer());
+
+  Sleep(100);
+
+  RuntimeCallStats::Leave(stats(), &timer);
+  Sleep(50);
+  EXPECT_FALSE(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.IsStarted());
+  EXPECT_FALSE(timer2.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());
+  // timer 1 is paused, while timer 2 is active.
+  EXPECT_TRUE(timer2.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.IsStarted());
+  EXPECT_FALSE(timer2.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.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.IsStarted());
+  EXPECT_EQ(&timer, stats()->current_timer());
+
+  RuntimeCallStats::Enter(stats(), &timer2, counter_id());
+  EXPECT_EQ(counter(), timer2.counter());
+  EXPECT_EQ(nullptr, timer.parent());
+  EXPECT_EQ(&timer, timer2.parent());
+  EXPECT_TRUE(timer2.IsStarted());
+  EXPECT_EQ(&timer2, stats()->current_timer());
+
+  Sleep(50);
+
+  RuntimeCallStats::Leave(stats(), &timer2);
+  EXPECT_EQ(nullptr, timer.parent());
+  EXPECT_FALSE(timer2.IsStarted());
+  EXPECT_TRUE(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.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, BasicPrintAndSnapshot) {
+  std::ostringstream out;
+  stats()->Print(out);
+  EXPECT_EQ(0, counter()->count());
+  EXPECT_EQ(0, counter2()->count());
+  EXPECT_EQ(0, counter3()->count());
+  EXPECT_EQ(0, counter()->time().InMilliseconds());
+  EXPECT_EQ(0, counter2()->time().InMilliseconds());
+  EXPECT_EQ(0, counter3()->time().InMilliseconds());
+
+  {
+    RuntimeCallTimerScope scope(stats(), counter_id());
+    Sleep(50);
+    stats()->Print(out);
+  }
+  stats()->Print(out);
+  EXPECT_EQ(1, counter()->count());
+  EXPECT_EQ(0, counter2()->count());
+  EXPECT_EQ(0, counter3()->count());
+  EXPECT_IN_RANGE(50, counter()->time().InMilliseconds(), 50 + kEpsilonMs);
+  EXPECT_EQ(0, counter2()->time().InMilliseconds());
+  EXPECT_EQ(0, counter3()->time().InMilliseconds());
+}
+
+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);
+}
+
+TEST_F(RuntimeCallStatsTest, NestedScopes) {
+  {
+    RuntimeCallTimerScope scope(stats(), counter_id());
+    Sleep(100);
+    {
+      RuntimeCallTimerScope scope(stats(), counter_id2());
+      Sleep(100);
+      {
+        RuntimeCallTimerScope scope(stats(), counter_id3());
+        Sleep(50);
+      }
+      Sleep(50);
+      {
+        RuntimeCallTimerScope scope(stats(), counter_id3());
+        Sleep(50);
+      }
+      Sleep(50);
+    }
+    Sleep(100);
+    {
+      RuntimeCallTimerScope scope(stats(), counter_id2());
+      Sleep(100);
+    }
+    Sleep(50);
+  }
+  EXPECT_EQ(1, counter()->count());
+  EXPECT_EQ(2, counter2()->count());
+  EXPECT_EQ(2, counter3()->count());
+  EXPECT_IN_RANGE(250, counter()->time().InMilliseconds(), 250 + kEpsilonMs);
+  EXPECT_IN_RANGE(300, counter2()->time().InMilliseconds(), 300 + kEpsilonMs);
+  EXPECT_IN_RANGE(100, counter3()->time().InMilliseconds(), 100 + kEpsilonMs);
+}
 
 }  // namespace internal
 }  // namespace v8