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

src/counters.cc

Index: src/counters.cc
diff --git a/src/counters.cc b/src/counters.cc
index 5089eb22e8ba397dc7108af37071dd2a74915cde..6c5e25ca9cfa8ff5e8a89b642cbd3a546c711faf 100644
--- a/src/counters.cc
+++ b/src/counters.cc
@@ -216,10 +216,11 @@ class RuntimeCallStatEntries {
   // binary size increase: std::vector::push_back expands to a large amount of
   // instructions, and this function is invoked repeatedly by macros.
   V8_NOINLINE void Add(RuntimeCallCounter* counter) {
-    if (counter->count == 0) return;
-    entries.push_back(Entry(counter->name, counter->time, counter->count));
-    total_time += counter->time;
-    total_call_count += counter->count;
+    if (counter->count() == 0) return;
+    entries.push_back(
+        Entry(counter->name(), counter->time(), counter->count()));
+    total_time += counter->time();
+    total_call_count += counter->count();
   }
 
  private:
@@ -273,20 +274,35 @@ class RuntimeCallStatEntries {
 };
 
 void RuntimeCallCounter::Reset() {
-  count = 0;
-  time = base::TimeDelta();
+  count_ = 0;
+  time_ = base::TimeDelta();
 }
 
 void RuntimeCallCounter::Dump(v8::tracing::TracedValue* value) {
-  value->BeginArray(name);
-  value->AppendLongInteger(count);
-  value->AppendLongInteger(time.InMicroseconds());
+  value->BeginArray(name_);
+  value->AppendLongInteger(count_);
+  value->AppendLongInteger(time_.InMicroseconds());
   value->EndArray();
 }
 
 void RuntimeCallCounter::Add(RuntimeCallCounter* other) {
-  count += other->count;
-  time += other->time;
+  count_ += other->count();
+  time_ += other->time();
+}
+
+void RuntimeCallTimer::Snapshot() {
+  base::TimeTicks now = base::TimeTicks::Now();
+  RuntimeCallTimer* timer = this;
+  base::TimeDelta delta = base::TimeDelta();

[Igor Sheludko, 2016/11/22 22:53:59]

Nit: you can drop = base::TimeDelta().

+  while (timer != nullptr) {
+    // Iteration 1:   delta = 0, AddSubtime will have no effect
+    // Iteration n+1: Subtract the subtimer's time from the current timer.
+    timer->SubtractSubtime(delta);
+    delta = timer->Restart(now);

[lpy, 2016/11/22 22:25:44]

I think there's a problem here. In order to maintain accurate time, I think we
should always restart timer in the order from parent to child, otherwise parent
may end up with negative time, because the timer of child restarts to count
before we restart the timer of parent.

WDYT?

[Igor Sheludko, 2016/11/22 22:53:59]

We request "now" value only once and then use it to restart timers. So the order
of Restart()s does not matter but it matters for proper subtracting time
measured by child from from time measured by parent timer.

+    // Add the timer's own time.
+    timer->AddAndSubmitResults(delta);
+    timer = timer->parent();
+  }
 }
 
 // static
@@ -313,7 +329,7 @@ const RuntimeCallStats::CounterId RuntimeCallStats::counters[] = {
 void RuntimeCallStats::Enter(RuntimeCallStats* stats, RuntimeCallTimer* timer,
                              CounterId counter_id) {
   RuntimeCallCounter* counter = &(stats->*counter_id);
-  DCHECK(counter->name != nullptr);
+  DCHECK(counter->name() != nullptr);
   timer->Start(counter, stats->current_timer_.Value());
   stats->current_timer_.SetValue(timer);
 }
@@ -354,7 +370,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) {
@@ -388,7 +404,7 @@ void RuntimeCallStats::Dump(v8::tracing::TracedValue* value) {
   for (const RuntimeCallStats::CounterId counter_id :
        RuntimeCallStats::counters) {
     RuntimeCallCounter* counter = &(this->*counter_id);
-    if (counter->count > 0) counter->Dump(value);
+    if (counter->count() > 0) counter->Dump(value);
   }
 
   in_use_ = false;