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

test/unittests/counters-unittest.cc

Index: test/unittests/counters-unittest.cc
diff --git a/test/unittests/counters-unittest.cc b/test/unittests/counters-unittest.cc
index 822a5c552ecb0b94addf11abb21878157693c85c..59329bac0f0ad6d2dd60934bd65f69403772ee63 100644
--- a/test/unittests/counters-unittest.cc
+++ b/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,33 @@ 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 microseconds) {

[Igor Sheludko, 2016/11/18 18:56:27]

Probably you don't need microseconds precision. WDYT:

void Sleep(int milliseconds) {
  ElapsedTimer timer;
  TimeDelta delta = TimeDelta::FromMilliseconds(milliseconds);
  timer.Start();
  while (!timer.HasExpired(delta)) {
    base::OS::Sleep(0);  // or 10?
  }
}

Inspired by TEST(TimeTicks, IsMonotonic).

+    base::OS::Sleep(base::TimeDelta::FromMicroseconds(microseconds));
+  }
+
+  const uint32_t kTimeMargin = 150;

[Igor Sheludko, 2016/11/18 18:56:28]

Maybe kEpsilonMs = 50;

+
+ private:
+  RuntimeCallStats stats_;
+};
+
 }  // namespace
 
 
@@ -195,6 +224,196 @@ 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(500);

[Igor Sheludko, 2016/11/18 18:56:27]

Probably 100-300 ms should be enough...

+
+  RuntimeCallStats::Leave(stats(), &timer);
+  EXPECT_FALSE(timer.timer().IsStarted());
+  EXPECT_EQ(1, counter()->count);
+  EXPECT_IN_RANGE(500, counter()->time.InMicroseconds(), 500 + kTimeMargin);

[Igor Sheludko, 2016/11/18 18:56:28]

... because what we are testing here and below is the RuntimeCallStats machinery
but not the underlying counter.

+}
+
+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());
+

[Igor Sheludko, 2016/11/18 18:56:28]

Maybe Sleep here as well.

+  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(500);
+  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(-counter()->time, counter()->time);

[Igor Sheludko, 2016/11/18 18:56:28]

We never subtract from time. This should start failing once you fix delta.

+  EXPECT_IN_RANGE(500, counter2()->time.InMicroseconds(), 500 + kTimeMargin);
+  EXPECT_EQ(&timer, stats()->current_timer());
+
+  Sleep(500);

[Igor Sheludko, 2016/11/18 18:56:28]

Maybe you can make the numbers different so that we can check that the time
interval went to the right counter.

+
+  RuntimeCallStats::Leave(stats(), &timer);
+  EXPECT_FALSE(timer.timer().IsStarted());
+  EXPECT_EQ(1, counter()->count);
+  EXPECT_EQ(1, counter2()->count);
+  EXPECT_IN_RANGE(500, counter()->time.InMicroseconds(), 500 + kTimeMargin);
+  EXPECT_IN_RANGE(500, counter2()->time.InMicroseconds(), 500 + kTimeMargin);
+  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(500);
+
+  RuntimeCallStats::Leave(stats(), &timer2);
+  EXPECT_FALSE(timer2.timer().IsStarted());
+  EXPECT_TRUE(timer.timer().IsStarted());
+  EXPECT_EQ(1, counter()->count);
+  EXPECT_IN_RANGE(500, counter()->time.InMicroseconds(), 500 + kTimeMargin);
+
+  Sleep(500);
+
+  RuntimeCallStats::Leave(stats(), &timer);
+  EXPECT_FALSE(timer.timer().IsStarted());
+  EXPECT_EQ(2, counter()->count);
+  EXPECT_IN_RANGE(1000, counter()->time.InMicroseconds(),
+                  1000 + 2 * kTimeMargin);
+}
+
+TEST_F(RuntimeCallStatsTest, RuntimeCallTimerScope) {
+  {
+    RuntimeCallTimerScope scope(stats(), counter_id());
+    Sleep(500);
+  }

[Igor Sheludko, 2016/11/18 18:56:27]

Maybe Sleep between scopes too to ensure that this time is not counted.

+  EXPECT_EQ(1, counter()->count);
+  EXPECT_IN_RANGE(500, counter()->time.InMicroseconds(), 500 + kTimeMargin);
+  {
+    RuntimeCallTimerScope scope(stats(), counter_id());
+    Sleep(500);
+  }
+  EXPECT_EQ(2, counter()->count);
+  EXPECT_IN_RANGE(1000, counter()->time.InMicroseconds(),
+                  1000 + 2 * kTimeMargin);
+}
+
+TEST_F(RuntimeCallStatsTest, RuntimeCallTimerScopeRecursive) {
+  {
+    RuntimeCallTimerScope scope(stats(), counter_id());
+    Sleep(500);
+    EXPECT_EQ(0, counter()->count);
+    EXPECT_EQ(0, counter()->time.InMicroseconds());
+    {
+      RuntimeCallTimerScope scope(stats(), counter_id());
+      Sleep(500);
+    }
+    EXPECT_EQ(1, counter()->count);
+    EXPECT_IN_RANGE(500, counter()->time.InMicroseconds(), 500 + kTimeMargin);
+  }
+  EXPECT_EQ(2, counter()->count);
+  EXPECT_IN_RANGE(1000, counter()->time.InMicroseconds(),
+                  1000 + 2 * kTimeMargin);
+}
+
+TEST_F(RuntimeCallStatsTest, RenameTimer) {
+  {
+    RuntimeCallTimerScope scope(stats(), counter_id());
+    Sleep(500);
+    EXPECT_EQ(0, counter()->count);
+    EXPECT_EQ(0, counter2()->count);
+    EXPECT_EQ(0, counter()->time.InMicroseconds());
+    EXPECT_EQ(0, counter2()->time.InMicroseconds());
+    {
+      RuntimeCallTimerScope scope(stats(), counter_id());
+      Sleep(500);
+    }
+    CHANGE_CURRENT_RUNTIME_COUNTER(stats(), TestCounter2);
+    EXPECT_EQ(1, counter()->count);
+    EXPECT_EQ(0, counter2()->count);
+    EXPECT_IN_RANGE(500, counter()->time.InMicroseconds(), 500 + kTimeMargin);
+    EXPECT_IN_RANGE(0, counter2()->time.InMicroseconds(), 0);
+  }
+  EXPECT_EQ(1, counter()->count);
+  EXPECT_EQ(1, counter2()->count);
+  EXPECT_IN_RANGE(500, counter()->time.InMicroseconds(), 500 + kTimeMargin);
+  EXPECT_IN_RANGE(500, counter2()->time.InMicroseconds(), 500 + kTimeMargin);
+}
+
+TEST_F(RuntimeCallStatsTest, PrintAndSnapshot) {
+  uint32_t offset = 200;
+  {
+    RuntimeCallTimerScope scope(stats(), counter_id());
+    Sleep(500);
+    EXPECT_EQ(0, counter()->count);
+    EXPECT_EQ(0, counter()->time.InMicroseconds());
+    {
+      RuntimeCallTimerScope scope(stats(), counter_id2());
+      EXPECT_EQ(0, counter2()->count);
+      EXPECT_EQ(0, counter2()->time.InMicroseconds());
+      Sleep(500);
+
+      // This calls Snapshot on the current active timer and sychronizes and
+      // commits the whole timer stack.
+      stats()->Print(std::cerr);

[Igor Sheludko, 2016/11/18 18:56:28]

Test driver does not like a lot of output. You may consider printing to
std::ostringstream.

You can also try to Sleep/Print several times. It should not affect the
resulting time.

+      EXPECT_EQ(0, counter()->count);
+      EXPECT_EQ(0, counter2()->count);
+      EXPECT_IN_RANGE(500, counter()->time.InMicroseconds(), 500 + kTimeMargin);
+      EXPECT_IN_RANGE(500, counter2()->time.InMicroseconds(),
+                      500 + kTimeMargin);
+      Sleep(500);
+    }
+    EXPECT_EQ(0, counter()->count);
+    EXPECT_EQ(1, counter2()->count);
+    EXPECT_IN_RANGE(500, counter()->time.InMicroseconds(), 500 + kTimeMargin);
+    EXPECT_IN_RANGE(1000 + offset, counter2()->time.InMicroseconds(),
+                    1000 + offset + 2 * kTimeMargin);
+  }
+  EXPECT_EQ(1, counter()->count);
+  EXPECT_EQ(1, counter2()->count);
+  EXPECT_IN_RANGE(500, counter()->time.InMicroseconds(), 500 + kTimeMargin);
+  EXPECT_IN_RANGE(1000, counter2()->time.InMicroseconds(),
+                  1000 + offset + 2 * kTimeMargin);
+}
 
 }  // namespace internal
 }  // namespace v8