[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=

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

src/counters-inl.h

@@ -10,6 +10,57 @@
 namespace v8 {
 namespace internal {
 
+void RuntimeCallTimer::Start(RuntimeCallCounter* counter,
+                             RuntimeCallTimer* parent) {
+  DCHECK(!IsStarted());
+  counter_ = counter;
+  parent_.SetValue(parent);
+  if (FLAG_runtime_stats ==
+      v8::tracing::TracingCategoryObserver::ENABLED_BY_SAMPLING) {
+    return;
+  }
+  base::TimeTicks now = Now();
+  if (parent) parent->Pause(now);
+  Resume(now);
+  DCHECK(IsStarted());
+}
+
+void RuntimeCallTimer::Pause(base::TimeTicks now) {
+  DCHECK(IsStarted());
+  elapsed_ += (now - start_ticks_);
+  start_ticks_ = base::TimeTicks();
+}
+
+void RuntimeCallTimer::Resume(base::TimeTicks now) {
+  DCHECK(!IsStarted());
+  start_ticks_ = now;
+}
+
+RuntimeCallTimer* RuntimeCallTimer::Stop() {
+  if (!IsStarted()) return parent();
+  base::TimeTicks now = Now();
+  Pause(now);
+  counter_->Increment();
+  CommitTimeToCounter();
+
+  RuntimeCallTimer* parent_timer = parent();
+  if (parent_timer) {
+    parent_timer->Resume(now);
+  }
+  return parent_timer;
+}
+
+void RuntimeCallTimer::CommitTimeToCounter() {
+  counter_->Add(elapsed_);
+  elapsed_ = base::TimeDelta();
+}
+
+bool RuntimeCallTimer::IsStarted() { return start_ticks_ != base::TimeTicks(); }
+
+base::TimeTicks RuntimeCallTimer::Now() {
+  return base::TimeTicks::HighResolutionNow();
+}
+
 RuntimeCallTimerScope::RuntimeCallTimerScope(
     Isolate* isolate, RuntimeCallStats::CounterId counter_id) {
   if (V8_UNLIKELY(FLAG_runtime_stats)) {

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,33 @@ 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 = Now();
+  // Pause only / topmost timer in the timer stack.
+  Pause(now);
+  // Commit all the timer's elapsed time to the counters.
+  RuntimeCallTimer* timer = this;
+  while (timer != nullptr) {
+    timer->CommitTimeToCounter();
+    timer = timer->parent();
+  }
+  Resume(now);
 }
 
 // static
@@ -313,7 +327,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);
 }
@@ -329,7 +343,7 @@ void RuntimeCallStats::Leave(RuntimeCallStats* stats, RuntimeCallTimer* timer) {
     RuntimeCallTimer* next = stats->current_timer_.Value();
     while (next && next->parent() != timer) next = next->parent();
     if (next == nullptr) return;
-    next->parent_.SetValue(timer->Stop());
+    next->set_parent(timer->Stop());
   }
 }
 
@@ -348,13 +362,13 @@ void RuntimeCallStats::CorrectCurrentCounterId(RuntimeCallStats* stats,
   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);
+  timer->set_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) {
@@ -388,7 +402,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;

src/counters.h

@@ -484,65 +484,51 @@ double AggregatedMemoryHistogram<Histogram>::Aggregate(double current_ms,
          value * ((current_ms - last_ms_) / interval_ms);
 }
 
-struct RuntimeCallCounter {
-  explicit RuntimeCallCounter(const char* name) : name(name) {}
+class RuntimeCallCounter final {
+ public:
+  explicit RuntimeCallCounter(const char* name) : name_(name) {}
   V8_NOINLINE void Reset();
   V8_NOINLINE void Dump(v8::tracing::TracedValue* value);
   void Add(RuntimeCallCounter* other);
 
-  const char* name;
-  int64_t count = 0;
-  base::TimeDelta time;
+  const char* name() const { return name_; }
+  int64_t count() const { return count_; }
+  base::TimeDelta time() const { return time_; }
+  void Increment() { count_++; }
+  void Add(base::TimeDelta delta) { time_ += delta; }
+
+ private:
+  const char* name_;
+  int64_t count_ = 0;
+  base::TimeDelta time_;
 };
 
 // RuntimeCallTimer is used to keep track of the stack of currently active
 // timers used for properly measuring the own time of a RuntimeCallCounter.
-class RuntimeCallTimer {
+class RuntimeCallTimer final {
  public:
   RuntimeCallCounter* counter() { return counter_; }
-  base::ElapsedTimer timer() { return timer_; }
+  void set_counter(RuntimeCallCounter* counter) { counter_ = counter; }
   RuntimeCallTimer* parent() const { return parent_.Value(); }
+  void set_parent(RuntimeCallTimer* timer) { parent_.SetValue(timer); }
+  const char* name() const { return counter_->name(); }
 
- private:
-  friend class RuntimeCallStats;
-
-  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 bool IsStarted();
 
-  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 Start(RuntimeCallCounter* counter, RuntimeCallTimer* parent);
+  void Snapshot();
+  inline RuntimeCallTimer* Stop();
 
-  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; }
+ private:
+  inline void Pause(base::TimeTicks now);
+  inline void Resume(base::TimeTicks now);
+  inline void CommitTimeToCounter();
+  inline base::TimeTicks Now();
 
   RuntimeCallCounter* counter_ = nullptr;
   base::AtomicValue<RuntimeCallTimer*> parent_;
-  base::ElapsedTimer timer_;
+  base::TimeTicks start_ticks_;
+  base::TimeDelta elapsed_;
 };
 
 #define FOR_EACH_API_COUNTER(V)                            \
@@ -749,6 +735,9 @@ class RuntimeCallTimer {
   V(PrototypeObject_DeleteProperty)                 \
   V(RecompileConcurrent)                            \
   V(RecompileSynchronous)                           \
+  V(TestCounter1)                                   \
+  V(TestCounter2)                                   \
+  V(TestCounter3)                                   \
   /* Dummy counter for the unexpected stub miss. */ \
   V(UnexpectedStubMiss)
 
@@ -820,7 +809,7 @@ class RuntimeCallTimer {
   V(StoreIC_StoreTransitionDH)                   \
   V(StoreIC_StoreViaSetter)
 
-class RuntimeCallStats : public ZoneObject {
+class V8_EXPORT_PRIVATE RuntimeCallStats final : public ZoneObject {
  public:
   typedef RuntimeCallCounter RuntimeCallStats::*CounterId;
 
@@ -895,6 +884,36 @@ class 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)        \
@@ -1306,36 +1325,6 @@ 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
 

src/log.cc

@@ -1279,7 +1279,7 @@ void Logger::RuntimeCallTimerEvent() {
   if (counter == nullptr) return;
   Log::MessageBuilder msg(log_);
   msg.Append("active-runtime-timer,");
-  msg.AppendDoubleQuotedString(counter->name);
+  msg.AppendDoubleQuotedString(counter->name());
   msg.WriteToLogFile();
 }
 

src/profiler/profile-generator.cc

@@ -750,8 +750,8 @@ CodeEntry* ProfileGenerator::FindEntry(void* address) {
     if (start <= address && address < end) {
       RuntimeCallCounter* counter =
           reinterpret_cast<RuntimeCallCounter*>(address);
-      CHECK(counter->name);
-      entry = new CodeEntry(CodeEventListener::FUNCTION_TAG, counter->name,
+      CHECK(counter->name());
+      entry = new CodeEntry(CodeEventListener::FUNCTION_TAG, counter->name(),
                             CodeEntry::kEmptyNamePrefix, "native V8Runtime");
       code_map_.AddCode(reinterpret_cast<Address>(address), entry, 1);
     }