[profiler] Emit code creation events for off-heap builtins

Bug: v8:6666
Change-Id: I8de39b6ce31b59e5a76267cb665d42f758309c2a
Reviewed-on: https://chromium-review.googlesource.com/897530Reviewed-by: Franziska Hinkelmann <franzih@chromium.org>
Reviewed-by: Jaroslav Sevcik <jarin@chromium.org>
Commit-Queue: Jakob Gruber <jgruber@chromium.org>
Cr-Commit-Position: refs/heads/master@{#51093}

src/code-events.h

@@ -14,6 +14,7 @@ namespace v8 {
 namespace internal {
 
 class AbstractCode;
+class InstructionStream;
 class Name;
 class SharedFunctionInfo;
 class String;
@@ -68,6 +69,9 @@ class CodeEventListener {
   virtual void GetterCallbackEvent(Name* name, Address entry_point) = 0;
   virtual void SetterCallbackEvent(Name* name, Address entry_point) = 0;
   virtual void RegExpCodeCreateEvent(AbstractCode* code, String* source) = 0;
+  virtual void InstructionStreamCreateEvent(LogEventsAndTags tag,
+                                            const InstructionStream* stream,
+                                            const char* description) = 0;
   virtual void CodeMoveEvent(AbstractCode* from, Address to) = 0;
   virtual void SharedFunctionInfoMoveEvent(Address from, Address to) = 0;
   virtual void CodeMovingGCEvent() = 0;
@@ -126,6 +130,11 @@ class CodeEventDispatcher {
   void RegExpCodeCreateEvent(AbstractCode* code, String* source) {
     CODE_EVENT_DISPATCH(RegExpCodeCreateEvent(code, source));
   }
+  void InstructionStreamCreateEvent(LogEventsAndTags tag,
+                                    const InstructionStream* stream,
+                                    const char* description) {
+    CODE_EVENT_DISPATCH(InstructionStreamCreateEvent(tag, stream, description));
+  }
   void CodeMoveEvent(AbstractCode* from, Address to) {
     CODE_EVENT_DISPATCH(CodeMoveEvent(from, to));
   }

src/isolate.cc

@@ -2917,9 +2917,11 @@ void ChangeToOffHeapTrampoline(Isolate* isolate, Handle<Code> code,
   std::memset(trailing_instruction_start, 0, trailing_instruction_size);
 }
 
-void LogInstructionStream(Isolate* isolate, const InstructionStream* stream) {
-  // TODO(jgruber): Log the given instruction stream object (the profiler needs
-  // this to assign ticks to builtins).
+void LogInstructionStream(Isolate* isolate, Code* code,
+                          const InstructionStream* stream) {
+  if (isolate->logger()->is_logging_code_events() || isolate->is_profiling()) {
+    isolate->logger()->LogInstructionStream(code, stream);
+  }
 }
 
 void MoveBuiltinsOffHeap(Isolate* isolate) {
@@ -2939,7 +2941,7 @@ void MoveBuiltinsOffHeap(Isolate* isolate) {
     if (!Builtins::IsIsolateIndependent(i)) continue;
     Handle<Code> code(builtins->builtin(i));
     InstructionStream* stream = new InstructionStream(*code);
-    LogInstructionStream(isolate, stream);
+    LogInstructionStream(isolate, *code, stream);
     ChangeToOffHeapTrampoline(isolate, code, stream);
     isolate->PushOffHeapCode(stream);
   }

src/log.cc

@@ -16,6 +16,7 @@
 #include "src/counters.h"
 #include "src/deoptimizer.h"
 #include "src/global-handles.h"
+#include "src/instruction-stream.h"
 #include "src/interpreter/bytecodes.h"
 #include "src/interpreter/interpreter.h"
 #include "src/libsampler/sampler.h"
@@ -207,6 +208,13 @@ void CodeEventLogger::RegExpCodeCreateEvent(AbstractCode* code,
   LogRecordedBuffer(code, nullptr, name_buffer_->get(), name_buffer_->size());
 }
 
+void CodeEventLogger::InstructionStreamCreateEvent(
+    LogEventsAndTags tag, const InstructionStream* stream,
+    const char* description) {
+  name_buffer_->Init(tag);
+  name_buffer_->AppendBytes(description);
+  LogRecordedBuffer(stream, name_buffer_->get(), name_buffer_->size());
+}
 
 // Linux perf tool logging support
 class PerfBasicLogger : public CodeEventLogger {
@@ -221,6 +229,8 @@ class PerfBasicLogger : public CodeEventLogger {
  private:
   void LogRecordedBuffer(AbstractCode* code, SharedFunctionInfo* shared,
                          const char* name, int length) override;
+  void LogRecordedBuffer(const InstructionStream* stream, const char* name,
+                         int length) override;
 
   // Extension added to V8 log file name to get the low-level log name.
   static const char kFilenameFormatString[];
@@ -273,6 +283,19 @@ void PerfBasicLogger::LogRecordedBuffer(AbstractCode* code, SharedFunctionInfo*,
                    code->instruction_size(), length, name);
 }
 
+void PerfBasicLogger::LogRecordedBuffer(const InstructionStream* stream,
+                                        const char* name, int length) {
+  // Linux perf expects hex literals without a leading 0x, while some
+  // implementations of printf might prepend one when using the %p format
+  // for pointers, leading to wrongly formatted JIT symbols maps.
+  //
+  // Instead, we use V8PRIxPTR format string and cast pointer to uintpr_t,
+  // so that we have control over the exact output format.
+  base::OS::FPrint(perf_output_handle_, "%" V8PRIxPTR " %x %.*s\n",
+                   reinterpret_cast<uintptr_t>(stream->bytes()),
+                   static_cast<int>(stream->byte_length()), length, name);
+}
+
 // Low-level logging support.
 #define LL_LOG(Call) if (ll_logger_) ll_logger_->Call;
 
@@ -290,6 +313,8 @@ class LowLevelLogger : public CodeEventLogger {
  private:
   void LogRecordedBuffer(AbstractCode* code, SharedFunctionInfo* shared,
                          const char* name, int length) override;
+  void LogRecordedBuffer(const InstructionStream* stream, const char* name,
+                         int length) override;
 
   // Low-level profiling event structures.
   struct CodeCreateStruct {
@@ -386,6 +411,18 @@ void LowLevelLogger::LogRecordedBuffer(AbstractCode* code, SharedFunctionInfo*,
       code->instruction_size());
 }
 
+void LowLevelLogger::LogRecordedBuffer(const InstructionStream* stream,
+                                       const char* name, int length) {
+  CodeCreateStruct event;
+  event.name_size = length;
+  event.code_address = stream->bytes();
+  event.code_size = static_cast<int32_t>(stream->byte_length());
+  LogWriteStruct(event);
+  LogWriteBytes(name, length);
+  LogWriteBytes(reinterpret_cast<const char*>(stream->bytes()),
+                static_cast<int>(stream->byte_length()));
+}
+
 void LowLevelLogger::CodeMoveEvent(AbstractCode* from, Address to) {
   CodeMoveStruct event;
   event.from_address = from->instruction_start();
@@ -425,6 +462,8 @@ class JitLogger : public CodeEventLogger {
  private:
   void LogRecordedBuffer(AbstractCode* code, SharedFunctionInfo* shared,
                          const char* name, int length) override;
+  void LogRecordedBuffer(const InstructionStream* stream, const char* name,
+                         int length) override;
 
   JitCodeEventHandler code_event_handler_;
   base::Mutex logger_mutex_;
@@ -453,6 +492,20 @@ void JitLogger::LogRecordedBuffer(AbstractCode* code,
   code_event_handler_(&event);
 }
 
+void JitLogger::LogRecordedBuffer(const InstructionStream* stream,
+                                  const char* name, int length) {
+  JitCodeEvent event;
+  memset(&event, 0, sizeof(event));
+  event.type = JitCodeEvent::CODE_ADDED;
+  event.code_start = stream->bytes();
+  event.code_len = stream->byte_length();
+  Handle<SharedFunctionInfo> shared_function_handle;
+  event.script = ToApiHandle<v8::UnboundScript>(shared_function_handle);
+  event.name.str = name;
+  event.name.len = length;
+  code_event_handler_(&event);
+}
+
 void JitLogger::CodeMoveEvent(AbstractCode* from, Address to) {
   base::LockGuard<base::Mutex> guard(&logger_mutex_);
 
@@ -987,6 +1040,18 @@ void AppendCodeCreateHeader(Log::MessageBuilder& msg,
       << code->instruction_size() << Logger::kNext;
 }
 
+void AppendCodeCreateHeader(Log::MessageBuilder& msg,
+                            CodeEventListener::LogEventsAndTags tag,
+                            const InstructionStream* stream,
+                            base::ElapsedTimer* timer) {
+  // TODO(jgruber,v8:6666): In time, we'll need to support non-builtin streams.
+  msg << kLogEventsNames[CodeEventListener::CODE_CREATION_EVENT]
+      << Logger::kNext << kLogEventsNames[tag] << Logger::kNext << Code::BUILTIN
+      << Logger::kNext << timer->Elapsed().InMicroseconds() << Logger::kNext
+      << reinterpret_cast<void*>(stream->bytes()) << Logger::kNext
+      << stream->byte_length() << Logger::kNext;
+}
+
 }  // namespace
 
 void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
@@ -1174,6 +1239,17 @@ void Logger::RegExpCodeCreateEvent(AbstractCode* code, String* source) {
   msg.WriteToLogFile();
 }
 
+void Logger::InstructionStreamCreateEvent(LogEventsAndTags tag,
+                                          const InstructionStream* stream,
+                                          const char* description) {
+  if (!is_logging_code_events()) return;
+  if (!FLAG_log_code || !log_->IsEnabled()) return;
+  Log::MessageBuilder msg(log_);
+  AppendCodeCreateHeader(msg, tag, stream, &timer_);
+  msg << description;
+  msg.WriteToLogFile();
+}
+
 void Logger::CodeMoveEvent(AbstractCode* from, Address to) {
   if (!is_logging_code_events()) return;
   MoveEventInternal(CodeEventListener::CODE_MOVE_EVENT, from->address(), to);
@@ -1545,6 +1621,12 @@ void Logger::LogCodeObject(Object* object) {
   PROFILE(isolate_, CodeCreateEvent(tag, code_object, description));
 }
 
+void Logger::LogInstructionStream(Code* code, const InstructionStream* stream) {
+  DCHECK(Builtins::IsBuiltinId(code->builtin_index()));
+  const char* description = isolate_->builtins()->name(code->builtin_index());
+  CodeEventListener::LogEventsAndTags tag = CodeEventListener::BUILTIN_TAG;
+  PROFILE(isolate_, InstructionStreamCreateEvent(tag, stream, description));
+}
 
 void Logger::LogCodeObjects() {
   Heap* heap = isolate_->heap();

src/log.h

@@ -181,6 +181,9 @@ class Logger : public CodeEventListener {
   void CodeMovingGCEvent();
   // Emits a code create event for a RegExp.
   void RegExpCodeCreateEvent(AbstractCode* code, String* source);
+  void InstructionStreamCreateEvent(LogEventsAndTags tag,
+                                    const InstructionStream* stream,
+                                    const char* description);
   // Emits a code move event.
   void CodeMoveEvent(AbstractCode* from, Address to);
   // Emits a code line info record event.
@@ -257,6 +260,9 @@ class Logger : public CodeEventListener {
   // Used for logging stubs found in the snapshot.
   void LogCodeObject(Object* code_object);
 
+  // Used for logging off-heap instruction streams.
+  void LogInstructionStream(Code* code, const InstructionStream* stream);
+
  private:
   explicit Logger(Isolate* isolate);
   ~Logger();
@@ -380,7 +386,9 @@ class CodeEventLogger : public CodeEventListener {
                        SharedFunctionInfo* shared, Name* source, int line,
                        int column) override;
   void RegExpCodeCreateEvent(AbstractCode* code, String* source) override;
-
+  void InstructionStreamCreateEvent(LogEventsAndTags tag,
+                                    const InstructionStream* stream,
+                                    const char* description) override;
   void CallbackEvent(Name* name, Address entry_point) override {}
   void GetterCallbackEvent(Name* name, Address entry_point) override {}
   void SetterCallbackEvent(Name* name, Address entry_point) override {}
@@ -394,6 +402,8 @@ class CodeEventLogger : public CodeEventListener {
 
   virtual void LogRecordedBuffer(AbstractCode* code, SharedFunctionInfo* shared,
                                  const char* name, int length) = 0;
+  virtual void LogRecordedBuffer(const InstructionStream* stream,
+                                 const char* name, int length) = 0;
 
   NameBuffer* name_buffer_;
 };

src/perf-jit.cc

@@ -31,6 +31,7 @@
 
 #include "src/assembler.h"
 #include "src/eh-frame.h"
+#include "src/instruction-stream.h"
 #include "src/objects-inl.h"
 #include "src/source-position-table.h"
 
@@ -248,6 +249,42 @@ void PerfJitLogger::LogRecordedBuffer(AbstractCode* abstract_code,
   LogWriteBytes(reinterpret_cast<const char*>(code_pointer), code_size);
 }
 
+void PerfJitLogger::LogRecordedBuffer(const InstructionStream* stream,
+                                      const char* name, int length) {
+  if (FLAG_perf_basic_prof_only_functions) return;
+
+  base::LockGuard<base::RecursiveMutex> guard_file(file_mutex_.Pointer());
+
+  if (perf_output_handle_ == nullptr) return;
+
+  const char* code_name = name;
+  uint8_t* code_pointer = stream->bytes();
+  uint32_t code_size = static_cast<uint32_t>(stream->byte_length());
+
+  // TODO(jgruber): Do we need unwinding info?
+
+  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.time_stamp_ = GetTimestamp();
+  code_load.process_id_ =
+      static_cast<uint32_t>(base::OS::GetCurrentProcessId());
+  code_load.thread_id_ = static_cast<uint32_t>(base::OS::GetCurrentThreadId());
+  code_load.vma_ = 0x0;  //  Our addresses are absolute.
+  code_load.code_address_ = reinterpret_cast<uint64_t>(code_pointer);
+  code_load.code_size_ = code_size;
+  code_load.code_id_ = code_index_;
+
+  code_index_++;
+
+  LogWriteBytes(reinterpret_cast<const char*>(&code_load), sizeof(code_load));
+  LogWriteBytes(code_name, length);
+  LogWriteBytes(string_terminator, 1);
+  LogWriteBytes(reinterpret_cast<const char*>(code_pointer), code_size);
+}
+
 namespace {
 
 std::unique_ptr<char[]> GetScriptName(Handle<Script> script) {

src/perf-jit.h

@@ -54,6 +54,8 @@ class PerfJitLogger : public CodeEventLogger {
   uint64_t GetTimestamp();
   void LogRecordedBuffer(AbstractCode* code, SharedFunctionInfo* shared,
                          const char* name, int length) override;
+  void LogRecordedBuffer(const InstructionStream* stream, const char* name,
+                         int length) override;
 
   // Extension added to V8 log file name to get the low-level log name.
   static const char kFilenameFormatString[];
@@ -126,6 +128,11 @@ class PerfJitLogger : public CodeEventLogger {
                          const char* name, int length) override {
     UNIMPLEMENTED();
   }
+
+  void LogRecordedBuffer(const InstructionStream* stream, const char* name,
+                         int length) override {
+    UNIMPLEMENTED();
+  }
 };
 
 #endif  // V8_OS_LINUX

src/profiler/profiler-listener.cc

@@ -5,6 +5,7 @@
 #include "src/profiler/profiler-listener.h"
 
 #include "src/deoptimizer.h"
+#include "src/instruction-stream.h"
 #include "src/objects-inl.h"
 #include "src/profiler/cpu-profiler.h"
 #include "src/profiler/profile-generator-inl.h"
@@ -164,6 +165,20 @@ void ProfilerListener::RegExpCodeCreateEvent(AbstractCode* code,
   DispatchCodeEvent(evt_rec);
 }
 
+void ProfilerListener::InstructionStreamCreateEvent(
+    CodeEventListener::LogEventsAndTags tag, const InstructionStream* stream,
+    const char* description) {
+  CodeEventsContainer evt_rec(CodeEventRecord::CODE_CREATION);
+  CodeCreateEventRecord* rec = &evt_rec.CodeCreateEventRecord_;
+  rec->start = stream->bytes();
+  rec->entry = NewCodeEntry(
+      tag, description, CodeEntry::kEmptyNamePrefix,
+      CodeEntry::kEmptyResourceName, CpuProfileNode::kNoLineNumberInfo,
+      CpuProfileNode::kNoColumnNumberInfo, nullptr, stream->bytes());
+  rec->size = static_cast<unsigned>(stream->byte_length());
+  DispatchCodeEvent(evt_rec);
+}
+
 void ProfilerListener::SetterCallbackEvent(Name* name, Address entry_point) {
   CodeEventsContainer evt_rec(CodeEventRecord::CODE_CREATION);
   CodeCreateEventRecord* rec = &evt_rec.CodeCreateEventRecord_;

src/profiler/profiler-listener.h

@@ -45,6 +45,9 @@ class ProfilerListener : public CodeEventListener {
                       int fp_to_sp_delta) override;
   void GetterCallbackEvent(Name* name, Address entry_point) override;
   void RegExpCodeCreateEvent(AbstractCode* code, String* source) override;
+  void InstructionStreamCreateEvent(CodeEventListener::LogEventsAndTags tag,
+                                    const InstructionStream* stream,
+                                    const char* description) override;
   void SetterCallbackEvent(Name* name, Address entry_point) override;
   void SharedFunctionInfoMoveEvent(Address from, Address to) override {}
 

src/snapshot/serializer.h

@@ -7,6 +7,7 @@
 
 #include <map>
 
+#include "src/instruction-stream.h"
 #include "src/isolate.h"
 #include "src/log.h"
 #include "src/objects.h"
@@ -116,6 +117,10 @@ class CodeAddressMap : public CodeEventLogger {
                          const char* name, int length) override {
     address_to_name_map_.Insert(code->address(), name, length);
   }
+  void LogRecordedBuffer(const InstructionStream* stream, const char* name,
+                         int length) override {
+    address_to_name_map_.Insert(stream->bytes(), name, length);
+  }
 
   NameMap address_to_name_map_;
   Isolate* isolate_;

test/cctest/test-log.cc

@@ -53,6 +53,10 @@ using v8::internal::EmbeddedVector;
 using v8::internal::Logger;
 using v8::internal::StrLength;
 
+namespace internal {
+class InstructionStream;
+}
+
 namespace {
 
 
@@ -699,6 +703,8 @@ TEST(Issue539892) {
    private:
     void LogRecordedBuffer(i::AbstractCode* code, i::SharedFunctionInfo* shared,
                            const char* name, int length) override {}
+    void LogRecordedBuffer(const i::InstructionStream* stream, const char* name,
+                           int length) override {}
   } code_event_logger;
   SETUP_FLAGS();
   v8::Isolate::CreateParams create_params;