Revert of [counters] RuntimeStats: fix wrong bookkeeping when dynamically...

Revert of [counters] RuntimeStats: fix wrong bookkeeping when dynamically changing counters. (patchset #15 id:320001 of https://codereview.chromium.org/2511093002/ )

Reason for revert:
The test is very flaky on the bots, e.g.:
https://build.chromium.org/p/client.v8/builders/V8%20Linux64%20ASAN/builds/17031
https://build.chromium.org/p/client.v8/builders/V8%20Linux%20-%20shared/builds/14776

Original issue's description:
> [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=
>
> Committed: https://crrev.com/f6c74d964d9387df4bed3d8c1ded51eb9e8aa6e8
> Committed: https://crrev.com/491651792d7818aed04eaeffb9890b5a309b543e
> Cr-Original-Commit-Position: refs/heads/master@{#41142}
> Cr-Commit-Position: refs/heads/master@{#41214}

TBR=ishell@chromium.org,fmeawad@chromium.org,lpy@chromium.org,cbruni@chromium.org
# Skipping CQ checks because original CL landed less than 1 days ago.
NOPRESUBMIT=true
NOTREECHECKS=true
NOTRY=true
BUG=

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

src/counters-inl.h

@@ -10,57 +10,6 @@
 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,11 +216,10 @@ 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:
@@ -274,33 +273,20 @@ 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();
-}
-
-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);
+  count += other->count;
+  time += other->time;
 }
 
 // static
@@ -327,7 +313,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);
 }
@@ -343,7 +329,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->set_parent(timer->Stop());
+    next->parent_.SetValue(timer->Stop());
   }
 }
 
@@ -362,13 +348,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->set_counter(&(stats->*counter_id));
+  timer->counter_ = &(stats->*counter_id);
 }
 
 void RuntimeCallStats::Print(std::ostream& os) {
   RuntimeCallStatEntries entries;
   if (current_timer_.Value() != nullptr) {
-    current_timer_.Value()->Snapshot();
+    current_timer_.Value()->Elapsed();
   }
   for (const RuntimeCallStats::CounterId counter_id :
        RuntimeCallStats::counters) {
@@ -402,7 +388,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,51 +484,65 @@ double AggregatedMemoryHistogram<Histogram>::Aggregate(double current_ms,
          value * ((current_ms - last_ms_) / interval_ms);
 }
 
-class RuntimeCallCounter final {
- public:
-  explicit RuntimeCallCounter(const char* name) : name_(name) {}
+struct RuntimeCallCounter {
+  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() 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_;
+  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 final {
+class RuntimeCallTimer {
  public:
   RuntimeCallCounter* counter() { return counter_; }
-  void set_counter(RuntimeCallCounter* counter) { counter_ = counter; }
+  base::ElapsedTimer timer() { return timer_; }
   RuntimeCallTimer* parent() const { return parent_.Value(); }
-  void set_parent(RuntimeCallTimer* timer) { parent_.SetValue(timer); }
-  const char* name() const { return counter_->name(); }
 
-  inline bool IsStarted();
+ 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 void Start(RuntimeCallCounter* counter, RuntimeCallTimer* parent);
-  void Snapshot();
-  inline RuntimeCallTimer* Stop();
+  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();
+  }
 
- private:
-  inline void Pause(base::TimeTicks now);
-  inline void Resume(base::TimeTicks now);
-  inline void CommitTimeToCounter();
-  inline base::TimeTicks Now();
+  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; }
 
   RuntimeCallCounter* counter_ = nullptr;
   base::AtomicValue<RuntimeCallTimer*> parent_;
-  base::TimeTicks start_ticks_;
-  base::TimeDelta elapsed_;
+  base::ElapsedTimer timer_;
 };
 
 #define FOR_EACH_API_COUNTER(V)                            \
@@ -732,9 +746,6 @@ class RuntimeCallTimer final {
   V(PrototypeObject_DeleteProperty)                 \
   V(RecompileConcurrent)                            \
   V(RecompileSynchronous)                           \
-  V(TestCounter1)                                   \
-  V(TestCounter2)                                   \
-  V(TestCounter3)                                   \
   /* Dummy counter for the unexpected stub miss. */ \
   V(UnexpectedStubMiss)
 
@@ -806,7 +817,7 @@ class RuntimeCallTimer final {
   V(StoreIC_StoreTransitionDH)                   \
   V(StoreIC_StoreViaSetter)
 
-class V8_EXPORT_PRIVATE RuntimeCallStats final : public ZoneObject {
+class RuntimeCallStats : public ZoneObject {
  public:
   typedef RuntimeCallCounter RuntimeCallStats::*CounterId;
 
@@ -881,36 +892,6 @@ class V8_EXPORT_PRIVATE RuntimeCallStats final : 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)        \
@@ -1322,6 +1303,36 @@ 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);
     }