(Step 1 of 2): Prepping Wasm events in the Recorder interface

As part of an effort to prepare the Recorder interface for general use,
we had to make some changes to the way the existing Wasm Events are
being used. In particular,
  - it is more fitting to use a ElapsedTimer than a TimedScope to
    measure the durations in src/wasm/module-[decoder|instantiate].cc
  - we want to rename the wall_clock_time_in_us field to duration_in_us
    for clarity.

Because these Wasm events are already being instantiated in chromium,
renaming the field requires a two-step change. This is the first of
those changes.

Change-Id: If1b2990f7645616a59fc21d07ac10bf00701c0e5
Bug: v8:11109
Reviewed-on: https://chromium-review.googlesource.com/c/v8/v8/+/2518619Reviewed-by: Camillo Bruni <cbruni@chromium.org>
Reviewed-by: Ulan Degenbaev <ulan@chromium.org>
Reviewed-by: Emanuel Ziegler <ecmziegler@chromium.org>
Reviewed-by: Clemens Backes <clemensb@chromium.org>
Commit-Queue: Clemens Backes <clemensb@chromium.org>
Cr-Commit-Position: refs/heads/master@{#71053}

include/v8-metrics.h

@@ -10,6 +10,7 @@
 namespace v8 {
 namespace metrics {
 
+// TODO(sartang@microsoft.com): Remove wall_clock_time_in_us.
 struct WasmModuleDecoded {
   bool async = false;
   bool streamed = false;
@@ -17,6 +18,7 @@ struct WasmModuleDecoded {
   size_t module_size_in_bytes = 0;
   size_t function_count = 0;
   int64_t wall_clock_time_in_us = -1;
+  int64_t wall_clock_duration_in_us = -1;
 };
 
 struct WasmModuleCompiled {
@@ -29,6 +31,7 @@ struct WasmModuleCompiled {
   size_t code_size_in_bytes = 0;
   size_t liftoff_bailout_count = 0;
   int64_t wall_clock_time_in_us = -1;
+  int64_t wall_clock_duration_in_us = -1;
 };
 
 struct WasmModuleInstantiated {
@@ -36,12 +39,14 @@ struct WasmModuleInstantiated {
   bool success = false;
   size_t imported_function_count = 0;
   int64_t wall_clock_time_in_us = -1;
+  int64_t wall_clock_duration_in_us = -1;
 };
 
 struct WasmModuleTieredUp {
   bool lazy = false;
   size_t code_size_in_bytes = 0;
   int64_t wall_clock_time_in_us = -1;
+  int64_t wall_clock_duration_in_us = -1;
 };
 
 struct WasmModulesPerIsolate {

src/logging/metrics.h

@@ -85,9 +85,7 @@ template <class T, int64_t (base::TimeDelta::*precision)() const =
                        &base::TimeDelta::InMicroseconds>
 class TimedScope {
  public:
-  TimedScope(T* event, int64_t T::*time) : event_(event), time_(time) {
-    Start();
-  }
+  explicit TimedScope(T* event) : event_(event) { Start(); }
   ~TimedScope() { Stop(); }
 
   void Start() { start_time_ = base::TimeTicks::Now(); }
@@ -95,13 +93,12 @@ class TimedScope {
   void Stop() {
     if (start_time_.IsMin()) return;
     base::TimeDelta duration = base::TimeTicks::Now() - start_time_;
-    event_->*time_ = (duration.*precision)();
+    event_->wall_clock_duration_in_us = (duration.*precision)();
     start_time_ = base::TimeTicks::Min();
   }
 
  private:
   T* event_;
-  int64_t T::*time_;
   base::TimeTicks start_time_;
 };
 

src/wasm/module-compiler.cc

@@ -1450,6 +1450,7 @@ 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
@@ -1459,7 +1460,8 @@ 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_time_in_us
+          duration.InMicroseconds(),               // wall_clock_time_in_us
+          duration.InMicroseconds()                // wall_clock_duration_in_us
       };
       metrics_recorder_->DelayMainThreadEvent(event, context_id_);
     }
@@ -1470,7 +1472,8 @@ class CompilationTimeCallback {
       v8::metrics::WasmModuleTieredUp event{
           FLAG_wasm_lazy_compilation,           // lazy
           native_module->turbofan_code_size(),  // code_size_in_bytes
-          duration.InMicroseconds()             // wall_clock_time_in_us
+          duration.InMicroseconds(),            // wall_clock_time_in_us
+          duration.InMicroseconds()             // wall_clock_duration_in_us
       };
       metrics_recorder_->DelayMainThreadEvent(event, context_id_);
     }
@@ -1484,7 +1487,8 @@ 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_time_in_us
+          duration.InMicroseconds(),               // wall_clock_time_in_us
+          duration.InMicroseconds()                // wall_clock_duration_in_us
       };
       metrics_recorder_->DelayMainThreadEvent(event, context_id_);
     }
@@ -1873,7 +1877,8 @@ void AsyncCompileJob::FinishCompile(bool is_after_cache_hit) {
           !compilation_state->failed(),             // success
           native_module_->liftoff_code_size(),      // code_size_in_bytes
           native_module_->liftoff_bailout_count(),  // liftoff_bailout_count
-          duration.InMicroseconds()                 // wall_clock_time_in_us
+          duration.InMicroseconds(),                // wall_clock_time_in_us
+          duration.InMicroseconds()                 // wall_clock_duration_in_us
       };
       isolate_->metrics_recorder()->DelayMainThreadEvent(event, context_id_);
     }
@@ -2388,6 +2393,7 @@ void AsyncStreamingProcessor::FinishAsyncCompileJobWithError(
   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_->metrics_event_.wall_clock_duration_in_us = duration.InMicroseconds();
   job_->isolate_->metrics_recorder()->DelayMainThreadEvent(job_->metrics_event_,
                                                            job_->context_id_);
 
@@ -2610,6 +2616,7 @@ void AsyncStreamingProcessor::OnFinishedStream(OwnedVector<uint8_t> bytes) {
   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_->metrics_event_.wall_clock_duration_in_us = duration.InMicroseconds();
   job_->isolate_->metrics_recorder()->DelayMainThreadEvent(job_->metrics_event_,
                                                            job_->context_id_);
 

src/wasm/module-decoder.cc

@@ -2182,13 +2182,14 @@ ModuleResult DecodeWasmModule(
   // as the {module}.
   ModuleDecoderImpl decoder(enabled, module_start, module_end, origin);
   v8::metrics::WasmModuleDecoded metrics_event;
-  metrics::TimedScope<v8::metrics::WasmModuleDecoded> metrics_event_scope(
-      &metrics_event, &v8::metrics::WasmModuleDecoded::wall_clock_time_in_us);
+  base::ElapsedTimer timer;
+  timer.Start();
   ModuleResult result =
       decoder.DecodeModule(counters, allocator, verify_functions);
 
   // Record event metrics.
-  metrics_event_scope.Stop();
+  metrics_event.wall_clock_duration_in_us = timer.Elapsed().InMicroseconds();
+  timer.Stop();
   metrics_event.success = decoder.ok() && result.ok();
   metrics_event.async = decoding_method == DecodingMethod::kAsync ||
                         decoding_method == DecodingMethod::kAsyncStream;

src/wasm/module-instantiate.cc

@@ -417,10 +417,8 @@ MaybeHandle<WasmInstanceObject> InstanceBuilder::Build() {
   TimedHistogramScope wasm_instantiate_module_time_scope(SELECT_WASM_COUNTER(
       isolate_->counters(), module_->origin, wasm_instantiate, module_time));
   v8::metrics::WasmModuleInstantiated wasm_module_instantiated;
-  metrics::TimedScope<v8::metrics::WasmModuleInstantiated>
-      wasm_module_instantiated_timed_scope(
-          &wasm_module_instantiated,
-          &v8::metrics::WasmModuleInstantiated::wall_clock_time_in_us);
+  base::ElapsedTimer timer;
+  timer.Start();
   NativeModule* native_module = module_object_->native_module();
 
   //--------------------------------------------------------------------------
@@ -752,7 +750,9 @@ MaybeHandle<WasmInstanceObject> InstanceBuilder::Build() {
   TRACE("Successfully built instance for module %p\n",
         module_object_->native_module());
   wasm_module_instantiated.success = true;
-  wasm_module_instantiated_timed_scope.Stop();
+  wasm_module_instantiated.wall_clock_duration_in_us =
+      timer.Elapsed().InMicroseconds();
+  timer.Stop();
   isolate_->metrics_recorder()->DelayMainThreadEvent(wasm_module_instantiated,
                                                      context_id_);
   return instance;

test/cctest/test-api.cc

@@ -28555,7 +28555,7 @@ class MetricsRecorder : public v8::metrics::Recorder {
                           v8::metrics::Recorder::ContextId id) override {
     if (v8::metrics::Recorder::GetContext(isolate_, id).IsEmpty()) return;
     ++count_;
-    time_in_us_ = event.wall_clock_time_in_us;
+    time_in_us_ = event.wall_clock_duration_in_us;
   }
 
   void AddThreadSafeEvent(
@@ -28589,7 +28589,7 @@ TEST(TriggerMainThreadMetricsEvent) {
     // Check that event submission works.
     {
       i::metrics::TimedScope<v8::metrics::WasmModuleDecoded> timed_scope(
-          &event, &v8::metrics::WasmModuleDecoded::wall_clock_time_in_us);
+          &event);
       v8::base::OS::Sleep(v8::base::TimeDelta::FromMilliseconds(100));
     }
     i_iso->metrics_recorder()->AddMainThreadEvent(event, context_id);
@@ -28628,7 +28628,7 @@ TEST(TriggerDelayedMainThreadMetricsEvent) {
     // Check that event submission works.
     {
       i::metrics::TimedScope<v8::metrics::WasmModuleDecoded> timed_scope(
-          &event, &v8::metrics::WasmModuleDecoded::wall_clock_time_in_us);
+          &event);
       v8::base::OS::Sleep(v8::base::TimeDelta::FromMilliseconds(100));
     }
     i_iso->metrics_recorder()->DelayMainThreadEvent(event, context_id);

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

@@ -311,7 +311,7 @@ COMPILE_TEST(TestEventMetrics) {
   CHECK_EQ(buffer.size(),
            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_time_in_us);
+  CHECK_LE(0, recorder->module_decoded_.back().wall_clock_duration_in_us);
 
   CHECK_EQ(1, recorder->module_compiled_.size());
   CHECK(recorder->module_compiled_.back().success);
@@ -331,14 +331,14 @@ COMPILE_TEST(TestEventMetrics) {
   CHECK_GE(native_module->generated_code_size(),
            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_time_in_us);
+  CHECK_LE(0, recorder->module_compiled_.back().wall_clock_duration_in_us);
 
   CHECK_EQ(1, recorder->module_instantiated_.size());
   CHECK(recorder->module_instantiated_.back().success);
   // We currently don't support true async instantiation.
   CHECK(!recorder->module_instantiated_.back().async);
   CHECK_EQ(0, recorder->module_instantiated_.back().imported_function_count);
-  CHECK_LE(0, recorder->module_instantiated_.back().wall_clock_time_in_us);
+  CHECK_LE(0, recorder->module_instantiated_.back().wall_clock_duration_in_us);
 
   CHECK_EQ(1, recorder->module_tiered_up_.size());
   CHECK(!recorder->module_tiered_up_.back().lazy);
@@ -349,7 +349,7 @@ COMPILE_TEST(TestEventMetrics) {
            recorder->module_tiered_up_.back().code_size_in_bytes);
   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_time_in_us);
+  CHECK_LE(0, recorder->module_tiered_up_.back().wall_clock_duration_in_us);
 }
 
 }  // namespace wasm