[wasm] Call LogWasmCode in ImportNativeModule

For performance profiling in DevTools, LogWasmCode has to be called on
every isolate for a NativeModule. After receiving a NativeModule from
postMessage, the call to LogWasmCode was missing.

R=clemensb@chromium.org

Bug: chromium:1381182
Change-Id: Ibbb5129a848477c42ac2a8fbc04b0e61ec8900eb
Reviewed-on: https://chromium-review.googlesource.com/c/v8/v8/+/4051245
Reviewed-by: Clemens Backes <clemensb@chromium.org>
Commit-Queue: Andreas Haas <ahaas@chromium.org>
Cr-Commit-Position: refs/heads/main@{#84546}

src/d8/d8-console.cc

@@ -4,6 +4,12 @@
 
 #include "src/d8/d8-console.h"
 
+#include <stdio.h>
+
+#include <fstream>
+
+#include "include/v8-profiler.h"
+#include "src/d8/d8.h"
 #include "src/execution/isolate.h"
 
 namespace v8 {
@@ -34,12 +40,49 @@ void WriteToFile(const char* prefix, FILE* file, Isolate* isolate,
   // often used for timing, so it should appear as soon as the code is executed.
   fflush(file);
 }
+
+class FileOutputStream : public v8::OutputStream {
+ public:
+  explicit FileOutputStream(const char* filename)
+      : os_(filename, std::ios_base::out | std::ios_base::trunc) {}
+
+  WriteResult WriteAsciiChunk(char* data, int size) override {
+    os_.write(data, size);
+    return kContinue;
+  }
+
+  void EndOfStream() override { os_.close(); }
+
+ private:
+  std::ofstream os_;
+};
+
+static constexpr const char* kCpuProfileOutputFilename = "v8.prof";
+
+class StringOutputStream : public v8::OutputStream {
+ public:
+  WriteResult WriteAsciiChunk(char* data, int size) override {
+    os_.write(data, size);
+    return kContinue;
+  }
+
+  void EndOfStream() override {}
+
+  std::string result() { return os_.str(); }
+
+ private:
+  std::ostringstream os_;
+};
 }  // anonymous namespace
 
 D8Console::D8Console(Isolate* isolate) : isolate_(isolate) {
   default_timer_ = base::TimeTicks::Now();
 }
 
+D8Console::~D8Console() {
+  if (profiler_) profiler_->Dispose();
+}
+
 void D8Console::Assert(const debug::ConsoleCallArguments& args,
                        const v8::debug::ConsoleContext&) {
   // If no arguments given, the "first" argument is undefined which is
@@ -74,6 +117,31 @@ void D8Console::Debug(const debug::ConsoleCallArguments& args,
   WriteToFile("console.debug", stdout, isolate_, args);
 }
 
+void D8Console::Profile(const debug::ConsoleCallArguments& args,
+                        const v8::debug::ConsoleContext&) {
+  if (!profiler_) {
+    profiler_ = CpuProfiler::New(isolate_);
+    Shell::SetCpuProfiler(profiler_);
+  }
+  profiler_->StartProfiling(String::Empty(isolate_), CpuProfilingOptions{});
+}
+
+void D8Console::ProfileEnd(const debug::ConsoleCallArguments& args,
+                           const v8::debug::ConsoleContext&) {
+  if (!profiler_) return;
+  CpuProfile* profile = profiler_->StopProfiling(String::Empty(isolate_));
+  if (Shell::HasOnProfileEndListener()) {
+    StringOutputStream out;
+    profile->Serialize(&out);
+    Shell::TriggerOnProfileEndListener(isolate_, out.result());
+    Shell::ResetCpuProfiler();
+  } else {
+    FileOutputStream out(kCpuProfileOutputFilename);
+    profile->Serialize(&out);
+  }
+  profile->Delete();
+}
+
 void D8Console::Time(const debug::ConsoleCallArguments& args,
                      const v8::debug::ConsoleContext&) {
   if (i::v8_flags.correctness_fuzzer_suppressions) return;

src/d8/d8-console.h

@@ -12,9 +12,12 @@
 
 namespace v8 {
 
+class CpuProfiler;
+
 class D8Console : public debug::ConsoleDelegate {
  public:
   explicit D8Console(Isolate* isolate);
+  ~D8Console() override;
 
  private:
   void Assert(const debug::ConsoleCallArguments& args,
@@ -29,6 +32,10 @@ class D8Console : public debug::ConsoleDelegate {
             const v8::debug::ConsoleContext&) override;
   void Debug(const debug::ConsoleCallArguments& args,
              const v8::debug::ConsoleContext&) override;
+  void Profile(const debug::ConsoleCallArguments& args,
+               const v8::debug::ConsoleContext& context) override;
+  void ProfileEnd(const debug::ConsoleCallArguments& args,
+                  const v8::debug::ConsoleContext& context) override;
   void Time(const debug::ConsoleCallArguments& args,
             const v8::debug::ConsoleContext&) override;
   void TimeEnd(const debug::ConsoleCallArguments& args,
@@ -41,6 +48,7 @@ class D8Console : public debug::ConsoleDelegate {
   Isolate* isolate_;
   std::map<std::string, base::TimeTicks> timers_;
   base::TimeTicks default_timer_;
+  CpuProfiler* profiler_{nullptr};
 };
 
 }  // namespace v8

src/d8/d8.cc

@@ -465,6 +465,9 @@ CounterCollection* Shell::counters_ = &local_counters_;
 base::LazyMutex Shell::context_mutex_;
 const base::TimeTicks Shell::kInitialTicks = base::TimeTicks::Now();
 Global<Function> Shell::stringify_function_;
+Global<Function> Shell::profile_end_callback_;
+Global<Context> Shell::profile_end_callback_context_;
+CpuProfiler* Shell::cpu_profiler_ = nullptr;
 base::LazyMutex Shell::workers_mutex_;
 bool Shell::allow_new_workers_ = true;
 std::unordered_set<std::shared_ptr<Worker>> Shell::running_workers_;
@@ -2509,6 +2512,47 @@ void Shell::SerializerDeserialize(
   args.GetReturnValue().Set(result);
 }
 
+void Shell::ProfilerSetOnProfileEndListener(
+    const v8::FunctionCallbackInfo<v8::Value>& args) {
+  Isolate* isolate = args.GetIsolate();
+  HandleScope handle_scope(isolate);
+  if (!args[0]->IsFunction()) {
+    isolate->ThrowError("The OnProfileEnd listener has to be a function");
+  }
+  profile_end_callback_.Reset(isolate, args[0].As<Function>());
+  profile_end_callback_context_.Reset(isolate, isolate->GetCurrentContext());
+}
+
+bool Shell::HasOnProfileEndListener() {
+  CHECK_EQ(profile_end_callback_.IsEmpty(),
+           profile_end_callback_context_.IsEmpty());
+  return !profile_end_callback_.IsEmpty();
+}
+
+void Shell::ProfilerTriggerSample(
+    const v8::FunctionCallbackInfo<v8::Value>& args) {
+  if (cpu_profiler_) {
+    Isolate* isolate = args.GetIsolate();
+    cpu_profiler_->CollectSample(isolate);
+  }
+}
+
+void Shell::TriggerOnProfileEndListener(Isolate* isolate, std::string profile) {
+  CHECK(HasOnProfileEndListener());
+  Local<Value> argv[1] = {
+      String::NewFromUtf8(isolate, profile.c_str()).ToLocalChecked()};
+  Local<Context> context = profile_end_callback_context_.Get(isolate);
+  TryCatch try_catch(isolate);
+  try_catch.SetVerbose(true);
+  USE(profile_end_callback_.Get(isolate)->Call(context, Undefined(isolate), 1,
+                                               argv));
+  // The profiler callback may have been set up on a worker. We reset the
+  // callbacks now to avoid problems in the shutdown sequence of the worker and
+  // the main thread.
+  profile_end_callback_.Reset();
+  profile_end_callback_context_.Reset();
+}
+
 void WriteToFile(FILE* file, const v8::FunctionCallbackInfo<v8::Value>& args) {
   for (int i = 0; i < args.Length(); i++) {
     HandleScope handle_scope(args.GetIsolate());
@@ -3535,6 +3579,16 @@ Local<ObjectTemplate> Shell::CreateD8Template(Isolate* isolate) {
                               Local<Signature>(), 1));
     d8_template->Set(isolate, "serializer", serializer_template);
   }
+  {
+    Local<ObjectTemplate> profiler_template = ObjectTemplate::New(isolate);
+    profiler_template->Set(
+        isolate, "setOneShotOnProfileEndListener",
+        FunctionTemplate::New(isolate, ProfilerSetOnProfileEndListener));
+    profiler_template->Set(
+        isolate, "triggerSample",
+        FunctionTemplate::New(isolate, ProfilerTriggerSample));
+    d8_template->Set(isolate, "profiler", profiler_template);
+  }
   return d8_template;
 }
 
@@ -5919,6 +5973,8 @@ int Shell::Main(int argc, char* argv[]) {
       cached_code_map_.clear();
       evaluation_context_.Reset();
       stringify_function_.Reset();
+      profile_end_callback_.Reset();
+      profile_end_callback_context_.Reset();
       CollectGarbage(isolate);
 #ifdef V8_FUZZILLI
       // Send result to parent (fuzzilli) and reset edge guards.

src/d8/d8.h

@@ -598,6 +598,22 @@ class Shell : public i::AllStatic {
   static void SerializerDeserialize(
       const v8::FunctionCallbackInfo<v8::Value>& args);
 
+  static void ProfilerSetOnProfileEndListener(
+      const v8::FunctionCallbackInfo<v8::Value>& args);
+  static void ProfilerTriggerSample(
+      const v8::FunctionCallbackInfo<v8::Value>& args);
+
+  static bool HasOnProfileEndListener();
+
+  static void TriggerOnProfileEndListener(Isolate* isolate,
+                                          std::string profile);
+
+  static void SetCpuProfiler(CpuProfiler* cpu_profiler) {
+    cpu_profiler_ = cpu_profiler;
+  }
+
+  static void ResetCpuProfiler() { cpu_profiler_ = nullptr; }
+
   static void Print(const v8::FunctionCallbackInfo<v8::Value>& args);
   static void PrintErr(const v8::FunctionCallbackInfo<v8::Value>& args);
   static void WriteStdout(const v8::FunctionCallbackInfo<v8::Value>& args);
@@ -734,6 +750,11 @@ class Shell : public i::AllStatic {
   static Global<Context> evaluation_context_;
   static base::OnceType quit_once_;
   static Global<Function> stringify_function_;
+
+  static Global<Function> profile_end_callback_;
+  static Global<Context> profile_end_callback_context_;
+  static CpuProfiler* cpu_profiler_;
+
   static const char* stringify_source_;
   static CounterMap* counter_map_;
   static base::SharedMutex counter_mutex_;

src/wasm/wasm-engine.cc

@@ -871,6 +871,7 @@ Handle<WasmModuleObject> WasmEngine::ImportNativeModule(
   ModuleWireBytes wire_bytes(native_module->wire_bytes());
   Handle<Script> script =
       GetOrCreateScript(isolate, shared_native_module, source_url);
+  native_module->LogWasmCodes(isolate, *script);
   Handle<WasmModuleObject> module_object =
       WasmModuleObject::New(isolate, std::move(shared_native_module), script);
   {

test/mjsunit/mjsunit.status

@@ -983,6 +983,10 @@
   # not possible.
   'wasm/serialization-with-compilation-hints': [SKIP],
 
+  # The test enables the global profiler, and there can only exist one profiler
+  # at a time.
+  'wasm/log-code-after-post-message': [SKIP],
+
   # The test explicitly deserializes a wasm module and expects the resulting
   # wasm module to match the serialized one. With multiple isolate the resulting
   # wasm module can however, come from the native module cache, and therefore

test/mjsunit/wasm/log-code-after-post-message.js

@@ -0,0 +1,44 @@
+// Copyright 2022 the V8 project authors. All rights reserved.
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+d8.file.execute("test/mjsunit/wasm/wasm-module-builder.js");
+
+function workerCode() {
+  function WorkerOnProfileEnd(profile) {
+    postMessage(profile.indexOf('foo'));
+  }
+
+  onmessage = (wasm_module) => {
+    WebAssembly.instantiate(wasm_module, {q: {func: d8.profiler.triggerSample}})
+        .then(instance => {
+          instance.exports.foo();
+          console.profileEnd();
+        });
+  };
+
+  d8.profiler.setOneShotOnProfileEndListener(WorkerOnProfileEnd);
+  // Code logging happens for all code objects when profiling gets started,
+  // and when new code objects appear after profiling has started. We want to
+  // test the second scenario here. As new code objects appear as the
+  // parameter of {OnMessage}, we have to start profiling already here before
+  // {onMessage} is called.
+  console.profile();
+  postMessage('Starting worker');
+}
+
+const worker = new Worker(workerCode, {type: 'function'});
+
+assertEquals("Starting worker", worker.getMessage());
+
+const builder = new WasmModuleBuilder();
+const sig_index = builder.addType(kSig_v_v);
+const imp_index = builder.addImport("q", "func", sig_index);
+builder.addFunction('foo', kSig_v_v)
+    .addBody([
+      kExprCallFunction, imp_index,
+    ])
+    .exportFunc();
+const wasm_module = builder.toModule();
+worker.postMessage(wasm_module);
+assertTrue(worker.getMessage() > 0);