[wasm] Pass the script ID to code logging

We didn't pass a script ID with the code creation events for profiling.
This made DevTools lose the connection to the wasm script, hence
jumping from the profiler entry to the source did not work.

This CL changes the timing of code logging a bit such that the script is
always allocated before logging. In the queue of code to be logged we
then also store the script ID, and finally set it on the {CodeEntry}
object.

R=thibaudm@chromium.org

Bug: chromium:1125986
Change-Id: I2248c1d520bc819436bbe732373f7a3446b64f48
Reviewed-on: https://chromium-review.googlesource.com/c/v8/v8/+/2575057
Commit-Queue: Clemens Backes <clemensb@chromium.org>
Reviewed-by: Peter Marshall <petermarshall@chromium.org>
Reviewed-by: Thibaud Michaud <thibaudm@chromium.org>
Cr-Commit-Position: refs/heads/master@{#71654}

src/logging/code-events.h

@@ -84,7 +84,7 @@ class CodeEventListener {
                                Handle<Name> script_name, int line,
                                int column) = 0;
   virtual void CodeCreateEvent(LogEventsAndTags tag, const wasm::WasmCode* code,
-                               wasm::WasmName name) = 0;
+                               wasm::WasmName name, int script_id) = 0;
 
   virtual void CallbackEvent(Handle<Name> name, Address entry_point) = 0;
   virtual void GetterCallbackEvent(Handle<Name> name, Address entry_point) = 0;
@@ -170,9 +170,9 @@ class CodeEventDispatcher : public CodeEventListener {
     });
   }
   void CodeCreateEvent(LogEventsAndTags tag, const wasm::WasmCode* code,
-                       wasm::WasmName name) override {
+                       wasm::WasmName name, int script_id) override {
     DispatchEventToListeners([=](CodeEventListener* listener) {
-      listener->CodeCreateEvent(tag, code, name);
+      listener->CodeCreateEvent(tag, code, name, script_id);
     });
   }
   void CallbackEvent(Handle<Name> name, Address entry_point) override {

src/logging/log.cc

@@ -239,7 +239,8 @@ void CodeEventLogger::CodeCreateEvent(LogEventsAndTags tag,
 
 void CodeEventLogger::CodeCreateEvent(LogEventsAndTags tag,
                                       const wasm::WasmCode* code,
-                                      wasm::WasmName name) {
+                                      wasm::WasmName name,
+                                      int /* script_id */) {
   name_buffer_->Init(tag);
   DCHECK(!name.empty());
   name_buffer_->AppendBytes(name.begin(), name.length());
@@ -465,7 +466,8 @@ void ExternalCodeEventListener::CodeCreateEvent(
 
 void ExternalCodeEventListener::CodeCreateEvent(LogEventsAndTags tag,
                                                 const wasm::WasmCode* code,
-                                                wasm::WasmName name) {
+                                                wasm::WasmName name,
+                                                int script_id) {
   // TODO(mmarchini): handle later
 }
 
@@ -1360,7 +1362,7 @@ void Logger::CodeCreateEvent(LogEventsAndTags tag, Handle<AbstractCode> code,
 }
 
 void Logger::CodeCreateEvent(LogEventsAndTags tag, const wasm::WasmCode* code,
-                             wasm::WasmName name) {
+                             wasm::WasmName name, int /* script_id */) {
   if (!is_listening_to_code_events()) return;
   if (!FLAG_log_code) return;
   MSG_BUILDER();
@@ -2192,7 +2194,8 @@ void ExistingCodeLogger::LogCompiledFunctions() {
   const std::vector<Handle<WasmModuleObject>> wasm_module_objects =
       EnumerateWasmModuleObjects(heap);
   for (auto& module_object : wasm_module_objects) {
-    module_object->native_module()->LogWasmCodes(isolate_);
+    int script_id = module_object->script().id();
+    module_object->native_module()->LogWasmCodes(isolate_, script_id);
   }
 }
 

src/logging/log.h

@@ -201,7 +201,7 @@ class Logger : public CodeEventListener {
                        Handle<SharedFunctionInfo> shared,
                        Handle<Name> script_name, int line, int column) override;
   void CodeCreateEvent(LogEventsAndTags tag, const wasm::WasmCode* code,
-                       wasm::WasmName name) override;
+                       wasm::WasmName name, int script_id) override;
 
   void CallbackEvent(Handle<Name> name, Address entry_point) override;
   void GetterCallbackEvent(Handle<Name> name, Address entry_point) override;
@@ -403,7 +403,7 @@ class V8_EXPORT_PRIVATE CodeEventLogger : public CodeEventListener {
                        Handle<SharedFunctionInfo> shared,
                        Handle<Name> script_name, int line, int column) override;
   void CodeCreateEvent(LogEventsAndTags tag, const wasm::WasmCode* code,
-                       wasm::WasmName name) override;
+                       wasm::WasmName name, int script_id) override;
 
   void RegExpCodeCreateEvent(Handle<AbstractCode> code,
                              Handle<String> source) override;
@@ -462,7 +462,7 @@ class ExternalCodeEventListener : public CodeEventListener {
                        Handle<SharedFunctionInfo> shared, Handle<Name> source,
                        int line, int column) override;
   void CodeCreateEvent(LogEventsAndTags tag, const wasm::WasmCode* code,
-                       wasm::WasmName name) override;
+                       wasm::WasmName name, int script_id) override;
 
   void RegExpCodeCreateEvent(Handle<AbstractCode> code,
                              Handle<String> source) override;

src/profiler/profiler-listener.cc

@@ -193,7 +193,7 @@ void ProfilerListener::CodeCreateEvent(LogEventsAndTags tag,
 
 void ProfilerListener::CodeCreateEvent(LogEventsAndTags tag,
                                        const wasm::WasmCode* code,
-                                       wasm::WasmName name) {
+                                       wasm::WasmName name, int script_id) {
   CodeEventsContainer evt_rec(CodeEventRecord::CODE_CREATION);
   CodeCreateEventRecord* rec = &evt_rec.CodeCreateEventRecord_;
   rec->instruction_start = code->instruction_start();
@@ -201,6 +201,7 @@ void ProfilerListener::CodeCreateEvent(LogEventsAndTags tag,
       new CodeEntry(tag, GetName(name), CodeEntry::kWasmResourceNamePrefix,
                     CpuProfileNode::kNoLineNumberInfo,
                     CpuProfileNode::kNoColumnNumberInfo, nullptr, true);
+  rec->entry->set_script_id(script_id);
   rec->instruction_size = code->instructions().length();
   DispatchCodeEvent(evt_rec);
 }

src/profiler/profiler-listener.h

@@ -43,7 +43,7 @@ class V8_EXPORT_PRIVATE ProfilerListener : public CodeEventListener {
                        Handle<SharedFunctionInfo> shared,
                        Handle<Name> script_name, int line, int column) override;
   void CodeCreateEvent(LogEventsAndTags tag, const wasm::WasmCode* code,
-                       wasm::WasmName name) override;
+                       wasm::WasmName name, int script_id) override;
 
   void CallbackEvent(Handle<Name> name, Address entry_point) override;
   void GetterCallbackEvent(Handle<Name> name, Address entry_point) override;

src/runtime/runtime-test.cc

@@ -1623,7 +1623,7 @@ RUNTIME_FUNCTION(Runtime_EnableCodeLoggingForTesting) {
                          Handle<Name> script_name, int line, int column) final {
     }
     void CodeCreateEvent(LogEventsAndTags tag, const wasm::WasmCode* code,
-                         wasm::WasmName name) final {}
+                         wasm::WasmName name, int script_id) final {}
 
     void CallbackEvent(Handle<Name> name, Address entry_point) final {}
     void GetterCallbackEvent(Handle<Name> name, Address entry_point) final {}

src/runtime/runtime-wasm.cc

@@ -202,14 +202,15 @@ RUNTIME_FUNCTION(Runtime_WasmCompileLazy) {
 
   DCHECK(isolate->context().is_null());
   isolate->set_context(instance->native_context());
-  auto* native_module = instance->module_object().native_module();
-  bool success = wasm::CompileLazy(isolate, native_module, func_index);
+  Handle<WasmModuleObject> module_object{instance->module_object(), isolate};
+  bool success = wasm::CompileLazy(isolate, module_object, func_index);
   if (!success) {
     DCHECK(isolate->has_pending_exception());
     return ReadOnlyRoots(isolate).exception();
   }
 
-  Address entrypoint = native_module->GetCallTargetForFunction(func_index);
+  Address entrypoint =
+      module_object->native_module()->GetCallTargetForFunction(func_index);
 
   return Object(entrypoint);
 }

src/wasm/module-compiler.cc

@@ -1080,8 +1080,9 @@ bool IsLazyModule(const WasmModule* module) {
 
 }  // namespace
 
-bool CompileLazy(Isolate* isolate, NativeModule* native_module,
+bool CompileLazy(Isolate* isolate, Handle<WasmModuleObject> module_object,
                  int func_index) {
+  NativeModule* native_module = module_object->native_module();
   const WasmModule* module = native_module->module();
   auto enabled_features = native_module->enabled_features();
   Counters* counters = isolate->counters();
@@ -1128,7 +1129,9 @@ bool CompileLazy(Isolate* isolate, NativeModule* native_module,
       native_module->AddCompiledCode(std::move(result)));
   DCHECK_EQ(func_index, code->index());
 
-  if (WasmCode::ShouldBeLogged(isolate)) code->LogCode(isolate);
+  if (WasmCode::ShouldBeLogged(isolate)) {
+    code->LogCode(isolate, module_object->script().id());
+  }
 
   counters->wasm_lazily_compiled_functions()->Increment();
 
@@ -1920,6 +1923,10 @@ void AsyncCompileJob::FinishCompile(bool is_after_cache_hit) {
   // We can only update the feature counts once the entire compile is done.
   compilation_state->PublishDetectedFeatures(isolate_);
 
+  // Finally, log all generated code (it does not matter if this happens
+  // repeatedly in case the script is shared).
+  native_module_->LogWasmCodes(isolate_, script->id());
+
   FinishModule();
 }
 
@@ -2655,7 +2662,6 @@ void AsyncStreamingProcessor::OnFinishedStream(OwnedVector<uint8_t> bytes) {
   } else {
     job_->native_module_->SetWireBytes(
         {std::move(job_->bytes_copy_), job_->wire_bytes_.length()});
-    job_->native_module_->LogWasmCodes(job_->isolate_);
   }
   const bool needs_finish = job_->DecrementAndCheckFinisherCount();
   DCHECK_IMPLIES(!has_code_section, needs_finish);

src/wasm/module-compiler.h

@@ -64,7 +64,7 @@ WasmCode* CompileImportWrapper(
 // Triggered by the WasmCompileLazy builtin. The return value indicates whether
 // compilation was successful. Lazy compilation can fail only if validation is
 // also lazy.
-bool CompileLazy(Isolate*, NativeModule*, int func_index);
+bool CompileLazy(Isolate*, Handle<WasmModuleObject>, int func_index);
 
 void TriggerTierUp(Isolate*, NativeModule*, int func_index);
 

src/wasm/wasm-code-manager.cc

@@ -217,7 +217,7 @@ bool WasmCode::ShouldBeLogged(Isolate* isolate) {
          isolate->is_profiling();
 }
 
-void WasmCode::LogCode(Isolate* isolate) const {
+void WasmCode::LogCode(Isolate* isolate, int script_id) const {
   DCHECK(ShouldBeLogged(isolate));
   if (IsAnonymous()) return;
 
@@ -268,8 +268,8 @@ void WasmCode::LogCode(Isolate* isolate) const {
                  "wasm-function[%d]", index()));
     name = VectorOf(name_buffer);
   }
-  PROFILE(isolate,
-          CodeCreateEvent(CodeEventListener::FUNCTION_TAG, this, name));
+  PROFILE(isolate, CodeCreateEvent(CodeEventListener::FUNCTION_TAG, this, name,
+                                   script_id));
 
   if (!source_positions().empty()) {
     LOG_CODE_EVENT(isolate, CodeLinePosInfoRecordEvent(instruction_start(),
@@ -856,7 +856,7 @@ void NativeModule::ReserveCodeTableForTesting(uint32_t max_functions) {
   code_space_data_[0].jump_table = main_jump_table_;
 }
 
-void NativeModule::LogWasmCodes(Isolate* isolate) {
+void NativeModule::LogWasmCodes(Isolate* isolate, int script_id) {
   if (!WasmCode::ShouldBeLogged(isolate)) return;
 
   TRACE_EVENT1("v8.wasm", "wasm.LogWasmCodes", "functions",
@@ -867,7 +867,7 @@ void NativeModule::LogWasmCodes(Isolate* isolate) {
   WasmCodeRefScope code_ref_scope;
   base::MutexGuard lock(&allocation_mutex_);
   for (auto& owned_entry : owned_code_) {
-    owned_entry.second->LogCode(isolate);
+    owned_entry.second->LogCode(isolate, script_id);
   }
 }
 

src/wasm/wasm-code-manager.h

@@ -199,7 +199,7 @@ class V8_EXPORT_PRIVATE WasmCode final {
                    Address current_pc = kNullAddress) const;
 
   static bool ShouldBeLogged(Isolate* isolate);
-  void LogCode(Isolate* isolate) const;
+  void LogCode(Isolate* isolate, int script_id) const;
 
   WasmCode(const WasmCode&) = delete;
   WasmCode& operator=(const WasmCode&) = delete;
@@ -571,7 +571,7 @@ class V8_EXPORT_PRIVATE NativeModule final {
   // on the fly, and bypass the instance builder pipeline.
   void ReserveCodeTableForTesting(uint32_t max_functions);
 
-  void LogWasmCodes(Isolate* isolate);
+  void LogWasmCodes(Isolate* isolate, int script_id);
 
   CompilationState* compilation_state() { return compilation_state_.get(); }
 

src/wasm/wasm-engine.cc

@@ -129,9 +129,9 @@ class WasmGCForegroundTask : public CancelableTask {
 
 class WeakScriptHandle {
  public:
-  explicit WeakScriptHandle(Handle<Script> handle) {
+  explicit WeakScriptHandle(Handle<Script> script) : script_id_(script->id()) {
     auto global_handle =
-        handle->GetIsolate()->global_handles()->Create(*handle);
+        script->GetIsolate()->global_handles()->Create(*script);
     location_ = std::make_unique<Address*>(global_handle.location());
     GlobalHandles::MakeWeak(location_.get());
   }
@@ -146,12 +146,18 @@ class WeakScriptHandle {
 
   WeakScriptHandle(WeakScriptHandle&&) V8_NOEXCEPT = default;
 
-  Handle<Script> handle() { return Handle<Script>(*location_); }
+  Handle<Script> handle() const { return Handle<Script>(*location_); }
+
+  int script_id() const { return script_id_; }
 
  private:
   // Store the location in a unique_ptr so that its address stays the same even
   // when this object is moved/copied.
   std::unique_ptr<Address*> location_;
+
+  // Store the script ID independent of the weak handle, such that it's always
+  // available.
+  int script_id_;
 };
 
 }  // namespace
@@ -351,8 +357,9 @@ struct WasmEngine::IsolateInfo {
   // The currently scheduled LogCodesTask.
   LogCodesTask* log_codes_task = nullptr;
 
-  // The vector of code objects that still need to be logged in this isolate.
-  std::vector<WasmCode*> code_to_log;
+  // The vector of code objects and associated script IDs that still need to be
+  // logged in this isolate.
+  std::vector<std::pair<std::vector<WasmCode*>, int>> code_to_log;
 
   // The foreground task runner of the isolate (can be called from background).
   std::shared_ptr<v8::TaskRunner> foreground_task_runner;
@@ -508,7 +515,7 @@ MaybeHandle<WasmModuleObject> WasmEngine::SyncCompile(
   }
 
   // Transfer ownership of the WasmModule to the {Managed<WasmModule>} generated
-  // in {CompileToModuleObject}.
+  // in {CompileToNativeModule}.
   Handle<FixedArray> export_wrappers;
   std::shared_ptr<NativeModule> native_module =
       CompileToNativeModule(isolate, enabled, thrower,
@@ -528,6 +535,8 @@ MaybeHandle<WasmModuleObject> WasmEngine::SyncCompile(
 
   Handle<Script> script = GetOrCreateScript(isolate, native_module);
 
+  native_module->LogWasmCodes(isolate, script->id());
+
   // Create the compiled module object and populate with compiled functions
   // and information needed at instantiation time. This object needs to be
   // serializable. Instantiation may occur off a deserialized version of this
@@ -985,9 +994,8 @@ void WasmEngine::RemoveIsolate(Isolate* isolate) {
     if (RemoveIsolateFromCurrentGC(isolate)) PotentiallyFinishCurrentGC();
   }
   if (auto* task = info->log_codes_task) task->Cancel();
-  if (!info->code_to_log.empty()) {
-    WasmCode::DecrementRefCount(VectorOf(info->code_to_log));
-    info->code_to_log.clear();
+  for (auto& pair : info->code_to_log) {
+    WasmCode::DecrementRefCount(VectorOf(pair.first));
   }
 }
 
@@ -1009,8 +1017,21 @@ void WasmEngine::LogCode(Vector<WasmCode*> code_vec) {
     if (info->code_to_log.empty()) {
       isolate->stack_guard()->RequestLogWasmCode();
     }
-    info->code_to_log.insert(info->code_to_log.end(), code_vec.begin(),
-                             code_vec.end());
+    auto script_it = info->scripts.find(native_module);
+    if (script_it == info->scripts.end()) {
+      // Script does not yet exist, logging will happen later.
+      continue;
+    }
+    int script_id = script_it->second.script_id();
+    if (!info->code_to_log.empty() &&
+        info->code_to_log.back().second == script_id) {
+      info->code_to_log.back().first.insert(
+          info->code_to_log.back().first.end(), code_vec.begin(),
+          code_vec.end());
+    } else {
+      info->code_to_log.emplace_back(
+          std::vector<WasmCode*>{code_vec.begin(), code_vec.end()}, script_id);
+    }
     for (WasmCode* code : code_vec) {
       DCHECK_EQ(native_module, code->native_module());
       code->IncRef();
@@ -1028,7 +1049,7 @@ void WasmEngine::EnableCodeLogging(Isolate* isolate) {
 void WasmEngine::LogOutstandingCodesForIsolate(Isolate* isolate) {
   // Under the mutex, get the vector of wasm code to log. Then log and decrement
   // the ref count without holding the mutex.
-  std::vector<WasmCode*> code_to_log;
+  std::vector<std::pair<std::vector<WasmCode*>, int>> code_to_log;
   {
     base::MutexGuard guard(&mutex_);
     DCHECK_EQ(1, isolates_.count(isolate));
@@ -1039,11 +1060,13 @@ void WasmEngine::LogOutstandingCodesForIsolate(Isolate* isolate) {
   if (!WasmCode::ShouldBeLogged(isolate)) return;
 
   TRACE_EVENT1("v8.wasm", "wasm.LogCode", "codeObjects", code_to_log.size());
-  if (code_to_log.empty()) return;
-  for (WasmCode* code : code_to_log) {
-    code->LogCode(isolate);
+  for (auto& pair : code_to_log) {
+    int script_id = pair.second;
+    for (WasmCode* code : pair.first) {
+      code->LogCode(isolate, script_id);
+    }
+    WasmCode::DecrementRefCount(VectorOf(pair.first));
   }
-  WasmCode::DecrementRefCount(VectorOf(code_to_log));
 }
 
 std::shared_ptr<NativeModule> WasmEngine::NewNativeModule(
@@ -1148,18 +1171,19 @@ void WasmEngine::FreeNativeModule(NativeModule* native_module) {
     // If there are {WasmCode} objects of the deleted {NativeModule}
     // outstanding to be logged in this isolate, remove them. Decrementing the
     // ref count is not needed, since the {NativeModule} dies anyway.
-    size_t remaining = info->code_to_log.size();
-    if (remaining > 0) {
-      for (size_t i = 0; i < remaining; ++i) {
-        while (i < remaining &&
-               info->code_to_log[i]->native_module() == native_module) {
-          // Move the last remaining item to this slot (this can be the same
-          // as {i}, which is OK).
-          info->code_to_log[i] = info->code_to_log[--remaining];
-        }
-      }
-      info->code_to_log.resize(remaining);
+    for (auto& pair : info->code_to_log) {
+      auto part_of_native_module = [native_module](WasmCode* code) {
+        return code->native_module() == native_module;
+      };
+      auto new_end = std::remove_if(pair.first.begin(), pair.first.end(),
+                                    part_of_native_module);
+      pair.first.erase(new_end, pair.first.end());
     }
+    // Now remove empty vectors in {code_to_log}.
+    auto new_end =
+        std::remove_if(info->code_to_log.begin(), info->code_to_log.end(),
+                       [](auto& pair) { return pair.first.empty(); });
+    info->code_to_log.erase(new_end, info->code_to_log.end());
   }
   // If there is a GC running which has references to code contained in the
   // deleted {NativeModule}, remove those references.

src/wasm/wasm-serialization.cc

@@ -830,9 +830,6 @@ MaybeHandle<WasmModuleObject> DeserializeNativeModule(
     if (error) return {};
   }
 
-  // Log the code within the generated module for profiling.
-  shared_native_module->LogWasmCodes(isolate);
-
   Handle<FixedArray> export_wrappers;
   CompileJsToWasmWrappers(isolate, shared_native_module->module(),
                           &export_wrappers);
@@ -844,6 +841,10 @@ MaybeHandle<WasmModuleObject> DeserializeNativeModule(
 
   // Finish the Wasm script now and make it public to the debugger.
   isolate->debug()->OnAfterCompile(script);
+
+  // Log the code within the generated module for profiling.
+  shared_native_module->LogWasmCodes(isolate, script->id());
+
   return module_object;
 }
 

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

@@ -558,7 +558,8 @@ void WasmFunctionCompiler::Build(const byte* start, const byte* end) {
   WasmCode* code = native_module->PublishCode(
       native_module->AddCompiledCode(std::move(result)));
   DCHECK_NOT_NULL(code);
-  if (WasmCode::ShouldBeLogged(isolate())) code->LogCode(isolate());
+  int script_id = builder_->instance_object()->module_object().script().id();
+  if (WasmCode::ShouldBeLogged(isolate())) code->LogCode(isolate(), script_id);
 }
 
 WasmFunctionCompiler::WasmFunctionCompiler(Zone* zone, const FunctionSig* sig,

test/inspector/cpu-profiler/console-profile-wasm-expected.txt

@@ -4,22 +4,22 @@ Compiling wasm.
 Building wasm module with sentinel 1.
 Running fib with increasing input until it shows up in the profile.
 Found expected functions in profile.
-Wasm script id is NOT SET.
+Wasm script id is set.
 testEnableProfilerLate
 Compiling wasm.
 Building wasm module with sentinel 2.
 Running fib with increasing input until it shows up in the profile.
 Found expected functions in profile.
-Wasm script id is NOT SET.
+Wasm script id is set.
 testEnableProfilerAfterDebugger
 Compiling wasm.
 Building wasm module with sentinel 3.
 Running fib with increasing input until it shows up in the profile.
 Found expected functions in profile.
-Wasm script id is NOT SET.
+Wasm script id is set.
 testEnableProfilerBeforeDebugger
 Compiling wasm.
 Building wasm module with sentinel 4.
 Running fib with increasing input until it shows up in the profile.
 Found expected functions in profile.
-Wasm script id is NOT SET.
+Wasm script id is set.