From 1d3e274da92771a5239299618f60741a6fc9ace1 Mon Sep 17 00:00:00 2001 From: Emanuel Ziegler Date: Wed, 19 Aug 2020 10:10:45 +0200 Subject: [PATCH] [ukm][wasm] Add event WasmModuleCompiled & WasmModuleTieredUp Add an event for recording metrics related to compiling Wasm modules. This provides different events for both baseline compilation and tier-up. R=clemensb@chromium.org Bug: chromium:1092417 Change-Id: Ib5ea7f5ba9e91e2c34473e666eea1c6dc6a97037 Reviewed-on: https://chromium-review.googlesource.com/c/v8/v8/+/2351674 Commit-Queue: Emanuel Ziegler Reviewed-by: Clemens Backes Cr-Commit-Position: refs/heads/master@{#69470} --- src/wasm/module-compiler.cc | 93 +++++++++++++++++++++++++++++------ src/wasm/wasm-code-manager.cc | 4 ++ src/wasm/wasm-code-manager.h | 5 ++ 3 files changed, 88 insertions(+), 14 deletions(-) diff --git a/src/wasm/module-compiler.cc b/src/wasm/module-compiler.cc index b03973b64a..10c50b53b1 100644 --- a/src/wasm/module-compiler.cc +++ b/src/wasm/module-compiler.cc @@ -18,6 +18,7 @@ #include "src/compiler/wasm-compiler.h" #include "src/heap/heap-inl.h" // For CodeSpaceMemoryModificationScope. #include "src/logging/counters.h" +#include "src/logging/metrics.h" #include "src/objects/property-descriptor.h" #include "src/tasks/task-utils.h" #include "src/tracing/trace-event.h" @@ -1332,17 +1333,25 @@ bool MayCompriseLazyFunctions(const WasmModule* module, class CompilationTimeCallback { public: enum CompileMode { kSynchronous, kAsync, kStreaming }; - explicit CompilationTimeCallback(std::shared_ptr async_counters, - CompileMode compile_mode) + explicit CompilationTimeCallback( + std::shared_ptr async_counters, + std::shared_ptr metrics_recorder, + v8::metrics::Recorder::ContextId context_id, + std::weak_ptr native_module, CompileMode compile_mode) : start_time_(base::TimeTicks::Now()), async_counters_(std::move(async_counters)), + metrics_recorder_(std::move(metrics_recorder)), + context_id_(context_id), + native_module_(std::move(native_module)), compile_mode_(compile_mode) {} void operator()(CompilationEvent event) { DCHECK(base::TimeTicks::IsHighResolution()); + std::shared_ptr native_module = native_module_.lock(); + if (!native_module) return; + auto now = base::TimeTicks::Now(); + auto duration = now - start_time_; if (event == CompilationEvent::kFinishedBaselineCompilation) { - auto now = base::TimeTicks::Now(); - auto duration = now - start_time_; // Reset {start_time_} to measure tier-up time. start_time_ = now; if (compile_mode_ != kSynchronous) { @@ -1352,23 +1361,60 @@ class CompilationTimeCallback { : async_counters_->wasm_streaming_compile_wasm_module_time(); histogram->AddSample(static_cast(duration.InMicroseconds())); } + + v8::metrics::WasmModuleCompiled event{ + (compile_mode_ != kSynchronous), // async + (compile_mode_ == kStreaming), // streamed + false, // cached + false, // deserialized + FLAG_wasm_lazy_compilation, // lazy + true, // success + native_module->generated_code_size(), // code_size_in_bytes + native_module->liftoff_bailout_count(), // liftoff_bailout_count + duration.InMicroseconds() // wall_clock_time_in_us + }; + metrics_recorder_->DelayMainThreadEvent(event, context_id_); } if (event == CompilationEvent::kFinishedTopTierCompilation) { - auto duration = base::TimeTicks::Now() - start_time_; TimedHistogram* histogram = async_counters_->wasm_tier_up_module_time(); histogram->AddSample(static_cast(duration.InMicroseconds())); + + v8::metrics::WasmModuleTieredUp event{ + FLAG_wasm_lazy_compilation, // lazy + native_module->generated_code_size(), // code_size_in_bytes + duration.InMicroseconds() // wall_clock_time_in_us + }; + metrics_recorder_->DelayMainThreadEvent(event, context_id_); + } + if (event == CompilationEvent::kFailedCompilation) { + v8::metrics::WasmModuleCompiled event{ + (compile_mode_ != kSynchronous), // async + (compile_mode_ == kStreaming), // streamed + false, // cached + false, // deserialized + FLAG_wasm_lazy_compilation, // lazy + false, // success + native_module->generated_code_size(), // code_size_in_bytes + native_module->liftoff_bailout_count(), // liftoff_bailout_count + duration.InMicroseconds() // wall_clock_time_in_us + }; + metrics_recorder_->DelayMainThreadEvent(event, context_id_); } } private: base::TimeTicks start_time_; const std::shared_ptr async_counters_; + std::shared_ptr metrics_recorder_; + v8::metrics::Recorder::ContextId context_id_; + std::weak_ptr native_module_; const CompileMode compile_mode_; }; -void CompileNativeModule(Isolate* isolate, ErrorThrower* thrower, - const WasmModule* wasm_module, - NativeModule* native_module) { +void CompileNativeModule(Isolate* isolate, + v8::metrics::Recorder::ContextId context_id, + ErrorThrower* thrower, const WasmModule* wasm_module, + std::shared_ptr native_module) { CHECK(!FLAG_jitless); ModuleWireBytes wire_bytes(native_module->wire_bytes()); const bool lazy_module = IsLazyModule(wasm_module); @@ -1378,7 +1424,7 @@ void CompileNativeModule(Isolate* isolate, ErrorThrower* thrower, // Validate wasm modules for lazy compilation if requested. Never validate // asm.js modules as these are valid by construction (additionally a CHECK // will catch this during lazy compilation). - ValidateSequentially(wasm_module, native_module, isolate->counters(), + ValidateSequentially(wasm_module, native_module.get(), isolate->counters(), isolate->allocator(), thrower, lazy_module, kOnlyLazyFunctions); // On error: Return and leave the module in an unexecutable state. @@ -1391,11 +1437,12 @@ void CompileNativeModule(Isolate* isolate, ErrorThrower* thrower, auto* compilation_state = Impl(native_module->compilation_state()); if (base::TimeTicks::IsHighResolution()) { compilation_state->AddCallback(CompilationTimeCallback{ - isolate->async_counters(), CompilationTimeCallback::kSynchronous}); + isolate->async_counters(), isolate->metrics_recorder(), context_id, + native_module, CompilationTimeCallback::kSynchronous}); } // Initialize the compilation units and kick off background compile tasks. - InitializeCompilationUnits(isolate, native_module); + InitializeCompilationUnits(isolate, native_module.get()); compilation_state->WaitForBaselineFinished(); @@ -1403,7 +1450,7 @@ void CompileNativeModule(Isolate* isolate, ErrorThrower* thrower, if (compilation_state->failed()) { DCHECK_IMPLIES(lazy_module, !FLAG_wasm_lazy_validation); - ValidateSequentially(wasm_module, native_module, isolate->counters(), + ValidateSequentially(wasm_module, native_module.get(), isolate->counters(), isolate->allocator(), thrower, lazy_module); CHECK(thrower->error()); } @@ -1495,7 +1542,9 @@ std::shared_ptr CompileToNativeModule( isolate, enabled, module, code_size_estimate); native_module->SetWireBytes(std::move(wire_bytes_copy)); - CompileNativeModule(isolate, thrower, wasm_module, native_module.get()); + v8::metrics::Recorder::ContextId context_id = + isolate->GetOrRegisterRecorderContextId(isolate->native_context()); + CompileNativeModule(isolate, context_id, thrower, wasm_module, native_module); bool cache_hit = !isolate->wasm_engine()->UpdateNativeModuleCache( thrower->error(), &native_module, isolate); if (thrower->error()) return {}; @@ -1716,6 +1765,21 @@ void AsyncCompileJob::FinishCompile(bool is_after_cache_hit) { int duration_usecs = static_cast(duration.InMicroseconds()); isolate_->counters()->wasm_streaming_finish_wasm_module_time()->AddSample( duration_usecs); + + if (is_after_cache_hit || is_after_deserialization) { + v8::metrics::WasmModuleCompiled event{ + true, // async + true, // streamed + is_after_cache_hit, // cached + is_after_deserialization, // deserialized + wasm_lazy_compilation_, // lazy + !compilation_state->failed(), // success + native_module_->generated_code_size(), // code_size_in_bytes + native_module_->liftoff_bailout_count(), // liftoff_bailout_count + duration.InMicroseconds() // wall_clock_time_in_us + }; + isolate_->metrics_recorder()->DelayMainThreadEvent(event, context_id_); + } } DCHECK(!isolate_->context().is_null()); @@ -2099,7 +2163,8 @@ class AsyncCompileJob::PrepareAndStartCompile : public CompileStep { ? CompilationTimeCallback::kAsync : CompilationTimeCallback::kStreaming; compilation_state->AddCallback(CompilationTimeCallback{ - job->isolate_->async_counters(), compile_mode}); + job->isolate_->async_counters(), job->isolate_->metrics_recorder(), + job->context_id_, job->native_module_, compile_mode}); } if (start_compilation_) { diff --git a/src/wasm/wasm-code-manager.cc b/src/wasm/wasm-code-manager.cc index b7137e1a00..2f5a3f479b 100644 --- a/src/wasm/wasm-code-manager.cc +++ b/src/wasm/wasm-code-manager.cc @@ -1119,6 +1119,10 @@ WasmCode* NativeModule::PublishCodeLocked(std::unique_ptr code) { PatchJumpTablesLocked(slot_idx, code->instruction_start()); } + if (!code->for_debugging() && tiering_state_ == kTieredDown && + code->tier() == ExecutionTier::kTurbofan) { + liftoff_bailout_count_.fetch_add(1); + } } WasmCodeRefScope::AddRef(code.get()); WasmCode* result = code.get(); diff --git a/src/wasm/wasm-code-manager.h b/src/wasm/wasm-code-manager.h index 50550cf270..905449d63e 100644 --- a/src/wasm/wasm-code-manager.h +++ b/src/wasm/wasm-code-manager.h @@ -581,6 +581,10 @@ class V8_EXPORT_PRIVATE NativeModule final { size_t committed_code_space() const { return code_allocator_.committed_code_space(); } + size_t generated_code_size() const { + return code_allocator_.generated_code_size(); + } + size_t liftoff_bailout_count() const { return liftoff_bailout_count_.load(); } WasmEngine* engine() const { return engine_; } bool HasWireBytes() const { @@ -772,6 +776,7 @@ class V8_EXPORT_PRIVATE NativeModule final { int modification_scope_depth_ = 0; UseTrapHandler use_trap_handler_ = kNoTrapHandler; bool lazy_compile_frozen_ = false; + std::atomic liftoff_bailout_count_{0}; DISALLOW_COPY_AND_ASSIGN(NativeModule); };