[profiling] Improve perf-jit logger performance

- Cache process-id as process-static variable
- Only extract the script name once per SFI

Change-Id: I4549c2a3849d57dbcfa115401719e22422cfac6a
Reviewed-on: https://chromium-review.googlesource.com/c/v8/v8/+/3477113Reviewed-by: Victor Gomes <victorgomes@chromium.org>
Commit-Queue: Camillo Bruni <cbruni@chromium.org>
Cr-Commit-Position: refs/heads/main@{#79206}

src/codegen/source-position.cc

@@ -62,24 +62,40 @@ std::vector<SourcePositionInfo> SourcePosition::InliningStack(
 std::vector<SourcePositionInfo> SourcePosition::InliningStack(
     Handle<Code> code) const {
   Isolate* isolate = code->GetIsolate();
-  Handle<DeoptimizationData> deopt_data(
-      DeoptimizationData::cast(code->deoptimization_data()), isolate);
+  DeoptimizationData deopt_data =
+      DeoptimizationData::cast(code->deoptimization_data());
   SourcePosition pos = *this;
   std::vector<SourcePositionInfo> stack;
   while (pos.isInlined()) {
-    InliningPosition inl =
-        deopt_data->InliningPositions().get(pos.InliningId());
+    InliningPosition inl = deopt_data.InliningPositions().get(pos.InliningId());
     Handle<SharedFunctionInfo> function(
-        deopt_data->GetInlinedFunction(inl.inlined_function_id), isolate);
+        deopt_data.GetInlinedFunction(inl.inlined_function_id), isolate);
     stack.push_back(SourcePositionInfo(pos, function));
     pos = inl.position;
   }
   Handle<SharedFunctionInfo> function(
-      SharedFunctionInfo::cast(deopt_data->SharedFunctionInfo()), isolate);
+      SharedFunctionInfo::cast(deopt_data.SharedFunctionInfo()), isolate);
   stack.push_back(SourcePositionInfo(pos, function));
   return stack;
 }
 
+SourcePositionInfo SourcePosition::FirstInfo(Handle<Code> code) const {
+  DisallowGarbageCollection no_gc;
+  Isolate* isolate = code->GetIsolate();
+  DeoptimizationData deopt_data =
+      DeoptimizationData::cast(code->deoptimization_data());
+  SourcePosition pos = *this;
+  if (pos.isInlined()) {
+    InliningPosition inl = deopt_data.InliningPositions().get(pos.InliningId());
+    Handle<SharedFunctionInfo> function(
+        deopt_data.GetInlinedFunction(inl.inlined_function_id), isolate);
+    return SourcePositionInfo(pos, function);
+  }
+  Handle<SharedFunctionInfo> function(
+      SharedFunctionInfo::cast(deopt_data.SharedFunctionInfo()), isolate);
+  return SourcePositionInfo(pos, function);
+}
+
 void SourcePosition::Print(std::ostream& out,
                            SharedFunctionInfo function) const {
   Script::PositionInfo pos;

src/codegen/source-position.h

@@ -84,6 +84,7 @@ class SourcePosition final {
   std::vector<SourcePositionInfo> InliningStack(Handle<Code> code) const;
   std::vector<SourcePositionInfo> InliningStack(
       OptimizedCompilationInfo* cinfo) const;
+  SourcePositionInfo FirstInfo(Handle<Code> code) const;
 
   void Print(std::ostream& out, Code code) const;
   void PrintJson(std::ostream& out) const;

src/diagnostics/perf-jit.cc

@@ -116,10 +116,12 @@ const char PerfJitLogger::kFilenameFormatString[] = "./jit-%d.dump";
 // Extra padding for the PID in the filename
 const int PerfJitLogger::kFilenameBufferPadding = 16;
 
-static const char kStringTerminator[] = "\0";
+static const char kStringTerminator[] = {'\0'};
+static const char kRepeatedNameMarker[] = {'\xff', '\0'};
 
 base::LazyRecursiveMutex PerfJitLogger::file_mutex_;
 // The following static variables are protected by PerfJitLogger::file_mutex_.
+int PerfJitLogger::process_id_ = 0;
 uint64_t PerfJitLogger::reference_count_ = 0;
 void* PerfJitLogger::marker_address_ = nullptr;
 uint64_t PerfJitLogger::code_index_ = 0;
@@ -131,8 +133,7 @@ void PerfJitLogger::OpenJitDumpFile() {
 
   int bufferSize = sizeof(kFilenameFormatString) + kFilenameBufferPadding;
   base::ScopedVector<char> perf_dump_name(bufferSize);
-  int size = SNPrintF(perf_dump_name, kFilenameFormatString,
-                      base::OS::GetCurrentProcessId());
+  int size = SNPrintF(perf_dump_name, kFilenameFormatString, process_id_);
   CHECK_NE(size, -1);
 
   int fd = open(perf_dump_name.begin(), O_CREAT | O_TRUNC | O_RDWR, 0666);
@@ -179,6 +180,7 @@ void PerfJitLogger::CloseMarkerFile(void* marker_address) {
 
 PerfJitLogger::PerfJitLogger(Isolate* isolate) : CodeEventLogger(isolate) {
   base::LockGuard<base::RecursiveMutex> guard_file(file_mutex_.Pointer());
+  process_id_ = base::OS::GetCurrentProcessId();
 
   reference_count_++;
   // If this is the first logger, open the file and write the header.
@@ -255,9 +257,7 @@ void PerfJitLogger::LogRecordedBuffer(const wasm::WasmCode* code,
 
   if (perf_output_handle_ == nullptr) return;
 
-  if (FLAG_perf_prof_annotate_wasm) {
-    LogWriteDebugInfo(code);
-  }
+  if (FLAG_perf_prof_annotate_wasm) LogWriteDebugInfo(code);
 
   WriteJitCodeLoadEntry(code->instructions().begin(),
                         code->instructions().length(), name, length);
@@ -271,8 +271,7 @@ void PerfJitLogger::WriteJitCodeLoadEntry(const uint8_t* code_pointer,
   code_load.event_ = PerfJitCodeLoad::kLoad;
   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());
+  code_load.process_id_ = static_cast<uint32_t>(process_id_);
   code_load.thread_id_ = static_cast<uint32_t>(base::OS::GetCurrentThreadId());
   code_load.vma_ = reinterpret_cast<uint64_t>(code_pointer);
   code_load.code_address_ = reinterpret_cast<uint64_t>(code_pointer);
@@ -283,7 +282,7 @@ void PerfJitLogger::WriteJitCodeLoadEntry(const uint8_t* code_pointer,
 
   LogWriteBytes(reinterpret_cast<const char*>(&code_load), sizeof(code_load));
   LogWriteBytes(name, name_length);
-  LogWriteBytes(kStringTerminator, 1);
+  LogWriteBytes(kStringTerminator, sizeof(kStringTerminator));
   LogWriteBytes(reinterpret_cast<const char*>(code_pointer), code_size);
 }
 
@@ -293,25 +292,12 @@ constexpr char kUnknownScriptNameString[] = "<unknown>";
 constexpr size_t kUnknownScriptNameStringLen =
     arraysize(kUnknownScriptNameString) - 1;
 
-size_t GetScriptNameLength(const SourcePositionInfo& info) {
-  if (!info.script.is_null()) {
-    Object name_or_url = info.script->GetNameOrSourceURL();
-    if (name_or_url.IsString()) {
-      String str = String::cast(name_or_url);
-      if (str.IsOneByteRepresentation()) return str.length();
-      int length;
-      str.ToCString(DISALLOW_NULLS, FAST_STRING_TRAVERSAL, &length);
-      return static_cast<size_t>(length);
-    }
-  }
-  return kUnknownScriptNameStringLen;
-}
-
-base::Vector<const char> GetScriptName(const SourcePositionInfo& info,
+namespace {
+base::Vector<const char> GetScriptName(Object maybeScript,
                                        std::unique_ptr<char[]>* storage,
                                        const DisallowGarbageCollection& no_gc) {
-  if (!info.script.is_null()) {
-    Object name_or_url = info.script->GetNameOrSourceURL();
+  if (maybeScript.IsScript()) {
+    Object name_or_url = Script::cast(maybeScript).GetNameOrSourceURL();
     if (name_or_url.IsSeqOneByteString()) {
       SeqOneByteString str = SeqOneByteString::cast(name_or_url);
       return {reinterpret_cast<char*>(str.GetChars(no_gc)),
@@ -326,12 +312,14 @@ base::Vector<const char> GetScriptName(const SourcePositionInfo& info,
   return {kUnknownScriptNameString, kUnknownScriptNameStringLen};
 }
 
+}  // namespace
+
 SourcePositionInfo GetSourcePositionInfo(Handle<Code> code,
                                          Handle<SharedFunctionInfo> function,
                                          SourcePosition pos) {
+  DisallowGarbageCollection disallow;
   if (code->is_turbofanned()) {
-    DisallowGarbageCollection disallow;
-    return pos.InliningStack(code)[0];
+    return pos.FirstInfo(code);
   } else {
     return SourcePositionInfo(pos, function);
   }
@@ -341,38 +329,47 @@ SourcePositionInfo GetSourcePositionInfo(Handle<Code> code,
 
 void PerfJitLogger::LogWriteDebugInfo(Handle<Code> code,
                                       Handle<SharedFunctionInfo> shared) {
+  // Line ends of all scripts have been initialized prior to this.
   DisallowGarbageCollection no_gc;
-  // TODO(v8:11429,cbruni): add proper baseline source position iterator
+  // The WasmToJS wrapper stubs have source position entries.
+  if (!shared->HasSourceCode()) return;
+
+  PerfJitCodeDebugInfo debug_info;
+  uint32_t size = sizeof(debug_info);
+
   ByteArray source_position_table = code->SourcePositionTable(*shared);
-  // Compute the entry count and get the name of the script.
+  // Compute the entry count and get the names of all scripts.
+  // Avoid additional work if the script name is repeated. Multiple script
+  // names only occur for cross-script inlining.
   uint32_t entry_count = 0;
+  Object last_script = Smi::zero();
+  std::vector<base::Vector<const char>> script_names;
   for (SourcePositionTableIterator iterator(source_position_table);
        !iterator.done(); iterator.Advance()) {
+    SourcePositionInfo info(
+        GetSourcePositionInfo(code, shared, iterator.source_position()));
+    Object current_script = *info.script;
+    if (current_script != last_script) {
+      std::unique_ptr<char[]> name_storage;
+      auto name = GetScriptName(shared->script(), &name_storage, no_gc);
+      script_names.push_back(name);
+      // Add the size of the name after each entry.
+      size += name.size() + sizeof(kStringTerminator);
+      last_script = current_script;
+    } else {
+      size += sizeof(kRepeatedNameMarker);
+    }
     entry_count++;
   }
   if (entry_count == 0) return;
-  // The WasmToJS wrapper stubs have source position entries.
-  if (!shared->HasSourceCode()) return;
-  Handle<Script> script(Script::cast(shared->script()), isolate_);
-
-  PerfJitCodeDebugInfo debug_info;
 
   debug_info.event_ = PerfJitCodeLoad::kDebugInfo;
   debug_info.time_stamp_ = GetTimestamp();
   debug_info.address_ = code->InstructionStart();
   debug_info.entry_count_ = entry_count;
 
-  uint32_t size = sizeof(debug_info);
   // Add the sizes of fixed parts of entries.
   size += entry_count * sizeof(PerfJitDebugEntry);
-  // Add the size of the name after each entry.
-
-  for (SourcePositionTableIterator iterator(source_position_table);
-       !iterator.done(); iterator.Advance()) {
-    SourcePositionInfo info(
-        GetSourcePositionInfo(code, shared, iterator.source_position()));
-    size += GetScriptNameLength(info) + 1;
-  }
 
   int padding = ((size + 7) & (~7)) - size;
   debug_info.size_ = size + padding;
@@ -380,6 +377,8 @@ void PerfJitLogger::LogWriteDebugInfo(Handle<Code> code,
 
   Address code_start = code->InstructionStart();
 
+  last_script = Smi::zero();
+  int script_names_index = 0;
   for (SourcePositionTableIterator iterator(source_position_table);
        !iterator.done(); iterator.Advance()) {
     SourcePositionInfo info(
@@ -392,12 +391,18 @@ void PerfJitLogger::LogWriteDebugInfo(Handle<Code> code,
     entry.line_number_ = info.line + 1;
     entry.column_ = info.column + 1;
     LogWriteBytes(reinterpret_cast<const char*>(&entry), sizeof(entry));
-    std::unique_ptr<char[]> name_storage;
-    base::Vector<const char> name_string =
-        GetScriptName(info, &name_storage, no_gc);
-    LogWriteBytes(name_string.begin(),
-                  static_cast<uint32_t>(name_string.size()));
-    LogWriteBytes(kStringTerminator, 1);
+    Object current_script = *info.script;
+    if (current_script != last_script) {
+      auto name_string = script_names[script_names_index];
+      LogWriteBytes(name_string.begin(),
+                    static_cast<uint32_t>(name_string.size()));
+      LogWriteBytes(kStringTerminator, sizeof(kStringTerminator));
+      script_names_index++;
+      last_script = current_script;
+    } else {
+      // Use the much shorter kRepeatedNameMarker for repeated names.
+      LogWriteBytes(kRepeatedNameMarker, sizeof(kRepeatedNameMarker));
+    }
   }
   char padding_bytes[8] = {0};
   LogWriteBytes(padding_bytes, padding);
@@ -464,7 +469,7 @@ void PerfJitLogger::LogWriteDebugInfo(const wasm::WasmCode* code) {
     LogWriteBytes(reinterpret_cast<const char*>(&entry), sizeof(entry));
     std::string name_string = source_map->GetFilename(offset);
     LogWriteBytes(name_string.c_str(), static_cast<int>(name_string.size()));
-    LogWriteBytes(kStringTerminator, 1);
+    LogWriteBytes(kStringTerminator, sizeof(kStringTerminator));
   }
 
   char padding_bytes[8] = {0};
@@ -528,7 +533,7 @@ void PerfJitLogger::LogWriteHeader() {
   header.size_ = sizeof(header);
   header.elf_mach_target_ = GetElfMach();
   header.reserved_ = 0xDEADBEEF;
-  header.process_id_ = base::OS::GetCurrentProcessId();
+  header.process_id_ = process_id_;
   header.time_stamp_ =
       static_cast<uint64_t>(V8::GetCurrentPlatform()->CurrentClockTimeMillis() *
                             base::Time::kMicrosecondsPerMillisecond);

src/diagnostics/perf-jit.h

@@ -135,6 +135,7 @@ class PerfJitLogger : public CodeEventLogger {
   static uint64_t reference_count_;
   static void* marker_address_;
   static uint64_t code_index_;
+  static int process_id_;
 };
 
 }  // namespace internal