[turbofan] Introduce V8.TurboFan timed histogram counters.

This adds new timed histograms to measure the time that TurboFan spends
on various compilation phases on a per function bases. This includes the
following new counters:

- V8.TurboFanOptimizePrepare
  Time spent in the preparation phase of TurboFan optimization. Recorded
  on each regular optimization of a function.
- V8.TurboFanOptimizeExecute
  Time spent in the execution phase of TurboFan optimization. Recorded on
  each regular optimization of a function.
- V8.TurboFanOptimizeFinalize
  Time spent in the finalization phase of TurboFan optimization. Recorded
  on each regular optimization of a function.
- V8.TurboFanOptimizeTotalForeground
  Total time spent on the main thread during TurboFan optimization.
  Recorded on each regular optimization of a function.
- V8.TurboFanOptimizeTotalBackground
  Total time spent on a background thread during TurboFan optimization.
  Recorded on each regular optimization of a function.
- V8.TurboFanOptimizeTotalTime
  Total time from starting optimizing to installing the code object.
  Recorded on each regular optimization of a function.
- V8.TurboFanOptimizeForOnStackReplacementPrepare
  Time spent in the preparation phase of TurboFan optimization for On
  Stack Replacement (OSR). Recorded on each optimization  for on-stack
  replacement of a function.
- V8.TurboFanOptimizeForOnStackReplacementExecute
  Time spent in the execution phase of TurboFan optimization for On Stack
  Replacement (OSR). Recorded on each optimization  for on-stack replacement
  of a function.
- V8.TurboFanOptimizeForOnStackReplacementFinalize
  Time spent in the finalization phase of TurboFan optimization for On Stack
  Replacement (OSR). Recorded on each optimization  for on-stack replacement
  of a function.
- V8.TurboFanOptimizeForOnStackReplacementTotalTime
  Total time from starting optimizing for On Stack Replacement (OSR) to
  installing the code object. Recorded on each optimization for on-stack
  replacement of a function.

This should give us a good overview and guide/validate future work on
the concurrent optimization pipeline.

Bug: v8:7790, v8:9074
Change-Id: I96573cd1da472684d06624b7573e4afd6efca99c
Doc: http://doc/1umgFxjLQ9p22lVS_BdhmAlo1o9xnxnWlhVi_HMWNktM
Cq-Include-Trybots: luci.chromium.try:linux-blink-rel
Reviewed-on: https://chromium-review.googlesource.com/c/v8/v8/+/1547864
Commit-Queue: Benedikt Meurer <bmeurer@chromium.org>
Commit-Queue: Jaroslav Sevcik <jarin@chromium.org>
Auto-Submit: Benedikt Meurer <bmeurer@chromium.org>
Reviewed-by: Jaroslav Sevcik <jarin@chromium.org>
Cr-Commit-Position: refs/heads/master@{#60604}

src/compiler.cc

@@ -174,6 +174,7 @@ void UnoptimizedCompilationJob::RecordCompilationStats(Isolate* isolate) const {
   counters->total_baseline_compile_count()->Increment(1);
 
   // TODO(5203): Add timers for each phase of compilation.
+  // Also add total time (there's now already timer_ on the base class).
 }
 
 void UnoptimizedCompilationJob::RecordFunctionCompilation(
@@ -249,7 +250,8 @@ CompilationJob::Status OptimizedCompilationJob::AbortOptimization(
   return UpdateState(FAILED, State::kFailed);
 }
 
-void OptimizedCompilationJob::RecordCompilationStats() const {
+void OptimizedCompilationJob::RecordCompilationStats(CompilationMode mode,
+                                                     Isolate* isolate) const {
   DCHECK(compilation_info()->IsOptimizing());
   Handle<JSFunction> function = compilation_info()->closure();
   double ms_creategraph = time_taken_to_prepare_.InMillisecondsF();
@@ -272,6 +274,43 @@ void OptimizedCompilationJob::RecordCompilationStats() const {
     PrintF("Compiled: %d functions with %d byte source size in %fms.\n",
            compiled_functions, code_size, compilation_time);
   }
+  Counters* const counters = isolate->counters();
+  if (compilation_info()->is_osr()) {
+    counters->turbofan_osr_prepare()->AddSample(
+        static_cast<int>(time_taken_to_prepare_.InMicroseconds()));
+    counters->turbofan_osr_execute()->AddSample(
+        static_cast<int>(time_taken_to_execute_.InMicroseconds()));
+    counters->turbofan_osr_finalize()->AddSample(
+        static_cast<int>(time_taken_to_finalize_.InMicroseconds()));
+    counters->turbofan_osr_total_time()->AddSample(
+        static_cast<int>(ElapsedTime().InMicroseconds()));
+  } else {
+    counters->turbofan_optimize_prepare()->AddSample(
+        static_cast<int>(time_taken_to_prepare_.InMicroseconds()));
+    counters->turbofan_optimize_execute()->AddSample(
+        static_cast<int>(time_taken_to_execute_.InMicroseconds()));
+    counters->turbofan_optimize_finalize()->AddSample(
+        static_cast<int>(time_taken_to_finalize_.InMicroseconds()));
+    counters->turbofan_optimize_total_time()->AddSample(
+        static_cast<int>(ElapsedTime().InMicroseconds()));
+
+    // Compute foreground / background time.
+    base::TimeDelta time_background;
+    base::TimeDelta time_foreground =
+        time_taken_to_prepare_ + time_taken_to_execute_;
+    switch (mode) {
+      case OptimizedCompilationJob::kConcurrent:
+        time_background += time_taken_to_execute_;
+        break;
+      case OptimizedCompilationJob::kSynchronous:
+        time_foreground += time_taken_to_execute_;
+        break;
+    }
+    counters->turbofan_optimize_total_background()->AddSample(
+        static_cast<int>(time_background.InMicroseconds()));
+    counters->turbofan_optimize_total_foreground()->AddSample(
+        static_cast<int>(time_foreground.InMicroseconds()));
+  }
 }
 
 void OptimizedCompilationJob::RecordFunctionCompilation(
@@ -686,7 +725,7 @@ bool GetOptimizedCodeNow(OptimizedCompilationJob* job, Isolate* isolate) {
   }
 
   // Success!
-  job->RecordCompilationStats();
+  job->RecordCompilationStats(OptimizedCompilationJob::kSynchronous, isolate);
   DCHECK(!isolate->has_pending_exception());
   InsertCodeIntoOptimizedCodeCache(compilation_info);
   job->RecordFunctionCompilation(CodeEventListener::LAZY_COMPILE_TAG, isolate);
@@ -2132,7 +2171,8 @@ bool Compiler::FinalizeOptimizedCompilationJob(OptimizedCompilationJob* job,
     if (shared->optimization_disabled()) {
       job->RetryOptimization(BailoutReason::kOptimizationDisabled);
     } else if (job->FinalizeJob(isolate) == CompilationJob::SUCCEEDED) {
-      job->RecordCompilationStats();
+      job->RecordCompilationStats(OptimizedCompilationJob::kConcurrent,
+                                  isolate);
       job->RecordFunctionCompilation(CodeEventListener::LAZY_COMPILE_TAG,
                                      isolate);
       InsertCodeIntoOptimizedCodeCache(compilation_info);

src/compiler.h

@@ -10,6 +10,7 @@
 
 #include "src/allocation.h"
 #include "src/bailout-reason.h"
+#include "src/base/platform/elapsed-timer.h"
 #include "src/code-events.h"
 #include "src/contexts.h"
 #include "src/isolate.h"
@@ -196,7 +197,9 @@ class V8_EXPORT_PRIVATE CompilationJob {
   };
 
   CompilationJob(uintptr_t stack_limit, State initial_state)
-      : state_(initial_state), stack_limit_(stack_limit) {}
+      : state_(initial_state), stack_limit_(stack_limit) {
+    timer_.Start();
+  }
   virtual ~CompilationJob() = default;
 
   void set_stack_limit(uintptr_t stack_limit) { stack_limit_ = stack_limit; }
@@ -205,6 +208,10 @@ class V8_EXPORT_PRIVATE CompilationJob {
   State state() const { return state_; }
 
  protected:
+  V8_WARN_UNUSED_RESULT base::TimeDelta ElapsedTime() const {
+    return timer_.Elapsed();
+  }
+
   V8_WARN_UNUSED_RESULT Status UpdateState(Status status, State next_state) {
     if (status == SUCCEEDED) {
       state_ = next_state;
@@ -217,6 +224,7 @@ class V8_EXPORT_PRIVATE CompilationJob {
  private:
   State state_;
   uintptr_t stack_limit_;
+  base::ElapsedTimer timer_;
 };
 
 // A base class for unoptimized compilation jobs.
@@ -302,7 +310,8 @@ class OptimizedCompilationJob : public CompilationJob {
   // Should only be called on optimization compilation jobs.
   Status AbortOptimization(BailoutReason reason);
 
-  void RecordCompilationStats() const;
+  enum CompilationMode { kConcurrent, kSynchronous };
+  void RecordCompilationStats(CompilationMode mode, Isolate* isolate) const;
   void RecordFunctionCompilation(CodeEventListener::LogEventsAndTags tag,
                                  Isolate* isolate) const;
 

src/counters-definitions.h

@@ -133,6 +133,27 @@ namespace internal {
   HT(gc_scavenger, V8.GCScavenger, 10000, MILLISECOND)                         \
   HT(gc_scavenger_background, V8.GCScavengerBackground, 10000, MILLISECOND)    \
   HT(gc_scavenger_foreground, V8.GCScavengerForeground, 10000, MILLISECOND)    \
+  /* TurboFan timers. */                                                       \
+  HT(turbofan_optimize_prepare, V8.TurboFanOptimizePrepare, 1000000,           \
+     MICROSECOND)                                                              \
+  HT(turbofan_optimize_execute, V8.TurboFanOptimizeExecute, 1000000,           \
+     MICROSECOND)                                                              \
+  HT(turbofan_optimize_finalize, V8.TurboFanOptimizeFinalize, 1000000,         \
+     MICROSECOND)                                                              \
+  HT(turbofan_optimize_total_foreground, V8.TurboFanOptimizeTotalForeground,   \
+     10000000, MICROSECOND)                                                    \
+  HT(turbofan_optimize_total_background, V8.TurboFanOptimizeTotalBackground,   \
+     10000000, MICROSECOND)                                                    \
+  HT(turbofan_optimize_total_time, V8.TurboFanOptimizeTotalTime, 10000000,     \
+     MICROSECOND)                                                              \
+  HT(turbofan_osr_prepare, V8.TurboFanOptimizeForOnStackReplacementPrepare,    \
+     1000000, MICROSECOND)                                                     \
+  HT(turbofan_osr_execute, V8.TurboFanOptimizeForOnStackReplacementExecute,    \
+     1000000, MICROSECOND)                                                     \
+  HT(turbofan_osr_finalize, V8.TurboFanOptimizeForOnStackReplacementFinalize,  \
+     1000000, MICROSECOND)                                                     \
+  HT(turbofan_osr_total_time,                                                  \
+     V8.TurboFanOptimizeForOnStackReplacementTotalTime, 10000000, MICROSECOND) \
   /* Wasm timers. */                                                           \
   HT(wasm_decode_asm_module_time, V8.WasmDecodeModuleMicroSeconds.asm,         \
      1000000, MICROSECOND)                                                     \