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

src/counters.cc

 // Copyright 2012 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 "src/counters.h"
 
 #include <iomanip>
 
 #include "src/base/platform/platform.h"
 #include "src/isolate.h"
@@ skipping 198 matching lines @@
       entry.Print(os);
     }
     os << std::string(88, '-') << std::endl;
     Entry("Total", total_time, total_call_count).Print(os);
   }
 
   // By default, the compiler will usually inline this, which results in a large
   // 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:
   class Entry {
    public:
     Entry(const char* name, base::TimeDelta time, uint64_t count)
         : name_(name),
           time_(time.InMicroseconds()),
           count_(count),
           time_percent_(100),
@@ skipping 33 matching lines @@
     double time_percent_;
     double count_percent_;
   };
 
   uint64_t total_call_count = 0;
   base::TimeDelta total_time;
   std::vector<Entry> entries;
 };
 
 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
 const RuntimeCallStats::CounterId RuntimeCallStats::counters[] = {
 #define CALL_RUNTIME_COUNTER(name) &RuntimeCallStats::name,
     FOR_EACH_MANUAL_COUNTER(CALL_RUNTIME_COUNTER)  //
 #undef CALL_RUNTIME_COUNTER
 #define CALL_RUNTIME_COUNTER(name, nargs, ressize) \
   &RuntimeCallStats::Runtime_##name,          //
     FOR_EACH_INTRINSIC(CALL_RUNTIME_COUNTER)  //
 #undef CALL_RUNTIME_COUNTER
 #define CALL_BUILTIN_COUNTER(name) &RuntimeCallStats::Builtin_##name,
     BUILTIN_LIST_C(CALL_BUILTIN_COUNTER)  //
 #undef CALL_BUILTIN_COUNTER
 #define CALL_BUILTIN_COUNTER(name) &RuntimeCallStats::API_##name,
     FOR_EACH_API_COUNTER(CALL_BUILTIN_COUNTER)  //
 #undef CALL_BUILTIN_COUNTER
 #define CALL_BUILTIN_COUNTER(name) &RuntimeCallStats::Handler_##name,
     FOR_EACH_HANDLER_COUNTER(CALL_BUILTIN_COUNTER)
 #undef CALL_BUILTIN_COUNTER
 };
 
 // static
 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);
 }
 
 // static
 void RuntimeCallStats::Leave(RuntimeCallStats* stats, RuntimeCallTimer* timer) {
   if (stats->current_timer_.Value() == timer) {
     stats->current_timer_.SetValue(timer->Stop());
   } else {
     // Must be a Threading cctest. Walk the chain of Timers to find the
@@ skipping 20 matching lines @@
                                                CounterId counter_id) {
   RuntimeCallTimer* timer = stats->current_timer_.Value();
   // When RCS are enabled dynamically there might be no current timer set up.
   if (timer == nullptr) return;
   timer->counter_ = &(stats->*counter_id);
 }
 
 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) {
     RuntimeCallCounter* counter = &(this->*counter_id);
     entries.Add(counter);
   }
   entries.Print(os);
 }
 
 void RuntimeCallStats::Reset() {
@@ skipping 13 matching lines @@
     counter->Reset();
   }
 
   in_use_ = true;
 }
 
 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;
 }
 
 }  // namespace internal
 }  // namespace v8