[wasm] Add CPU time metrics

This adds CPU time metrics to the WasmModuleDecoded (except for streaming),
WasmModuleCompiled and WasmModuleTieredUp events. This can later be used
to provide this information as UKMs or UMAs.

Bug: v8:11611
Change-Id: I36818f5efbdcae2d3ed6f27c16db21f9d8440d98
Reviewed-on: https://chromium-review.googlesource.com/c/v8/v8/+/2796952Reviewed-by: Ulan Degenbaev <ulan@chromium.org>
Reviewed-by: Andreas Haas <ahaas@chromium.org>
Commit-Queue: Emanuel Ziegler <ecmziegler@chromium.org>
Cr-Commit-Position: refs/heads/master@{#73882}

include/v8-metrics.h

@@ -69,6 +69,7 @@ struct WasmModuleDecoded {
   size_t module_size_in_bytes = 0;
   size_t function_count = 0;
   int64_t wall_clock_duration_in_us = -1;
+  int64_t cpu_duration_in_us = -1;
 };
 
 struct WasmModuleCompiled {
@@ -81,6 +82,7 @@ struct WasmModuleCompiled {
   size_t code_size_in_bytes = 0;
   size_t liftoff_bailout_count = 0;
   int64_t wall_clock_duration_in_us = -1;
+  int64_t cpu_duration_in_us = -1;
 };
 
 struct WasmModuleInstantiated {
@@ -94,6 +96,7 @@ struct WasmModuleTieredUp {
   bool lazy = false;
   size_t code_size_in_bytes = 0;
   int64_t wall_clock_duration_in_us = -1;
+  int64_t cpu_duration_in_us = -1;
 };
 
 struct WasmModulesPerIsolate {

src/wasm/function-compiler.cc

@@ -4,6 +4,7 @@
 
 #include "src/wasm/function-compiler.h"
 
+#include "src/base/platform/time.h"
 #include "src/codegen/compiler.h"
 #include "src/codegen/macro-assembler-inl.h"
 #include "src/codegen/optimized-compilation-info.h"
@@ -183,6 +184,9 @@ WasmCompilationResult WasmCompilationUnit::ExecuteFunctionCompilation(
   }
 
   WasmCompilationResult result;
+  base::ThreadTicks thread_ticks = base::ThreadTicks::IsSupported()
+                                       ? base::ThreadTicks::Now()
+                                       : base::ThreadTicks();
 
   switch (tier_) {
     case ExecutionTier::kNone:
@@ -223,6 +227,11 @@ WasmCompilationResult WasmCompilationUnit::ExecuteFunctionCompilation(
       break;
   }
 
+  if (!thread_ticks.IsNull()) {
+    result.cpu_duration =
+        (base::ThreadTicks::Now() - thread_ticks).InMicroseconds();
+  }
+
   return result;
 }
 
@@ -269,6 +278,7 @@ void WasmCompilationUnit::CompileWasmFunction(Isolate* isolate,
       isolate->wasm_engine(), &env,
       native_module->compilation_state()->GetWireBytesStorage(),
       isolate->counters(), detected);
+  native_module->UpdateCPUDuration(result);
   if (result.succeeded()) {
     WasmCodeRefScope code_ref_scope;
     native_module->PublishCode(

src/wasm/function-compiler.h

@@ -75,6 +75,7 @@ struct WasmCompilationResult {
   ExecutionTier result_tier;
   Kind kind = kFunction;
   ForDebugging for_debugging = kNoDebugging;
+  size_t cpu_duration = 0;
 };
 
 class V8_EXPORT_PRIVATE WasmCompilationUnit final {

src/wasm/module-compiler.cc

@@ -1126,6 +1126,7 @@ bool CompileLazy(Isolate* isolate, Handle<WasmModuleObject> module_object,
       isolate->wasm_engine(), &env, compilation_state->GetWireBytesStorage(),
       counters, &detected_features);
   compilation_state->OnCompilationStopped(detected_features);
+  native_module->UpdateCPUDuration(result);
 
   // During lazy compilation, we can only get compilation errors when
   // {--wasm-lazy-validation} is enabled. Otherwise, the module was fully
@@ -1309,6 +1310,8 @@ CompilationExecutionResult ExecuteCompilationUnits(
       // (synchronized): Publish the compilation result and get the next unit.
       BackgroundCompileScope compile_scope(native_module);
       if (compile_scope.cancelled()) return kYield;
+      compile_scope.native_module()->UpdateCPUDuration(
+          results_to_publish.back());
 
       if (!results_to_publish.back().succeeded()) {
         compile_scope.compilation_state()->SetError();
@@ -1485,7 +1488,6 @@ class CompilationTimeCallback {
         histogram->AddSample(static_cast<int>(duration.InMicroseconds()));
       }
 
-      // TODO(sartang@microsoft.com): Remove wall_clock_time_in_us field
       v8::metrics::WasmModuleCompiled event{
           (compile_mode_ != kSynchronous),         // async
           (compile_mode_ == kStreaming),           // streamed
@@ -1495,8 +1497,10 @@ class CompilationTimeCallback {
           true,                                    // success
           native_module->liftoff_code_size(),      // code_size_in_bytes
           native_module->liftoff_bailout_count(),  // liftoff_bailout_count
-          duration.InMicroseconds()                // wall_clock_duration_in_us
-      };
+          duration.InMicroseconds(),               // wall_clock_duration_in_us
+          FLAG_liftoff                             // cpu_time_duration_in_us
+              ? native_module->liftoff_cpu_duration()
+              : native_module->turbofan_cpu_duration()};
       metrics_recorder_->DelayMainThreadEvent(event, context_id_);
     }
     if (event == CompilationEvent::kFinishedTopTierCompilation) {
@@ -1504,9 +1508,10 @@ class CompilationTimeCallback {
       histogram->AddSample(static_cast<int>(duration.InMicroseconds()));
 
       v8::metrics::WasmModuleTieredUp event{
-          FLAG_wasm_lazy_compilation,           // lazy
-          native_module->turbofan_code_size(),  // code_size_in_bytes
-          duration.InMicroseconds()             // wall_clock_duration_in_us
+          FLAG_wasm_lazy_compilation,             // lazy
+          native_module->turbofan_code_size(),    // code_size_in_bytes
+          duration.InMicroseconds(),              // wall_clock_duration_in_us
+          native_module->turbofan_cpu_duration()  // cpu_time_duration_in_us
       };
       metrics_recorder_->DelayMainThreadEvent(event, context_id_);
     }
@@ -1520,8 +1525,10 @@ class CompilationTimeCallback {
           false,                                   // success
           native_module->liftoff_code_size(),      // code_size_in_bytes
           native_module->liftoff_bailout_count(),  // liftoff_bailout_count
-          duration.InMicroseconds()                // wall_clock_duration_in_us
-      };
+          duration.InMicroseconds(),               // wall_clock_duration_in_us
+          FLAG_liftoff                             // cpu_time_duration_in_us
+              ? native_module->liftoff_cpu_duration()
+              : native_module->turbofan_cpu_duration()};
       metrics_recorder_->DelayMainThreadEvent(event, context_id_);
     }
   }
@@ -1919,10 +1926,12 @@ void AsyncCompileJob::FinishCompile(bool is_after_cache_hit) {
           is_after_deserialization,                 // deserialized
           wasm_lazy_compilation_,                   // lazy
           !compilation_state->failed(),             // success
-          native_module_->liftoff_code_size(),      // code_size_in_bytes
+          native_module_->turbofan_code_size(),     // code_size_in_bytes
           native_module_->liftoff_bailout_count(),  // liftoff_bailout_count
-          duration.InMicroseconds()                 // wall_clock_duration_in_us
-      };
+          duration.InMicroseconds(),                // wall_clock_duration_in_us
+          FLAG_liftoff                              // cpu_time_duration_in_us
+              ? native_module_->liftoff_cpu_duration()
+              : native_module_->turbofan_cpu_duration()};
       isolate_->metrics_recorder()->DelayMainThreadEvent(event, context_id_);
     }
   }

src/wasm/module-decoder.cc

@@ -2143,12 +2143,19 @@ ModuleResult DecodeWasmModule(
   v8::metrics::WasmModuleDecoded metrics_event;
   base::ElapsedTimer timer;
   timer.Start();
+  base::ThreadTicks thread_ticks = base::ThreadTicks::IsSupported()
+                                       ? base::ThreadTicks::Now()
+                                       : base::ThreadTicks();
   ModuleResult result =
       decoder.DecodeModule(counters, allocator, verify_functions);
 
   // Record event metrics.
   metrics_event.wall_clock_duration_in_us = timer.Elapsed().InMicroseconds();
   timer.Stop();
+  if (!thread_ticks.IsNull()) {
+    metrics_event.cpu_duration_in_us =
+        (base::ThreadTicks::Now() - thread_ticks).InMicroseconds();
+  }
   metrics_event.success = decoder.ok() && result.ok();
   metrics_event.async = decoding_method == DecodingMethod::kAsync ||
                         decoding_method == DecodingMethod::kAsyncStream;

src/wasm/wasm-code-manager.cc

@@ -1498,6 +1498,21 @@ void NativeModule::SetWireBytes(OwnedVector<const uint8_t> wire_bytes) {
   }
 }
 
+void NativeModule::UpdateCPUDuration(WasmCompilationResult& result) {
+  if (result.for_debugging != ForDebugging::kNoDebugging) return;
+  DCHECK_NE(std::numeric_limits<size_t>::max(), result.cpu_duration);
+  if (result.requested_tier == ExecutionTier::kLiftoff) {
+    liftoff_cpu_duration_.fetch_add(result.cpu_duration,
+                                    std::memory_order::memory_order_relaxed);
+  } else if (result.requested_tier == ExecutionTier::kTurbofan) {
+    turbofan_cpu_duration_.fetch_add(result.cpu_duration,
+                                     std::memory_order::memory_order_relaxed);
+  }
+#ifdef DEBUG
+  result.cpu_duration = std::numeric_limits<size_t>::max();
+#endif
+}
+
 void NativeModule::TransferNewOwnedCodeLocked() const {
   // The caller holds the allocation mutex.
   DCHECK(!allocation_mutex_.TryLock());

src/wasm/wasm-code-manager.h

@@ -631,6 +631,8 @@ class V8_EXPORT_PRIVATE NativeModule final {
   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_cpu_duration() const { return liftoff_cpu_duration_.load(); }
+  size_t turbofan_cpu_duration() const { return turbofan_cpu_duration_.load(); }
   WasmEngine* engine() const { return engine_; }
 
   bool HasWireBytes() const {
@@ -639,6 +641,8 @@ class V8_EXPORT_PRIVATE NativeModule final {
   }
   void SetWireBytes(OwnedVector<const uint8_t> wire_bytes);
 
+  void UpdateCPUDuration(WasmCompilationResult& result);
+
   WasmCode* Lookup(Address) const;
 
   WasmImportWrapperCache* import_wrapper_cache() const {
@@ -853,6 +857,8 @@ class V8_EXPORT_PRIVATE NativeModule final {
   std::atomic<size_t> liftoff_bailout_count_{0};
   std::atomic<size_t> liftoff_code_size_{0};
   std::atomic<size_t> turbofan_code_size_{0};
+  std::atomic<size_t> liftoff_cpu_duration_{0};
+  std::atomic<size_t> turbofan_cpu_duration_{0};
 };
 
 class V8_EXPORT_PRIVATE WasmCodeManager final {

test/cctest/wasm/test-wasm-metrics.cc

@@ -7,6 +7,7 @@
 #include "include/libplatform/libplatform.h"
 #include "include/v8-metrics.h"
 #include "src/api/api-inl.h"
+#include "src/base/platform/time.h"
 #include "src/wasm/wasm-engine.h"
 #include "src/wasm/wasm-module-builder.h"
 #include "test/cctest/cctest.h"
@@ -271,6 +272,9 @@ COMPILE_TEST(TestEventMetrics) {
   std::shared_ptr<MetricsRecorder> recorder =
       std::make_shared<MetricsRecorder>();
   reinterpret_cast<v8::Isolate*>(isolate)->SetMetricsRecorder(recorder);
+  if (v8::base::ThreadTicks::IsSupported()) {
+    v8::base::ThreadTicks::WaitUntilInitialized();
+  }
 
   TestSignatures sigs;
   v8::internal::AccountingAllocator allocator;
@@ -313,6 +317,8 @@ COMPILE_TEST(TestEventMetrics) {
            recorder->module_decoded_.back().module_size_in_bytes);
   CHECK_EQ(1, recorder->module_decoded_.back().function_count);
   CHECK_LE(0, recorder->module_decoded_.back().wall_clock_duration_in_us);
+  CHECK_IMPLIES(v8::base::ThreadTicks::IsSupported(),
+                recorder->module_decoded_.back().wall_clock_duration_in_us > 0);
 
   CHECK_EQ(1, recorder->module_compiled_.size());
   CHECK(recorder->module_compiled_.back().success);
@@ -333,6 +339,12 @@ COMPILE_TEST(TestEventMetrics) {
            recorder->module_compiled_.back().code_size_in_bytes);
   CHECK_EQ(0, recorder->module_compiled_.back().liftoff_bailout_count);
   CHECK_LE(0, recorder->module_compiled_.back().wall_clock_duration_in_us);
+  CHECK_EQ(i::FLAG_liftoff ? native_module->liftoff_cpu_duration()
+                           : native_module->turbofan_cpu_duration(),
+           recorder->module_compiled_.back().cpu_duration_in_us);
+  CHECK_IMPLIES(
+      v8::base::ThreadTicks::IsSupported() && !i::FLAG_wasm_test_streaming,
+      recorder->module_compiled_.back().cpu_duration_in_us > 0);
 
   CHECK_EQ(1, recorder->module_instantiated_.size());
   CHECK(recorder->module_instantiated_.back().success);
@@ -351,6 +363,10 @@ COMPILE_TEST(TestEventMetrics) {
   CHECK_GE(native_module->committed_code_space(),
            recorder->module_tiered_up_.back().code_size_in_bytes);
   CHECK_LE(0, recorder->module_tiered_up_.back().wall_clock_duration_in_us);
+  CHECK_EQ(native_module->turbofan_cpu_duration(),
+           recorder->module_tiered_up_.back().cpu_duration_in_us);
+  CHECK_IMPLIES(v8::base::ThreadTicks::IsSupported() && i::FLAG_wasm_tier_up,
+                recorder->module_tiered_up_.back().cpu_duration_in_us > 0);
 }
 
 }  // namespace wasm

test/cctest/wasm/wasm-run-utils.cc

@@ -558,6 +558,7 @@ void WasmFunctionCompiler::Build(const byte* start, const byte* end) {
       isolate()->counters(), &unused_detected_features);
   WasmCode* code = native_module->PublishCode(
       native_module->AddCompiledCode(std::move(result)));
+  native_module->UpdateCPUDuration(result);
   DCHECK_NOT_NULL(code);
   DisallowGarbageCollection no_gc;
   Script script = builder_->instance_object()->module_object().script();