[counter] Properly measure own-time of runtime counters.

By keeping track of the stack of counters we can properly subtract the
subcounter times and properly measure the own-time spent in each runtime
function. This is useful to get more details for builtins like HandleApiCall
which are typical top-level entries for chome which previously prevent
measurements of sub-calls to builtins/runtime functions.

BUG=

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

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

src/arguments.h

@@ -271,28 +271,23 @@ 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();                                           \
-    RuntimeCallStats* stats = isolate->counters()->runtime_call_stats();  \
-    stats->Count_##Name++;                                                \
-    base::ElapsedTimer timer;                                             \
-    bool timing = false;                                                  \
-    if (FLAG_runtime_call_stats && !stats->in_runtime_call) {             \
-      stats->in_runtime_call = true;                                      \
-      timing = true;                                                      \
-      timer.Start();                                                      \
-    }                                                                     \
-    Arguments args(args_length, args_object);                             \
-    Type value = __RT_impl_##Name(args, isolate);                         \
-    if (timing) {                                                         \
-      stats->in_runtime_call = false;                                     \
-      isolate->counters()->runtime_call_stats()->Time_##Name +=           \
-          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();                                            \
+    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;                                                          \
+  }                                                                        \
   static Type __RT_impl_##Name(Arguments args, Isolate* isolate)
 
 #define RUNTIME_FUNCTION(Name) RUNTIME_FUNCTION_RETURNS_TYPE(Object*, Name)

src/builtins.cc

@@ -142,22 +142,17 @@ BUILTIN_LIST_C(DEF_ARG_TYPE)
                                                      Isolate* isolate);        \
   MUST_USE_RESULT static Object* Builtin_##name(                               \
       int args_length, Object** args_object, Isolate* isolate) {               \
-    RuntimeCallStats* stats = isolate->counters()->runtime_call_stats();       \
-    stats->Count_Builtin_##name++;                                             \
+    isolate->counters()->runtime_calls()->Increment();                         \
     base::ElapsedTimer timer;                                                  \
-    bool timing = false;                                                       \
-    if (FLAG_runtime_call_stats && !stats->in_runtime_call) {                  \
-      stats->in_runtime_call = true;                                           \
-      timing = true;                                                           \
+    if (FLAG_runtime_call_stats) {                                             \
+      RuntimeCallStats* stats = isolate->counters()->runtime_call_stats();     \
+      stats->Enter(&stats->Builtin_##name);                                    \
       timer.Start();                                                           \
     }                                                                          \
     name##ArgumentsType args(args_length, args_object);                        \
-    isolate->counters()->runtime_calls()->Increment();                         \
     Object* value = Builtin_Impl_##name(args, isolate);                        \
-    if (timing) {                                                              \
-      stats->in_runtime_call = false;                                          \
-      isolate->counters()->runtime_call_stats()->Time_Builtin_##name +=        \
-          timer.Elapsed();                                                     \
+    if (FLAG_runtime_call_stats) {                                             \
+      isolate->counters()->runtime_call_stats()->Leave(timer.Elapsed());       \
     }                                                                          \
     return value;                                                              \
   }                                                                            \

src/counters.cc

@@ -212,10 +212,10 @@ class RuntimeCallStatEntries {
     }
   }
 
-  void Add(const char* name, base::TimeDelta time, uint32_t count) {
-    entries.push_back(Entry(name, time, count));
-    total_time += time;
-    total_call_count += count;
+  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;
   }
 
  private:
@@ -263,18 +263,38 @@ class RuntimeCallStatEntries {
   std::vector<Entry> entries;
 };
 
+void RuntimeCallCounter::Reset() {
+  count = 0;
+  time = base::TimeDelta();
+}
+
+void RuntimeCallStats::Enter(RuntimeCallCounter* counter) {
+  counter->count++;
+  counter->parent_counter = current_counter;
+  current_counter = counter;
+}
+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::Print(std::ostream& os) {
   RuntimeCallStatEntries entries;
 
-#define PRINT_COUNTER(name, nargs, ressize)                                    \
-  if (this->Count_Runtime_##name > 0) {                                        \
-    entries.Add(#name, this->Time_Runtime_##name, this->Count_Runtime_##name); \
+#define PRINT_COUNTER(name, nargs, ressize)   \
+  if (this->Runtime_##name.count > 0) {       \
+    entries.Add(#name, this->Runtime_##name); \
   }
   FOR_EACH_INTRINSIC(PRINT_COUNTER)
 #undef PRINT_COUNTER
-#define PRINT_COUNTER(name, type)                                              \
-  if (this->Count_Builtin_##name > 0) {                                        \
-    entries.Add(#name, this->Time_Builtin_##name, this->Count_Builtin_##name); \
+#define PRINT_COUNTER(name, type)             \
+  if (this->Builtin_##name.count > 0) {       \
+    entries.Add(#name, this->Builtin_##name); \
   }
   BUILTIN_LIST_C(PRINT_COUNTER)
 #undef PRINT_COUNTER
@@ -282,14 +302,10 @@ void RuntimeCallStats::Print(std::ostream& os) {
 }
 
 void RuntimeCallStats::Reset() {
-#define RESET_COUNTER(name, nargs, ressize) \
-  Count_Runtime_##name = 0;                 \
-  Time_Runtime_##name = base::TimeDelta();
+#define RESET_COUNTER(name, nargs, ressize) this->Runtime_##name.Reset();
   FOR_EACH_INTRINSIC(RESET_COUNTER)
 #undef RESET_COUNTER
-#define RESET_COUNTER(name, type) \
-  Count_Builtin_##name = 0;       \
-  Time_Builtin_##name = base::TimeDelta();
+#define RESET_COUNTER(name, type) this->Builtin_##name.Reset();
   BUILTIN_LIST_C(RESET_COUNTER)
 #undef RESET_COUNTER
 }

src/counters.h

@@ -701,23 +701,35 @@ 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) \
-  uint32_t Count_Runtime_##name;                   \
-  base::TimeDelta Time_Runtime_##name;
+  RuntimeCallCounter Runtime_##name;
   FOR_EACH_INTRINSIC(CALL_RUNTIME_COUNTER)
 #undef CALL_RUNTIME_COUNTER
-#define CALL_BUILTIN_COUNTER(name, type) \
-  uint32_t Count_Builtin_##name;         \
-  base::TimeDelta Time_Builtin_##name;
+#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.
-  uint32_t Count_UnexpectedStubMiss;
-  base::TimeDelta Time_UnexpectedStubMiss;
-
-  bool in_runtime_call = false;
+  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);