[counters] Making runtime counters reentrant.

So far counters did not work when they were reentrant and thus would lead to
wrong bookkeeping of the counter stack. Using a separate stack-allocated linked
list to track the timer stack solves this issue. This is a temporary workaround
with the limitations of the counter system in mind. Eventually we will move to
the trace-based system for these kind of statistics.

BUG=v8:4770
LOG=n

Review URL: https://codereview.chromium.org/1695733002

Cr-Commit-Position: refs/heads/master@{#34208}

src/arguments.h

@@ -271,23 +271,16 @@ double ClobberDoubleRegisters(double x1, double x2, double x3, double x4);
 #define CLOBBER_DOUBLE_REGISTERS()
 #endif
 
-#define RUNTIME_FUNCTION_RETURNS_TYPE(Type, Name)                          \
-  static INLINE(Type __RT_impl_##Name(Arguments args, Isolate* isolate));  \
-  Type Name(int args_length, Object** args_object, Isolate* isolate) {     \
-    CLOBBER_DOUBLE_REGISTERS();                                            \
-    base::ElapsedTimer timer;                                              \
-    if (FLAG_runtime_call_stats) {                                         \
-      RuntimeCallStats* stats = isolate->counters()->runtime_call_stats(); \
-      stats->Enter(&stats->Name);                                          \
-      timer.Start();                                                       \
-    }                                                                      \
-    Arguments args(args_length, args_object);                              \
-    Type value = __RT_impl_##Name(args, isolate);                          \
-    if (FLAG_runtime_call_stats) {                                         \
-      isolate->counters()->runtime_call_stats()->Leave(timer.Elapsed());   \
-    }                                                                      \
-    return value;                                                          \
-  }                                                                        \
+#define RUNTIME_FUNCTION_RETURNS_TYPE(Type, Name)                         \
+  static INLINE(Type __RT_impl_##Name(Arguments args, Isolate* isolate)); \
+  Type Name(int args_length, Object** args_object, Isolate* isolate) {    \
+    CLOBBER_DOUBLE_REGISTERS();                                           \
+    RuntimeCallStats* stats = isolate->counters()->runtime_call_stats();  \
+    RuntimeCallTimerScope timer(isolate, &stats->Name);                   \
+    Arguments args(args_length, args_object);                             \
+    Type value = __RT_impl_##Name(args, isolate);                         \
+    return value;                                                         \
+  }                                                                       \
   static Type __RT_impl_##Name(Arguments args, Isolate* isolate)
 
 #define RUNTIME_FUNCTION(Name) RUNTIME_FUNCTION_RETURNS_TYPE(Object*, Name)

src/builtins.cc

@@ -143,17 +143,10 @@ BUILTIN_LIST_C(DEF_ARG_TYPE)
   MUST_USE_RESULT static Object* Builtin_##name(                               \
       int args_length, Object** args_object, Isolate* isolate) {               \
     isolate->counters()->runtime_calls()->Increment();                         \
-    base::ElapsedTimer timer;                                                  \
-    if (FLAG_runtime_call_stats) {                                             \
-      RuntimeCallStats* stats = isolate->counters()->runtime_call_stats();     \
-      stats->Enter(&stats->Builtin_##name);                                    \
-      timer.Start();                                                           \
-    }                                                                          \
+    RuntimeCallStats* stats = isolate->counters()->runtime_call_stats();       \
+    RuntimeCallTimerScope timer(isolate, &stats->Builtin_##name);              \
     name##ArgumentsType args(args_length, args_object);                        \
     Object* value = Builtin_Impl_##name(args, isolate);                        \
-    if (FLAG_runtime_call_stats) {                                             \
-      isolate->counters()->runtime_call_stats()->Leave(timer.Elapsed());       \
-    }                                                                          \
     return value;                                                              \
   }                                                                            \
                                                                                \

src/counters.cc

@@ -198,24 +198,24 @@ void Counters::ResetHistograms() {
 class RuntimeCallStatEntries {
  public:
   void Print(std::ostream& os) {
-    if (total_call_count > 0) {
-      std::sort(entries.rbegin(), entries.rend());
-      os << std::setw(50) << "Runtime Function/C++ Builtin" << std::setw(10)
-         << "Time" << std::setw(18) << "Count" << std::endl
-         << std::string(86, '=') << std::endl;
-      for (Entry& entry : entries) {
-        entry.SetTotal(total_time, total_call_count);
-        entry.Print(os);
-      }
-      os << std::string(86, '-') << std::endl;
-      Entry("Total", total_time, total_call_count).Print(os);
+    if (total_call_count == 0) return;
+    std::sort(entries.rbegin(), entries.rend());
+    os << std::setw(50) << "Runtime Function/C++ Builtin" << std::setw(10)
+       << "Time" << std::setw(18) << "Count" << std::endl
+       << std::string(86, '=') << std::endl;
+    for (Entry& entry : entries) {
+      entry.SetTotal(total_time, total_call_count);
+      entry.Print(os);
     }
+    os << std::string(86, '-') << std::endl;
+    Entry("Total", total_time, total_call_count).Print(os);
   }
 
-  void Add(const char* name, RuntimeCallCounter counter) {
-    entries.push_back(Entry(name, counter.time, counter.count));
-    total_time += counter.time;
-    total_call_count += counter.count;
+  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;
   }
 
  private:
@@ -246,7 +246,11 @@ class RuntimeCallStatEntries {
     }
 
     void SetTotal(base::TimeDelta total_time, uint64_t total_count) {
-      time_percent_ = 100.0 * time_ / total_time.InMilliseconds();
+      if (total_time.InMilliseconds() == 0) {
+        time_percent_ = 0;
+      } else {
+        time_percent_ = 100.0 * time_ / total_time.InMilliseconds();
+      }
       count_percent_ = 100.0 * count_ / total_count;
     }
 
@@ -269,35 +273,38 @@ void RuntimeCallCounter::Reset() {
 }
 
 void RuntimeCallStats::Enter(RuntimeCallCounter* counter) {
-  counter->count++;
-  counter->parent_counter = current_counter;
-  current_counter = counter;
+  Enter(new RuntimeCallTimer(counter, current_timer_));
 }
-void RuntimeCallStats::Leave(base::TimeDelta time) {
-  RuntimeCallCounter* counter = current_counter;
-  counter->time += time;
-  current_counter = counter->parent_counter;
-  counter->parent_counter = NULL;
-  if (current_counter != NULL) {
-    current_counter->time -= time;
-  }
+
+void RuntimeCallStats::Enter(RuntimeCallTimer* timer_) {
+  current_timer_ = timer_;
+  current_timer_->Start();
+}
+
+void RuntimeCallStats::Leave() {
+  RuntimeCallTimer* timer = current_timer_;
+  Leave(timer);
+  delete timer;
+}
+
+void RuntimeCallStats::Leave(RuntimeCallTimer* timer) {
+  current_timer_ = timer->Stop();
 }
 
 void RuntimeCallStats::Print(std::ostream& os) {
   RuntimeCallStatEntries entries;
 
-#define PRINT_COUNTER(name, nargs, ressize)   \
-  if (this->Runtime_##name.count > 0) {       \
-    entries.Add(#name, this->Runtime_##name); \
-  }
+#define PRINT_COUNTER(name, nargs, ressize) entries.Add(&this->Runtime_##name);
   FOR_EACH_INTRINSIC(PRINT_COUNTER)
 #undef PRINT_COUNTER
-#define PRINT_COUNTER(name, type)             \
-  if (this->Builtin_##name.count > 0) {       \
-    entries.Add(#name, this->Builtin_##name); \
-  }
+
+#define PRINT_COUNTER(name, type) entries.Add(&this->Builtin_##name);
   BUILTIN_LIST_C(PRINT_COUNTER)
 #undef PRINT_COUNTER
+
+  entries.Add(&this->ExternalCallback);
+  entries.Add(&this->UnexpectedStubMiss);
+
   entries.Print(os);
 }
 
@@ -310,5 +317,19 @@ void RuntimeCallStats::Reset() {
 #undef RESET_COUNTER
 }
 
+RuntimeCallTimerScope::RuntimeCallTimerScope(Isolate* isolate,
+                                             RuntimeCallCounter* counter)
+    : isolate_(isolate),
+      timer_(counter,
+             isolate->counters()->runtime_call_stats()->current_timer()) {
+  if (!FLAG_runtime_call_stats) return;
+  isolate->counters()->runtime_call_stats()->Enter(&timer_);
+}
+
+RuntimeCallTimerScope::~RuntimeCallTimerScope() {
+  if (!FLAG_runtime_call_stats) return;
+  isolate_->counters()->runtime_call_stats()->Leave(&timer_);
+}
+
 }  // namespace internal
 }  // namespace v8

src/counters.h

@@ -332,8 +332,8 @@ class AggregatableHistogramTimer : public Histogram {
 };
 
 // A helper class for use with AggregatableHistogramTimer. This is the
-// outer-most timer scope used with an AggregatableHistogramTimer. It will
-// aggregate the information from the inner AggregatedHistogramTimerScope.
+// // outer-most timer scope used with an AggregatableHistogramTimer. It will
+// // aggregate the information from the inner AggregatedHistogramTimerScope.
 class AggregatingHistogramTimerScope {
  public:
   explicit AggregatingHistogramTimerScope(AggregatableHistogramTimer* histogram)
@@ -347,7 +347,7 @@ class AggregatingHistogramTimerScope {
 };
 
 // A helper class for use with AggregatableHistogramTimer, the "inner" scope
-// which defines the events to be timed.
+// // which defines the events to be timed.
 class AggregatedHistogramTimerScope {
  public:
   explicit AggregatedHistogramTimerScope(AggregatableHistogramTimer* histogram)
@@ -479,6 +479,91 @@ double AggregatedMemoryHistogram<Histogram>::Aggregate(double current_ms,
          value * ((current_ms - last_ms_) / interval_ms);
 }
 
+struct RuntimeCallCounter {
+  explicit RuntimeCallCounter(const char* name) : name(name) {}
+  void Reset();
+
+  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 {
+ public:
+  RuntimeCallTimer(RuntimeCallCounter* counter, RuntimeCallTimer* parent)
+      : counter_(counter), parent_(parent) {}
+
+  inline void Start() {
+    timer_.Start();
+    counter_->count++;
+  }
+
+  inline RuntimeCallTimer* Stop() {
+    base::TimeDelta delta = timer_.Elapsed();
+    counter_->time += delta;
+    if (parent_ != NULL) {
+      parent_->AdjustForSubTimer(delta);
+    }
+    return parent_;
+  }
+
+  void AdjustForSubTimer(base::TimeDelta delta) { counter_->time -= delta; }
+
+ private:
+  RuntimeCallCounter* counter_;
+  RuntimeCallTimer* parent_;
+  base::ElapsedTimer timer_;
+};
+
+struct RuntimeCallStats {
+  // Dummy counter for the unexpected stub miss.
+  RuntimeCallCounter UnexpectedStubMiss =
+      RuntimeCallCounter("UnexpectedStubMiss");
+  // Counter for runtime callbacks into JavaScript.
+  RuntimeCallCounter ExternalCallback = RuntimeCallCounter("ExternalCallback");
+#define CALL_RUNTIME_COUNTER(name, nargs, ressize) \
+  RuntimeCallCounter Runtime_##name = RuntimeCallCounter(#name);
+  FOR_EACH_INTRINSIC(CALL_RUNTIME_COUNTER)
+#undef CALL_RUNTIME_COUNTER
+#define CALL_BUILTIN_COUNTER(name, type) \
+  RuntimeCallCounter Builtin_##name = RuntimeCallCounter(#name);
+  BUILTIN_LIST_C(CALL_BUILTIN_COUNTER)
+#undef CALL_BUILTIN_COUNTER
+
+  // Counter to track recursive time events.
+  RuntimeCallTimer* current_timer_ = NULL;
+
+  // Starting measuring the time for a function. This will establish the
+  // connection to the parent counter for properly calculating the own times.
+  void Enter(RuntimeCallCounter* counter);
+  void Enter(RuntimeCallTimer* timer);
+  // Leave a scope for a measured runtime function. This will properly add
+  // the time delta to the current_counter and subtract the delta from its
+  // parent.
+  void Leave();
+  void Leave(RuntimeCallTimer* timer);
+
+  RuntimeCallTimer* current_timer() { return current_timer_; }
+
+  void Reset();
+  void Print(std::ostream& os);
+
+  RuntimeCallStats() { Reset(); }
+};
+
+// A RuntimeCallTimerScopes wraps around a RuntimeCallTimer to measure the
+// the time of C++ scope.
+class RuntimeCallTimerScope {
+ public:
+  explicit RuntimeCallTimerScope(Isolate* isolate, RuntimeCallCounter* counter);
+  ~RuntimeCallTimerScope();
+
+ private:
+  Isolate* isolate_;
+  RuntimeCallTimer timer_;
+};
 
 #define HISTOGRAM_RANGE_LIST(HR)                                              \
   /* Generic range histograms */                                              \
@@ -703,42 +788,6 @@ double AggregatedMemoryHistogram<Histogram>::Aggregate(double current_ms,
   /* Total count of functions compiled using the baseline compiler. */         \
   SC(total_baseline_compile_count, V8.TotalBaselineCompileCount)
 
-typedef struct RuntimeCallCounter {
-  int64_t count = 0;
-  base::TimeDelta time;
-  RuntimeCallCounter* parent_counter;
-
-  void Reset();
-} RuntimeCallCounter;
-
-struct RuntimeCallStats {
-#define CALL_RUNTIME_COUNTER(name, nargs, ressize) \
-  RuntimeCallCounter Runtime_##name;
-  FOR_EACH_INTRINSIC(CALL_RUNTIME_COUNTER)
-#undef CALL_RUNTIME_COUNTER
-#define CALL_BUILTIN_COUNTER(name, type) RuntimeCallCounter Builtin_##name;
-  BUILTIN_LIST_C(CALL_BUILTIN_COUNTER)
-#undef CALL_BUILTIN_COUNTER
-
-  // Dummy counter for the unexpected stub miss.
-  RuntimeCallCounter UnexpectedStubMiss;
-  // Counter to track recursive time events.
-  RuntimeCallCounter* current_counter;
-
-  // Starting measuring the time for a function. This will establish the
-  // connection to the parent counter for properly calculating the own times.
-  void Enter(RuntimeCallCounter* counter);
-  // Leave a scope for a measured runtime function. This will properly add
-  // the time delta to the current_counter and subtract the delta from its
-  // parent.
-  void Leave(base::TimeDelta time);
-
-  void Reset();
-  void Print(std::ostream& os);
-
-  RuntimeCallStats() { Reset(); }
-};
-
 // This file contains all the v8 counters that are in use.
 class Counters {
  public:

src/vm-state-inl.h

@@ -61,18 +61,25 @@ VMState<Tag>::~VMState() {
   isolate_->set_current_vm_state(previous_tag_);
 }
 
-
 ExternalCallbackScope::ExternalCallbackScope(Isolate* isolate, Address callback)
     : isolate_(isolate),
       callback_(callback),
-      previous_scope_(isolate->external_callback_scope()) {
+      previous_scope_(isolate->external_callback_scope()),
+      timer_(&isolate->counters()->runtime_call_stats()->ExternalCallback,
+             isolate->counters()->runtime_call_stats()->current_timer()) {
 #ifdef USE_SIMULATOR
   scope_address_ = Simulator::current(isolate)->get_sp();
 #endif
   isolate_->set_external_callback_scope(this);
+  if (FLAG_runtime_call_stats) {
+    isolate_->counters()->runtime_call_stats()->Enter(&timer_);
+  }
 }
 
 ExternalCallbackScope::~ExternalCallbackScope() {
+  if (FLAG_runtime_call_stats) {
+    isolate_->counters()->runtime_call_stats()->Leave(&timer_);
+  }
   isolate_->set_external_callback_scope(previous_scope_);
 }
 

src/vm-state.h

@@ -6,6 +6,7 @@
 #define V8_VM_STATE_H_
 
 #include "src/allocation.h"
+#include "src/counters.h"
 #include "src/isolate.h"
 
 namespace v8 {
@@ -48,6 +49,7 @@ class ExternalCallbackScope BASE_EMBEDDED {
   Isolate* isolate_;
   Address callback_;
   ExternalCallbackScope* previous_scope_;
+  RuntimeCallTimer timer_;
 #ifdef USE_SIMULATOR
   Address scope_address_;
 #endif