Runtime call counters and timers.

In d8, run with --runtime-call-stats and it will output the stats when d8 finishes.

In Chrome, run the following: (only on trusted code, this punches *massive* security hole into Chrome)

chrome --js-flags="--runtime-call-stats --allow-natives-syntax"

To get the stats in the console, just run

console.log(%GetAndResetRuntimeCallStats());

To output stats every second:

setInterval(function() { console.log(%GetAndResetRuntimeCallStats()); }, 1000)

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

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

src/arguments.h

@@ -274,14 +274,29 @@ double ClobberDoubleRegisters(double x1, double x2, double x3, double x4);
 #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();                                            \
-  Arguments args(args_length, args_object);                              \
-  return __RT_impl_##Name(args, isolate);                                \
-}                                                                        \
-static Type __RT_impl_##Name(Arguments args, Isolate* isolate)
+#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->runtime_state()->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->runtime_state()->runtime_call_stats()->Time_##Name +=          \
+          timer.Elapsed();                                                    \
+    }                                                                         \
+    return value;                                                             \
+  }                                                                           \
+  static Type __RT_impl_##Name(Arguments args, Isolate* isolate)
 
 
 #define RUNTIME_FUNCTION(Name) RUNTIME_FUNCTION_RETURNS_TYPE(Object*, Name)

src/flag-definitions.h

@@ -802,6 +802,9 @@ DEFINE_INT(hash_seed, 0,
            "Fixed seed to use to hash property keys (0 means random)"
            "(with snapshots this option cannot override the baked-in seed)")
 
+// runtime.cc
+DEFINE_BOOL(runtime_call_stats, false, "report runtime call counts and times")
+
 // snapshot-common.cc
 DEFINE_BOOL(profile_deserialization, false,
             "Print the time it takes to deserialize the snapshot.")

src/isolate.cc

@@ -2396,6 +2396,11 @@ void Isolate::DumpAndResetCompilationStats() {
   turbo_statistics_ = nullptr;
   delete hstatistics_;
   hstatistics_ = nullptr;
+  if (FLAG_runtime_call_stats) {
+    OFStream os(stdout);
+    runtime_state()->runtime_call_stats()->Print(os);
+    runtime_state()->runtime_call_stats()->Reset();
+  }
 }
 
 

src/runtime/runtime-internal.cc

@@ -477,5 +477,17 @@ RUNTIME_FUNCTION(Runtime_IncrementUseCounter) {
   return isolate->heap()->undefined_value();
 }
 
+
+RUNTIME_FUNCTION(Runtime_GetAndResetRuntimeCallStats) {
+  HandleScope scope(isolate);
+  DCHECK_EQ(0, args.length());
+  std::stringstream stats_stream;
+  isolate->runtime_state()->runtime_call_stats()->Print(stats_stream);
+  Handle<String> result =
+      isolate->factory()->NewStringFromAsciiChecked(stats_stream.str().c_str());
+  isolate->runtime_state()->runtime_call_stats()->Reset();
+  return *result;
+}
+
 }  // namespace internal
 }  // namespace v8

src/runtime/runtime.cc

@@ -4,6 +4,8 @@
 
 #include "src/runtime/runtime.h"
 
+#include <iomanip>
+
 #include "src/assembler.h"
 #include "src/contexts.h"
 #include "src/handles-inl.h"
@@ -130,5 +132,80 @@ std::ostream& operator<<(std::ostream& os, Runtime::FunctionId id) {
   return os << Runtime::FunctionForId(id)->name;
 }
 
+
+class RuntimeCallStatEntries {
+ public:
+  void Print(std::ostream& os) {
+    if (total_call_count > 0) {
+      std::sort(entries.rbegin(), entries.rend());
+      os << "Runtime function                                  Time      "
+            "Count"
+         << std::endl
+         << std::string(70, '=') << std::endl;
+      for (Entry& entry : entries) {
+        entry.Print(os);
+      }
+      os << std::string(60, '-') << std::endl;
+      Entry("Total", total_time, total_call_count).Print(os);
+    }
+  }
+
+  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;
+  }
+
+ private:
+  class Entry {
+   public:
+    Entry(const char* name, base::TimeDelta time, uint64_t count)
+        : name_(name), time_(time.InMilliseconds()), count_(count) {}
+
+    bool operator<(const Entry& other) const {
+      if (time_ < other.time_) return true;
+      if (time_ > other.time_) return false;
+      return count_ < other.count_;
+    }
+
+    void Print(std::ostream& os) {
+      os << std::setw(50) << name_;
+      os << std::setw(8) << time_ << "ms";
+      os << std::setw(10) << count_ << std::endl;
+    }
+
+   private:
+    const char* name_;
+    int64_t time_;
+    uint64_t count_;
+  };
+
+  uint64_t total_call_count = 0;
+  base::TimeDelta total_time;
+  std::vector<Entry> entries;
+};
+
+
+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); \
+  }
+  FOR_EACH_INTRINSIC(PRINT_COUNTER)
+#undef PRINT_COUNTER
+  entries.Print(os);
+}
+
+
+void RuntimeCallStats::Reset() {
+#define RESET_COUNTER(name, nargs, ressize) \
+  Count_Runtime_##name = 0;                 \
+  Time_Runtime_##name = base::TimeDelta();
+  FOR_EACH_INTRINSIC(RESET_COUNTER)
+#undef RESET_COUNTER
+}
+
 }  // namespace internal
 }  // namespace v8