[wasm][ukm] Add tests for Wasm events (reland)

Ensure that events are triggered when a module is decoded, compiled,
instantiated and tiered-up.

This is a reland of Ib5883a338c3756c6f3488fbdd7b6861ecc2ba218.

R=clemensb@chromium.org
TBR=adamk@chromium.org

Bug: chromium:1092417
Change-Id: I803ae3db23a5f71f26e8ec118251eccdfc551353
Cq-Include-Trybots: luci.v8.try:v8_linux64_tsan_rel_ng
Cq-Include-Trybots: luci.v8.try:v8_linux64_tsan_isolates_rel_ng
Reviewed-on: https://chromium-review.googlesource.com/c/v8/v8/+/2425056
Commit-Queue: Emanuel Ziegler <ecmziegler@chromium.org>
Reviewed-by: Clemens Backes <clemensb@chromium.org>
Cr-Commit-Position: refs/heads/master@{#70113}

include/v8-metrics.h

@@ -16,7 +16,7 @@ struct WasmModuleDecoded {
   bool success = false;
   size_t module_size_in_bytes = 0;
   size_t function_count = 0;
-  int64_t wall_clock_time_in_us = 0;
+  int64_t wall_clock_time_in_us = -1;
 };
 
 struct WasmModuleCompiled {
@@ -28,20 +28,20 @@ struct WasmModuleCompiled {
   bool success = false;
   size_t code_size_in_bytes = 0;
   size_t liftoff_bailout_count = 0;
-  int64_t wall_clock_time_in_us = 0;
+  int64_t wall_clock_time_in_us = -1;
 };
 
 struct WasmModuleInstantiated {
   bool async = false;
   bool success = false;
   size_t imported_function_count = 0;
-  int64_t wall_clock_time_in_us = 0;
+  int64_t wall_clock_time_in_us = -1;
 };
 
 struct WasmModuleTieredUp {
   bool lazy = false;
   size_t code_size_in_bytes = 0;
-  int64_t wall_clock_time_in_us = 0;
+  int64_t wall_clock_time_in_us = -1;
 };
 
 struct WasmModulesPerIsolate {

src/wasm/module-compiler.cc

@@ -1527,7 +1527,7 @@ class CompilationTimeCallback {
           false,                                   // deserialized
           FLAG_wasm_lazy_compilation,              // lazy
           true,                                    // success
-          native_module->generated_code_size(),    // code_size_in_bytes
+          native_module->liftoff_code_size(),      // code_size_in_bytes
           native_module->liftoff_bailout_count(),  // liftoff_bailout_count
           duration.InMicroseconds()                // wall_clock_time_in_us
       };
@@ -1539,7 +1539,7 @@ class CompilationTimeCallback {
 
       v8::metrics::WasmModuleTieredUp event{
           FLAG_wasm_lazy_compilation,           // lazy
-          native_module->generated_code_size(),  // code_size_in_bytes
+          native_module->turbofan_code_size(),  // code_size_in_bytes
           duration.InMicroseconds()             // wall_clock_time_in_us
       };
       metrics_recorder_->DelayMainThreadEvent(event, context_id_);
@@ -1552,7 +1552,7 @@ class CompilationTimeCallback {
           false,                                   // deserialized
           FLAG_wasm_lazy_compilation,              // lazy
           false,                                   // success
-          native_module->generated_code_size(),    // code_size_in_bytes
+          native_module->liftoff_code_size(),      // code_size_in_bytes
           native_module->liftoff_bailout_count(),  // liftoff_bailout_count
           duration.InMicroseconds()                // wall_clock_time_in_us
       };
@@ -1792,6 +1792,7 @@ AsyncCompileJob::AsyncCompileJob(
       isolate->global_handles()->Create(context->native_context());
   DCHECK(native_context_->IsNativeContext());
   context_id_ = isolate->GetOrRegisterRecorderContextId(native_context_);
+  metrics_event_.async = true;
 }
 
 void AsyncCompileJob::Start() {
@@ -1958,7 +1959,7 @@ void AsyncCompileJob::FinishCompile(bool is_after_cache_hit) {
           is_after_deserialization,                 // deserialized
           wasm_lazy_compilation_,                   // lazy
           !compilation_state->failed(),             // success
-          native_module_->generated_code_size(),    // code_size_in_bytes
+          native_module_->liftoff_code_size(),      // code_size_in_bytes
           native_module_->liftoff_bailout_count(),  // liftoff_bailout_count
           duration.InMicroseconds()                 // wall_clock_time_in_us
       };
@@ -2463,6 +2464,16 @@ void AsyncStreamingProcessor::FinishAsyncCompileJobWithError(
   // of the AsyncCompileJob to DecodeFail.
   job_->background_task_manager_.CancelAndWait();
 
+  // Record event metrics.
+  auto duration = base::TimeTicks::Now() - job_->start_time_;
+  job_->metrics_event_.success = false;
+  job_->metrics_event_.streamed = true;
+  job_->metrics_event_.module_size_in_bytes = job_->wire_bytes_.length();
+  job_->metrics_event_.function_count = num_functions_;
+  job_->metrics_event_.wall_clock_time_in_us = duration.InMicroseconds();
+  job_->isolate_->metrics_recorder()->DelayMainThreadEvent(job_->metrics_event_,
+                                                           job_->context_id_);
+
   // Check if there is already a CompiledModule, in which case we have to clean
   // up the CompilationStateImpl as well.
   if (job_->native_module_) {
@@ -2674,6 +2685,16 @@ void AsyncStreamingProcessor::OnFinishedStream(OwnedVector<uint8_t> bytes) {
   job_->wire_bytes_ = ModuleWireBytes(bytes.as_vector());
   job_->bytes_copy_ = bytes.ReleaseData();
 
+  // Record event metrics.
+  auto duration = base::TimeTicks::Now() - job_->start_time_;
+  job_->metrics_event_.success = true;
+  job_->metrics_event_.streamed = true;
+  job_->metrics_event_.module_size_in_bytes = job_->wire_bytes_.length();
+  job_->metrics_event_.function_count = num_functions_;
+  job_->metrics_event_.wall_clock_time_in_us = duration.InMicroseconds();
+  job_->isolate_->metrics_recorder()->DelayMainThreadEvent(job_->metrics_event_,
+                                                           job_->context_id_);
+
   if (prefix_cache_hit_) {
     // Restart as an asynchronous, non-streaming compilation. Most likely
     // {PrepareAndStartCompile} will get the native module from the cache.

src/wasm/module-compiler.h

@@ -9,9 +9,9 @@
 #include <functional>
 #include <memory>
 
-#include "include/v8-metrics.h"
 #include "src/base/optional.h"
 #include "src/common/globals.h"
+#include "src/logging/metrics.h"
 #include "src/tasks/cancelable-task.h"
 #include "src/wasm/compilation-environment.h"
 #include "src/wasm/wasm-features.h"
@@ -213,6 +213,7 @@ class AsyncCompileJob {
   ModuleWireBytes wire_bytes_;
   Handle<NativeContext> native_context_;
   v8::metrics::Recorder::ContextId context_id_;
+  v8::metrics::WasmModuleDecoded metrics_event_;
   const std::shared_ptr<CompilationResultResolver> resolver_;
 
   Handle<WasmModuleObject> module_object_;

src/wasm/module-decoder.cc

@@ -266,27 +266,6 @@ class WasmSectionIterator {
   }
 };
 
-class AutoSubmitMetrics : public v8::metrics::WasmModuleDecoded {
- public:
-  AutoSubmitMetrics(std::shared_ptr<metrics::Recorder> recorder,
-                    v8::metrics::Recorder::ContextId context_id)
-      : recorder_(std::move(recorder)),
-        context_id_(context_id),
-        timed_scope_(this,
-                     &v8::metrics::WasmModuleDecoded::wall_clock_time_in_us) {}
-
-  ~AutoSubmitMetrics() {
-    timed_scope_.Stop();
-    recorder_->DelayMainThreadEvent<v8::metrics::WasmModuleDecoded>(
-        *this, context_id_);
-  }
-
- private:
-  std::shared_ptr<metrics::Recorder> recorder_;
-  v8::metrics::Recorder::ContextId context_id_;
-  metrics::TimedScope<v8::metrics::WasmModuleDecoded> timed_scope_;
-};
-
 }  // namespace
 
 // The main logic for decoding the bytes of a module.
@@ -301,13 +280,13 @@ class ModuleDecoderImpl : public Decoder {
                     const byte* module_end, ModuleOrigin origin)
       : Decoder(module_start, module_end),
         enabled_features_(enabled),
+        module_start_(module_start),
+        module_end_(module_end),
         origin_(origin) {
     if (end_ < start_) {
       error(start_, "end is less than start");
       end_ = start_;
     }
-    module_start_ = module_start;
-    module_end_ = module_end;
   }
 
   void onFirstError() override {
@@ -1225,13 +1204,6 @@ class ModuleDecoderImpl : public Decoder {
       CalculateGlobalOffsets(module_.get());
     }
 
-    if (metrics_) {
-      metrics_->success = ok() && !intermediate_error_.has_error();
-      metrics_->module_size_in_bytes = end() - start();
-      metrics_->function_count = module_->num_declared_functions;
-      metrics_.reset();
-    }
-
     ModuleResult result = toResult(std::move(module_));
     if (verify_functions && result.ok() && intermediate_error_.has_error()) {
       // Copy error message and location.
@@ -1275,13 +1247,6 @@ class ModuleDecoderImpl : public Decoder {
     if (FLAG_dump_wasm_module) DumpModule(orig_bytes);
 
     if (decoder.failed()) {
-      if (metrics_) {
-        metrics_->success = false;
-        metrics_->module_size_in_bytes = orig_bytes.length();
-        metrics_->function_count = module_->num_declared_functions;
-        metrics_.reset();
-      }
-
       return decoder.toResult<std::unique_ptr<WasmModule>>(nullptr);
     }
 
@@ -1335,37 +1300,11 @@ class ModuleDecoderImpl : public Decoder {
     counters_ = counters;
   }
 
-  void EnableMetricsRecording(
-      std::shared_ptr<metrics::Recorder> metrics_recorder,
-      v8::metrics::Recorder::ContextId context_id,
-      DecodingMethod decoding_method) {
-    metrics_ = std::make_unique<AutoSubmitMetrics>(std::move(metrics_recorder),
-                                                   context_id);
-    switch (decoding_method) {
-      case DecodingMethod::kSync:
-        break;
-      case DecodingMethod::kAsync:
-        metrics_->async = true;
-        break;
-      case DecodingMethod::kSyncStream:
-        metrics_->streamed = true;
-        break;
-      case DecodingMethod::kAsyncStream:
-        metrics_->async = true;
-        metrics_->streamed = true;
-        break;
-      case DecodingMethod::kDeserialize:
-        // TODO(ecmziegler): verify if we need to add a deserialized metric flag
-        // in the next UKM update.
-        break;
-    }
-  }
-
  private:
   const WasmFeatures enabled_features_;
   std::shared_ptr<WasmModule> module_;
-  const byte* module_start_;
-  const byte* module_end_;
+  const byte* module_start_ = nullptr;
+  const byte* module_end_ = nullptr;
   Counters* counters_ = nullptr;
   // The type section is the first section in a module.
   uint8_t next_ordered_section_ = kFirstSectionInModule;
@@ -1386,7 +1325,6 @@ class ModuleDecoderImpl : public Decoder {
   // reporting once the whole type section is parsed.
   std::unordered_map<uint32_t, int> deferred_check_type_index_;
   ModuleOrigin origin_;
-  std::unique_ptr<AutoSubmitMetrics> metrics_;
 
   ValueType TypeOf(const WasmInitExpr& expr) {
     switch (expr.kind()) {
@@ -2240,9 +2178,28 @@ ModuleResult DecodeWasmModule(
   // Signatures are stored in zone memory, which have the same lifetime
   // as the {module}.
   ModuleDecoderImpl decoder(enabled, module_start, module_end, origin);
-  decoder.EnableMetricsRecording(std::move(metrics_recorder), context_id,
-                                 decoding_method);
-  return decoder.DecodeModule(counters, allocator, verify_functions);
+  v8::metrics::WasmModuleDecoded metrics_event;
+  metrics::TimedScope<v8::metrics::WasmModuleDecoded> metrics_event_scope(
+      &metrics_event, &v8::metrics::WasmModuleDecoded::wall_clock_time_in_us);
+  ModuleResult result =
+      decoder.DecodeModule(counters, allocator, verify_functions);
+
+  // Record event metrics.
+  metrics_event_scope.Stop();
+  metrics_event.success = decoder.ok() && result.ok();
+  metrics_event.async = decoding_method == DecodingMethod::kAsync ||
+                        decoding_method == DecodingMethod::kAsyncStream;
+  metrics_event.streamed = decoding_method == DecodingMethod::kSyncStream ||
+                           decoding_method == DecodingMethod::kAsyncStream;
+  if (result.ok()) {
+    metrics_event.function_count = result.value()->num_declared_functions;
+  } else if (auto&& module = decoder.shared_module()) {
+    metrics_event.function_count = module->num_declared_functions;
+  }
+  metrics_event.module_size_in_bytes = size;
+  metrics_recorder->DelayMainThreadEvent(metrics_event, context_id);
+
+  return result;
 }
 
 ModuleDecoder::ModuleDecoder(const WasmFeatures& enabled)
@@ -2260,8 +2217,6 @@ void ModuleDecoder::StartDecoding(
     ModuleOrigin origin) {
   DCHECK_NULL(impl_);
   impl_.reset(new ModuleDecoderImpl(enabled_features_, origin));
-  impl_->EnableMetricsRecording(std::move(metrics_recorder), context_id,
-                                DecodingMethod::kAsyncStream);
   impl_->StartDecoding(counters, allocator);
 }
 

src/wasm/wasm-code-manager.cc

@@ -1020,6 +1020,7 @@ std::unique_ptr<WasmCode> NativeModule::AddCodeWithCodeSpace(
     Vector<uint8_t> dst_code_bytes, const JumpTablesRef& jump_tables) {
   Vector<byte> reloc_info{desc.buffer + desc.buffer_size - desc.reloc_size,
                           static_cast<size_t>(desc.reloc_size)};
+  UpdateCodeSize(desc.instr_size, tier, for_debugging);
 
   // TODO(jgruber,v8:8758): Remove this translation. It exists only because
   // CodeDesc contains real offsets but WasmCode expects an offset of 0 to mean
@@ -1174,6 +1175,7 @@ WasmCode* NativeModule::AddDeserializedCode(
   // CodeSpaceWriteScope is provided by the caller.
   Vector<uint8_t> dst_code_bytes =
       code_allocator_.AllocateForCode(this, instructions.size());
+  UpdateCodeSize(dst_code_bytes.size(), tier, kNoDebugging);
   memcpy(dst_code_bytes.begin(), instructions.begin(), instructions.size());
 
   std::unique_ptr<WasmCode> code{new WasmCode{
@@ -1230,6 +1232,7 @@ WasmCode* NativeModule::CreateEmptyJumpTableInRegion(
   Vector<uint8_t> code_space = code_allocator_.AllocateForCodeInRegion(
       this, jump_table_size, region, allocator_lock);
   DCHECK(!code_space.empty());
+  UpdateCodeSize(jump_table_size, ExecutionTier::kNone, kNoDebugging);
   CODE_SPACE_WRITE_SCOPE
   ZapCode(reinterpret_cast<Address>(code_space.begin()), code_space.size());
   std::unique_ptr<WasmCode> code{
@@ -1252,6 +1255,15 @@ WasmCode* NativeModule::CreateEmptyJumpTableInRegion(
   return PublishCode(std::move(code));
 }
 
+void NativeModule::UpdateCodeSize(size_t size, ExecutionTier tier,
+                                  ForDebugging for_debugging) {
+  if (for_debugging != kNoDebugging) return;
+  // Count jump tables (ExecutionTier::kNone) for both Liftoff and TurboFan as
+  // this is shared code.
+  if (tier != ExecutionTier::kTurbofan) liftoff_code_size_.fetch_add(size);
+  if (tier != ExecutionTier::kLiftoff) turbofan_code_size_.fetch_add(size);
+}
+
 void NativeModule::PatchJumpTablesLocked(uint32_t slot_index, Address target) {
   // The caller must hold the {allocation_mutex_}, thus we fail to lock it here.
   DCHECK(!allocation_mutex_.TryLock());

src/wasm/wasm-code-manager.h

@@ -596,6 +596,8 @@ class V8_EXPORT_PRIVATE NativeModule final {
     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(); }
   WasmEngine* engine() const { return engine_; }
 
   bool HasWireBytes() const {
@@ -697,6 +699,8 @@ class V8_EXPORT_PRIVATE NativeModule final {
       int jump_table_size, base::AddressRegion,
       const WasmCodeAllocator::OptionalLock&);
 
+  void UpdateCodeSize(size_t, ExecutionTier, ForDebugging);
+
   // Hold the {allocation_mutex_} when calling one of these methods.
   // {slot_index} is the index in the declared functions, i.e. function index
   // minus the number of imported functions.
@@ -788,6 +792,8 @@ class V8_EXPORT_PRIVATE NativeModule final {
   UseTrapHandler use_trap_handler_ = kNoTrapHandler;
   bool lazy_compile_frozen_ = false;
   std::atomic<size_t> liftoff_bailout_count_{0};
+  std::atomic<size_t> liftoff_code_size_{0};
+  std::atomic<size_t> turbofan_code_size_{0};
 
   DISALLOW_COPY_AND_ASSIGN(NativeModule);
 };

test/cctest/BUILD.gn

@@ -309,6 +309,7 @@ v8_source_set("cctest_sources") {
     "wasm/test-wasm-debug-evaluate.cc",
     "wasm/test-wasm-debug-evaluate.h",
     "wasm/test-wasm-import-wrapper-cache.cc",
+    "wasm/test-wasm-metrics.cc",
     "wasm/test-wasm-serialization.cc",
     "wasm/test-wasm-shared-engine.cc",
     "wasm/test-wasm-stack.cc",

test/cctest/cctest.status

@@ -522,6 +522,7 @@
   'test-wasm-codegen/*': [SKIP],
   'test-wasm-debug-evaluate/*': [SKIP],
   'test-wasm-import-wrapper-cache/*': [SKIP],
+  'test-wasm-metrics/*': [SKIP],
   'test-wasm-serialization/*': [SKIP],
   'test-wasm-shared-engine/*': [SKIP],
   'test-wasm-stack/*': [SKIP],