Implement code creation events for wasm code on native heap

Adds support for generating logging/profiling event when wasm code gets compiled
on the native heap. As code objects on the native heap are not ordinary heap
objects, the existing abstractions for reporting cannot be used. Instead, add
specialized versions for WasmCode objects.

Change-Id: I808618d70142073b3c1b06edef6931f59bed8cf5
Reviewed-on: https://chromium-review.googlesource.com/913308
Commit-Queue: Stephan Herhut <herhut@chromium.org>
Reviewed-by: Clemens Hammacher <clemensh@chromium.org>
Cr-Commit-Position: refs/heads/master@{#51388}

src/code-events.h

@@ -9,6 +9,7 @@
 
 #include "src/base/platform/mutex.h"
 #include "src/globals.h"
+#include "src/vector.h"
 
 namespace v8 {
 namespace internal {
@@ -19,6 +20,11 @@ class Name;
 class SharedFunctionInfo;
 class String;
 
+namespace wasm {
+class WasmCode;
+using WasmName = Vector<const char>;
+}  // namespace wasm
+
 #define LOG_EVENTS_AND_TAGS_LIST(V)                                      \
   V(CODE_CREATION_EVENT, "code-creation")                                \
   V(CODE_DISABLE_OPT_EVENT, "code-disable-optimization")                 \
@@ -65,6 +71,8 @@ class CodeEventListener {
   virtual void CodeCreateEvent(LogEventsAndTags tag, AbstractCode* code,
                                SharedFunctionInfo* shared, Name* source,
                                int line, int column) = 0;
+  virtual void CodeCreateEvent(LogEventsAndTags tag, wasm::WasmCode* code,
+                               wasm::WasmName name) = 0;
   virtual void CallbackEvent(Name* name, Address entry_point) = 0;
   virtual void GetterCallbackEvent(Name* name, Address entry_point) = 0;
   virtual void SetterCallbackEvent(Name* name, Address entry_point) = 0;
@@ -118,6 +126,10 @@ class CodeEventDispatcher {
     CODE_EVENT_DISPATCH(
         CodeCreateEvent(tag, code, shared, source, line, column));
   }
+  void CodeCreateEvent(LogEventsAndTags tag, wasm::WasmCode* code,
+                       wasm::WasmName name) {
+    CODE_EVENT_DISPATCH(CodeCreateEvent(tag, code, name));
+  }
   void CallbackEvent(Name* name, Address entry_point) {
     CODE_EVENT_DISPATCH(CallbackEvent(name, entry_point));
   }

src/compiler/wasm-compiler.cc

@@ -4688,7 +4688,7 @@ Handle<Code> CompileJSToWasmWrapper(Isolate* isolate, wasm::WasmModule* module,
 #endif
 
   if (must_record_function_compilation(isolate)) {
-    RecordFunctionCompilation(CodeEventListener::FUNCTION_TAG, isolate, code,
+    RecordFunctionCompilation(CodeEventListener::STUB_TAG, isolate, code,
                               "%.*s", func_name.length(), func_name.start());
   }
 
@@ -4821,7 +4821,7 @@ Handle<Code> CompileWasmToJSWrapper(
 #endif
 
   if (must_record_function_compilation(isolate)) {
-    RecordFunctionCompilation(CodeEventListener::FUNCTION_TAG, isolate, code,
+    RecordFunctionCompilation(CodeEventListener::STUB_TAG, isolate, code,
                               "%.*s", func_name.length(), func_name.start());
   }
 
@@ -4894,7 +4894,7 @@ Handle<Code> CompileWasmToWasmWrapper(Isolate* isolate, WasmCodeWrapper target,
     buffer.Dispose();
   }
   if (isolate->logger()->is_logging_code_events() || isolate->is_profiling()) {
-    RecordFunctionCompilation(CodeEventListener::FUNCTION_TAG, isolate, code,
+    RecordFunctionCompilation(CodeEventListener::STUB_TAG, isolate, code,
                               "wasm-to-wasm");
   }
 
@@ -4957,7 +4957,7 @@ Handle<Code> CompileWasmInterpreterEntry(Isolate* isolate, uint32_t func_index,
 #endif
 
     if (must_record_function_compilation(isolate)) {
-      RecordFunctionCompilation(CodeEventListener::FUNCTION_TAG, isolate, code,
+      RecordFunctionCompilation(CodeEventListener::STUB_TAG, isolate, code,
                                 "%.*s", func_name.length(), func_name.start());
     }
   }
@@ -5320,7 +5320,6 @@ WasmCodeWrapper WasmCompilationUnit::FinishTurbofanCompilation(
     if (!code) {
       return WasmCodeWrapper(code);
     }
-    // TODO(mtrofin): add CodeEventListener call - see the non-native case.
     if (FLAG_trace_wasm_decode_time) {
       double codegen_ms = codegen_timer.Elapsed().InMillisecondsF();
       PrintF("wasm-code-generation ok: %u bytes, %0.3f ms code generation\n",
@@ -5328,6 +5327,9 @@ WasmCodeWrapper WasmCompilationUnit::FinishTurbofanCompilation(
              codegen_ms);
     }
 
+    PROFILE(isolate_,
+            CodeCreateEvent(CodeEventListener::FUNCTION_TAG, code, func_name_));
+
     Handle<ByteArray> source_positions =
         tf_.job_->compilation_info()->wasm_code_desc()->source_positions_table;
     MaybeHandle<HandlerTable> handler_table =
@@ -5408,14 +5410,16 @@ WasmCodeWrapper WasmCompilationUnit::FinishLiftoffCompilation(
     PackProtectedInstructions(code);
     ret = WasmCodeWrapper(code);
   } else {
-    // TODO(mtrofin): figure a way to raise events.
-    // Consider lifting it to FinishCompilation.
+    // TODO(herhut) Consider lifting it to FinishCompilation.
     native_module_->compiled_module()->source_positions()->set(
         func_index_, *source_positions);
-    ret = WasmCodeWrapper(
+    wasm::WasmCode* code =
         native_module_->AddCode(desc, liftoff_.asm_.GetTotalFrameSlotCount(),
                                 func_index_, liftoff_.safepoint_table_offset_,
-                                std::move(protected_instructions_), true));
+                                std::move(protected_instructions_), true);
+    PROFILE(isolate_,
+            CodeCreateEvent(CodeEventListener::FUNCTION_TAG, code, func_name_));
+    ret = WasmCodeWrapper(code);
   }
 #ifdef ENABLE_DISASSEMBLER
   if (FLAG_print_code || FLAG_print_wasm_code) {

src/log.h

@@ -74,6 +74,11 @@ class Profiler;
 class ProfilerListener;
 class RuntimeCallTimer;
 class Ticker;
+class WasmCompiledModule;
+
+namespace wasm {
+class WasmCode;
+}
 
 #undef LOG
 #define LOG(isolate, Call)                              \
@@ -176,6 +181,8 @@ class Logger : public CodeEventListener {
   void CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
                        AbstractCode* code, SharedFunctionInfo* shared,
                        Name* source, int line, int column);
+  void CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
+                       wasm::WasmCode* code, wasm::WasmName name);
   // Emits a code deoptimization event.
   void CodeDisableOptEvent(AbstractCode* code, SharedFunctionInfo* shared);
   void CodeMovingGCEvent();
@@ -237,6 +244,7 @@ class Logger : public CodeEventListener {
 
   void LogExistingFunction(Handle<SharedFunctionInfo> shared,
                            Handle<AbstractCode> code);
+  void LogCompiledModule(Handle<WasmCompiledModule> module);
   // Logs all compiled functions found in the heap.
   void LogCompiledFunctions();
   // Logs all accessor callbacks found in the heap.
@@ -385,6 +393,9 @@ class CodeEventLogger : public CodeEventListener {
   void CodeCreateEvent(LogEventsAndTags tag, AbstractCode* code,
                        SharedFunctionInfo* shared, Name* source, int line,
                        int column) override;
+  void CodeCreateEvent(LogEventsAndTags tag, wasm::WasmCode* code,
+                       wasm::WasmName name) override;
+
   void RegExpCodeCreateEvent(AbstractCode* code, String* source) override;
   void InstructionStreamCreateEvent(LogEventsAndTags tag,
                                     const InstructionStream* stream,
@@ -404,6 +415,8 @@ class CodeEventLogger : public CodeEventListener {
                                  const char* name, int length) = 0;
   virtual void LogRecordedBuffer(const InstructionStream* stream,
                                  const char* name, int length) = 0;
+  virtual void LogRecordedBuffer(wasm::WasmCode* code, const char* name,
+                                 int length) = 0;
 
   NameBuffer* name_buffer_;
 };

src/perf-jit.cc

@@ -34,6 +34,7 @@
 #include "src/instruction-stream.h"
 #include "src/objects-inl.h"
 #include "src/source-position-table.h"
+#include "src/wasm/wasm-code-manager.h"
 
 #if V8_OS_LINUX
 #include <fcntl.h>
@@ -214,7 +215,11 @@ void PerfJitLogger::LogRecordedBuffer(AbstractCode* abstract_code,
 
   // Debug info has to be emitted first.
   if (FLAG_perf_prof && shared != nullptr) {
-    LogWriteDebugInfo(code, shared);
+    // TODO(herhut): This currently breaks for js2wasm/wasm2js functions.
+    if (code->kind() != Code::JS_TO_WASM_FUNCTION &&
+        code->kind() != Code::WASM_TO_JS_FUNCTION) {
+      LogWriteDebugInfo(code, shared);
+    }
   }
 
   const char* code_name = name;
@@ -227,11 +232,27 @@ void PerfJitLogger::LogRecordedBuffer(AbstractCode* abstract_code,
   // Unwinding info comes right after debug info.
   if (FLAG_perf_prof_unwinding_info) LogWriteUnwindingInfo(code);
 
+  WriteJitCodeLoadEntry(code_pointer, code_size, code_name, length);
+}
+
+void PerfJitLogger::LogRecordedBuffer(wasm::WasmCode* code, const char* name,
+                                      int length) {
+  base::LockGuard<base::RecursiveMutex> guard_file(file_mutex_.Pointer());
+
+  if (perf_output_handle_ == nullptr) return;
+
+  WriteJitCodeLoadEntry(code->instructions().start(),
+                        code->instructions().length(), name, length);
+}
+
+void PerfJitLogger::WriteJitCodeLoadEntry(const uint8_t* code_pointer,
+                                          uint32_t code_size, const char* name,
+                                          int name_length) {
   static const char string_terminator[] = "\0";
 
   PerfJitCodeLoad code_load;
   code_load.event_ = PerfJitCodeLoad::kLoad;
-  code_load.size_ = sizeof(code_load) + length + 1 + code_size;
+  code_load.size_ = sizeof(code_load) + name_length + 1 + code_size;
   code_load.time_stamp_ = GetTimestamp();
   code_load.process_id_ =
       static_cast<uint32_t>(base::OS::GetCurrentProcessId());
@@ -244,7 +265,7 @@ void PerfJitLogger::LogRecordedBuffer(AbstractCode* abstract_code,
   code_index_++;
 
   LogWriteBytes(reinterpret_cast<const char*>(&code_load), sizeof(code_load));
-  LogWriteBytes(code_name, length);
+  LogWriteBytes(name, name_length);
   LogWriteBytes(string_terminator, 1);
   LogWriteBytes(reinterpret_cast<const char*>(code_pointer), code_size);
 }

src/perf-jit.h

@@ -56,6 +56,8 @@ class PerfJitLogger : public CodeEventLogger {
                          const char* name, int length) override;
   void LogRecordedBuffer(const InstructionStream* stream, const char* name,
                          int length) override;
+  void LogRecordedBuffer(wasm::WasmCode* code, const char* name,
+                         int length) override;
 
   // Extension added to V8 log file name to get the low-level log name.
   static const char kFilenameFormatString[];
@@ -65,6 +67,9 @@ class PerfJitLogger : public CodeEventLogger {
   // minimize the associated overhead.
   static const int kLogBufferSize = 2 * MB;
 
+  void WriteJitCodeLoadEntry(const uint8_t* code_pointer, uint32_t code_size,
+                             const char* name, int name_length);
+
   void LogWriteBytes(const char* bytes, int size);
   void LogWriteHeader();
   void LogWriteDebugInfo(Code* code, SharedFunctionInfo* shared);
@@ -133,6 +138,11 @@ class PerfJitLogger : public CodeEventLogger {
                          int length) override {
     UNIMPLEMENTED();
   }
+
+  void LogRecordedBuffer(wasm::WasmCode* code, const char* name,
+                         int length) override {
+    UNIMPLEMENTED();
+  }
 };
 
 #endif  // V8_OS_LINUX

src/profiler/profiler-listener.cc

@@ -10,6 +10,7 @@
 #include "src/profiler/cpu-profiler.h"
 #include "src/profiler/profile-generator-inl.h"
 #include "src/source-position-table.h"
+#include "src/wasm/wasm-code-manager.h"
 
 namespace v8 {
 namespace internal {
@@ -111,6 +112,21 @@ void ProfilerListener::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
   DispatchCodeEvent(evt_rec);
 }
 
+void ProfilerListener::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
+                                       wasm::WasmCode* code,
+                                       wasm::WasmName name) {
+  CodeEventsContainer evt_rec(CodeEventRecord::CODE_CREATION);
+  CodeCreateEventRecord* rec = &evt_rec.CodeCreateEventRecord_;
+  rec->start = code->instructions().start();
+  rec->entry = NewCodeEntry(
+      tag, GetFunctionName(name.start()), CodeEntry::kEmptyNamePrefix,
+      CodeEntry::kEmptyResourceName, CpuProfileNode::kNoLineNumberInfo,
+      CpuProfileNode::kNoColumnNumberInfo, nullptr,
+      code->instructions().start());
+  rec->size = code->instructions().length();
+  DispatchCodeEvent(evt_rec);
+}
+
 void ProfilerListener::CodeMoveEvent(AbstractCode* from, Address to) {
   CodeEventsContainer evt_rec(CodeEventRecord::CODE_MOVE);
   CodeMoveEventRecord* rec = &evt_rec.CodeMoveEventRecord_;

src/profiler/profiler-listener.h

@@ -37,6 +37,9 @@ class ProfilerListener : public CodeEventListener {
   void CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
                        AbstractCode* code, SharedFunctionInfo* shared,
                        Name* script_name, int line, int column) override;
+  void CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
+                       wasm::WasmCode* code, wasm::WasmName name) override;
+
   void CodeMovingGCEvent() override {}
   void CodeMoveEvent(AbstractCode* from, Address to) override;
   void CodeDisableOptEvent(AbstractCode* code,

src/snapshot/serializer.h

@@ -122,6 +122,11 @@ class CodeAddressMap : public CodeEventLogger {
     address_to_name_map_.Insert(stream->bytes(), name, length);
   }
 
+  void LogRecordedBuffer(wasm::WasmCode* code, const char* name,
+                         int length) override {
+    UNREACHABLE();
+  }
+
   NameMap address_to_name_map_;
   Isolate* isolate_;
 };

src/wasm/wasm-objects.cc

@@ -1819,6 +1819,28 @@ bool WasmCompiledModule::SetBreakPoint(
   return true;
 }
 
+void WasmCompiledModule::LogWasmCodes(Isolate* isolate) {
+  wasm::NativeModule* native_module = GetNativeModule();
+  if (native_module == nullptr) return;
+  const uint32_t number_of_codes = native_module->FunctionCount();
+  if (has_shared()) {
+    Handle<WasmSharedModuleData> shared_handle(shared(), isolate);
+    for (uint32_t i = 0; i < number_of_codes; i++) {
+      wasm::WasmCode* code = native_module->GetCode(i);
+      if (code == nullptr) continue;
+      int name_length;
+      Handle<String> name(
+          WasmSharedModuleData::GetFunctionName(isolate, shared_handle, i));
+      auto cname = name->ToCString(AllowNullsFlag::DISALLOW_NULLS,
+                                   RobustnessFlag::ROBUST_STRING_TRAVERSAL,
+                                   &name_length);
+      wasm::WasmName wasm_name(cname.get(), name_length);
+      PROFILE(isolate, CodeCreateEvent(CodeEventListener::FUNCTION_TAG, code,
+                                       wasm_name));
+    }
+  }
+}
+
 void AttachWasmFunctionInfo(Isolate* isolate, Handle<Code> code,
                             MaybeHandle<WeakCell> weak_instance,
                             int func_index) {

src/wasm/wasm-objects.h

@@ -556,6 +556,8 @@ class WasmCompiledModule : public FixedArray {
   static Address GetTableValue(FixedArray* table, int index);
   inline void ReplaceCodeTableForTesting(Handle<FixedArray> testing_table);
 
+  void LogWasmCodes(Isolate* isolate);
+
  private:
   void InitId();
 

test/cctest/test-log.cc

@@ -705,6 +705,8 @@ TEST(Issue539892) {
                            const char* name, int length) override {}
     void LogRecordedBuffer(const i::InstructionStream* stream, const char* name,
                            int length) override {}
+    void LogRecordedBuffer(i::wasm::WasmCode* code, const char* name,
+                           int length) override {}
   } code_event_logger;
   SETUP_FLAGS();
   v8::Isolate::CreateParams create_params;