[wasm] Add metrics for lazy compilation

This CL adds three metrics for lazy compilation: the number of functions
compiled lazily, the total time spent on compiling functions lazily,
and the maximum time spent on compiling a single function. All three
metrics get recorded twice, once 5 seconds after instantiation, and once
20 seconds after instantiation.

R=clemensb@chromium.org

Bug: v8:12852
Change-Id: Ib9e5e12921fb1ec7aefd53af604cbb389bee79b9
Reviewed-on: https://chromium-review.googlesource.com/c/v8/v8/+/3811502Reviewed-by: Clemens Backes <clemensb@chromium.org>
Commit-Queue: Andreas Haas <ahaas@chromium.org>
Cr-Commit-Position: refs/heads/main@{#82248}

src/logging/counters-definitions.h

@@ -108,7 +108,11 @@ namespace internal {
   /* Number of in-use external pointers in the external pointer table */       \
   /* Counted after sweeping the table at the end of mark-compact GC */         \
   HR(external_pointers_count, V8.SandboxedExternalPointersCount, 0,            \
-     kMaxExternalPointers, 101)
+     kMaxExternalPointers, 101)                                                \
+  HR(wasm_num_lazy_compilations_5sec, V8.WasmNumLazyCompilations5Sec, 0,       \
+     200000, 50)                                                               \
+  HR(wasm_num_lazy_compilations_20sec, V8.WasmNumLazyCompilations20Sec, 0,     \
+     200000, 50)
 
 #define NESTED_TIMED_HISTOGRAM_LIST(HT)                                       \
   /* Nested timer histograms allow distributions of nested timed results. */  \
@@ -245,7 +249,15 @@ namespace internal {
   HT(compile_script_on_background,                                             \
      V8.CompileScriptMicroSeconds.BackgroundThread, 1000000, MICROSECOND)      \
   HT(compile_function_on_background,                                           \
-     V8.CompileFunctionMicroSeconds.BackgroundThread, 1000000, MICROSECOND)
+     V8.CompileFunctionMicroSeconds.BackgroundThread, 1000000, MICROSECOND)    \
+  HT(wasm_max_lazy_compilation_time_5sec,                                      \
+     V8.WasmMaxLazyCompilationTime5SecMilliSeconds, 5000, MILLISECOND)         \
+  HT(wasm_max_lazy_compilation_time_20sec,                                     \
+     V8.WasmMaxLazyCompilationTime20SecMilliSeconds, 5000, MILLISECOND)        \
+  HT(wasm_sum_lazy_compilation_time_5sec,                                      \
+     V8.WasmSumLazyCompilationTime5SecMilliSeconds, 20000, MILLISECOND)        \
+  HT(wasm_sum_lazy_compilation_time_20sec,                                     \
+     V8.WasmSumLazyCompilationTime20SecMilliSeconds, 20000, MILLISECOND)
 
 #define AGGREGATABLE_HISTOGRAM_TIMER_LIST(AHT) \
   AHT(compile_lazy, V8.CompileLazyMicroSeconds)

src/wasm/module-compiler.cc

@@ -1138,24 +1138,44 @@ bool IsLazyModule(const WasmModule* module) {
          (FLAG_asm_wasm_lazy_compilation && is_asmjs_module(module));
 }
 
+class CompileLazyTimingScope {
+ public:
+  CompileLazyTimingScope(Counters* counters, NativeModule* native_module)
+      : counters_(counters), native_module_(native_module) {
+    timer_.Start();
+  }
+
+  ~CompileLazyTimingScope() {
+    base::TimeDelta elapsed = timer_.Elapsed();
+    native_module_->AddLazyCompilationTimeSample(elapsed.InMicroseconds());
+    counters_->wasm_lazy_compile_time()->AddTimedSample(elapsed);
+  }
+
+ private:
+  Counters* counters_;
+  NativeModule* native_module_;
+  base::ElapsedTimer timer_;
+};
+
 }  // namespace
 
 bool CompileLazy(Isolate* isolate, Handle<WasmInstanceObject> instance,
                  int func_index, NativeModule** out_native_module) {
   Handle<WasmModuleObject> module_object(instance->module_object(), isolate);
   NativeModule* native_module = module_object->native_module();
-  const WasmModule* module = native_module->module();
-  auto enabled_features = native_module->enabled_features();
   Counters* counters = isolate->counters();
 
   // Put the timer scope around everything, including the {CodeSpaceWriteScope}
   // and its destruction, to measure complete overhead (apart from the runtime
   // function itself, which has constant overhead).
-  base::Optional<TimedHistogramScope> lazy_compile_time_scope;
+  base::Optional<CompileLazyTimingScope> lazy_compile_time_scope;
   if (base::TimeTicks::IsHighResolution()) {
-    lazy_compile_time_scope.emplace(counters->wasm_lazy_compile_time());
+    lazy_compile_time_scope.emplace(counters, native_module);
   }
 
+  const WasmModule* module = native_module->module();
+  auto enabled_features = native_module->enabled_features();
+
   DCHECK(!native_module->lazy_compile_frozen());
 
   TRACE_LAZY("Compiling wasm-function#%d.\n", func_index);
@@ -1234,6 +1254,7 @@ bool CompileLazy(Isolate* isolate, Handle<WasmInstanceObject> instance,
     instance->feedback_vectors().set(
         declared_function_index(module, func_index), *vector);
   }
+
   return true;
 }
 

src/wasm/module-instantiate.cc

@@ -378,6 +378,52 @@ class InstanceBuilder {
   void InitializeTags(Handle<WasmInstanceObject> instance);
 };
 
+namespace {
+class ReportLazyCompilationTimesTask : public v8::Task {
+ public:
+  ReportLazyCompilationTimesTask(std::weak_ptr<Counters> counters,
+                                 std::weak_ptr<NativeModule> native_module,
+                                 int delay_in_seconds)
+      : counters_(std::move(counters)),
+        native_module_(std::move(native_module)),
+        delay_in_seconds_(delay_in_seconds) {}
+
+  void Run() final {
+    std::shared_ptr<NativeModule> native_module = native_module_.lock();
+    if (!native_module) return;
+    std::shared_ptr<Counters> counters = counters_.lock();
+    if (!counters) return;
+    int num_compilations = native_module->num_lazy_compilations();
+    // If no compilations happened, we don't add samples. Experiments showed
+    // many cases of num_compilations == 0, and adding these cases would make
+    // other cases less visible.
+    if (!num_compilations) return;
+    if (delay_in_seconds_ == 5) {
+      counters->wasm_num_lazy_compilations_5sec()->AddSample(num_compilations);
+      counters->wasm_sum_lazy_compilation_time_5sec()->AddSample(
+          static_cast<int>(native_module->sum_lazy_compilation_time_in_ms()));
+      counters->wasm_max_lazy_compilation_time_5sec()->AddSample(
+          static_cast<int>(native_module->max_lazy_compilation_time_in_ms()));
+      return;
+    }
+    if (delay_in_seconds_ == 20) {
+      counters->wasm_num_lazy_compilations_20sec()->AddSample(num_compilations);
+      counters->wasm_sum_lazy_compilation_time_20sec()->AddSample(
+          static_cast<int>(native_module->sum_lazy_compilation_time_in_ms()));
+      counters->wasm_max_lazy_compilation_time_20sec()->AddSample(
+          static_cast<int>(native_module->max_lazy_compilation_time_in_ms()));
+      return;
+    }
+    UNREACHABLE();
+  }
+
+ private:
+  std::weak_ptr<Counters> counters_;
+  std::weak_ptr<NativeModule> native_module_;
+  int delay_in_seconds_;
+};
+}  // namespace
+
 MaybeHandle<WasmInstanceObject> InstantiateToInstanceObject(
     Isolate* isolate, ErrorThrower* thrower,
     Handle<WasmModuleObject> module_object, MaybeHandle<JSReceiver> imports,
@@ -387,8 +433,25 @@ MaybeHandle<WasmInstanceObject> InstantiateToInstanceObject(
   InstanceBuilder builder(isolate, context_id, thrower, module_object, imports,
                           memory_buffer);
   auto instance = builder.Build();
-  if (!instance.is_null() && builder.ExecuteStartFunction()) {
-    return instance;
+  if (!instance.is_null()) {
+    // Post tasks for lazy compilation metrics before we call the start function
+    if (FLAG_wasm_lazy_compilation &&
+        module_object->native_module()
+            ->ShouldLazyCompilationMetricsBeReported()) {
+      V8::GetCurrentPlatform()->CallDelayedOnWorkerThread(
+          std::make_unique<ReportLazyCompilationTimesTask>(
+              isolate->async_counters(), module_object->shared_native_module(),
+              5),
+          5.0);
+      V8::GetCurrentPlatform()->CallDelayedOnWorkerThread(
+          std::make_unique<ReportLazyCompilationTimesTask>(
+              isolate->async_counters(), module_object->shared_native_module(),
+              20),
+          20.0);
+    }
+    if (builder.ExecuteStartFunction()) {
+      return instance;
+    }
   }
   DCHECK(isolate->has_pending_exception() || thrower->error());
   return {};

src/wasm/wasm-code-manager.cc

@@ -1718,6 +1718,20 @@ void NativeModule::UpdateCPUDuration(size_t cpu_duration, ExecutionTier tier) {
   }
 }
 
+void NativeModule::AddLazyCompilationTimeSample(int64_t sample_in_micro_sec) {
+  num_lazy_compilations_.fetch_add(1, std::memory_order_relaxed);
+  sum_lazy_compilation_time_in_micro_sec_.fetch_add(sample_in_micro_sec,
+                                                    std::memory_order_relaxed);
+  int64_t max =
+      max_lazy_compilation_time_in_micro_sec_.load(std::memory_order_relaxed);
+  while (sample_in_micro_sec > max &&
+         !max_lazy_compilation_time_in_micro_sec_.compare_exchange_weak(
+             max, sample_in_micro_sec, std::memory_order_relaxed,
+             std::memory_order_relaxed)) {
+    // Repeat until we set the new maximum sucessfully.
+  }
+}
+
 void NativeModule::TransferNewOwnedCodeLocked() const {
   allocation_mutex_.AssertHeld();
   DCHECK(!new_owned_code_.empty());

src/wasm/wasm-code-manager.h

@@ -773,13 +773,46 @@ class V8_EXPORT_PRIVATE NativeModule final {
   size_t generated_code_size() const {
     return code_allocator_.generated_code_size();
   }
-  size_t liftoff_bailout_count() const { return liftoff_bailout_count_.load(); }
-  size_t liftoff_code_size() const { return liftoff_code_size_.load(); }
-  size_t turbofan_code_size() const { return turbofan_code_size_.load(); }
+  size_t liftoff_bailout_count() const {
+    return liftoff_bailout_count_.load(std::memory_order_relaxed);
+  }
+  size_t liftoff_code_size() const {
+    return liftoff_code_size_.load(std::memory_order_relaxed);
+  }
+  size_t turbofan_code_size() const {
+    return turbofan_code_size_.load(std::memory_order_relaxed);
+  }
   size_t baseline_compilation_cpu_duration() const {
     return baseline_compilation_cpu_duration_.load();
   }
-  size_t tier_up_cpu_duration() const { return tier_up_cpu_duration_.load(); }
+  size_t tier_up_cpu_duration() const {
+    return tier_up_cpu_duration_.load(std::memory_order_relaxed);
+  }
+
+  void AddLazyCompilationTimeSample(int64_t sample);
+
+  int num_lazy_compilations() const {
+    return num_lazy_compilations_.load(std::memory_order_relaxed);
+  }
+
+  int64_t sum_lazy_compilation_time_in_ms() const {
+    return sum_lazy_compilation_time_in_micro_sec_.load(
+               std::memory_order_relaxed) /
+           1000;
+  }
+
+  int64_t max_lazy_compilation_time_in_ms() const {
+    return max_lazy_compilation_time_in_micro_sec_.load(
+               std::memory_order_relaxed) /
+           1000;
+  }
+
+  // To avoid double-reporting, only the first instantiation should report lazy
+  // compilation performance metrics.
+  bool ShouldLazyCompilationMetricsBeReported() {
+    return should_metrics_be_reported_.exchange(false,
+                                                std::memory_order_relaxed);
+  }
 
   bool HasWireBytes() const {
     auto wire_bytes = std::atomic_load(&wire_bytes_);
@@ -1016,6 +1049,12 @@ class V8_EXPORT_PRIVATE NativeModule final {
   std::atomic<size_t> turbofan_code_size_{0};
   std::atomic<size_t> baseline_compilation_cpu_duration_{0};
   std::atomic<size_t> tier_up_cpu_duration_{0};
+
+  // Metrics for lazy compilation.
+  std::atomic<int> num_lazy_compilations_{0};
+  std::atomic<int64_t> sum_lazy_compilation_time_in_micro_sec_{0};
+  std::atomic<int64_t> max_lazy_compilation_time_in_micro_sec_{0};
+  std::atomic<bool> should_metrics_be_reported_{true};
 };
 
 class V8_EXPORT_PRIVATE WasmCodeManager final {