[cpu-profiler] Add source positions for inlined function calls

Currently in both kCallerLineNumbers and kLeafNodeLineNumbers modes, we
correctly capture inline stacks. In leaf number mode, this is simple as
we simply add the path onto the existing tree. For caller line numbers
mode this is more complex, because each path through various inlined
function should be represented in the tree, even when there are
multiple callsites to the same function inlined.

Currently we don't correctly show line numbers for inlined functions.
We do actually have this information though, which is generated by
turbofan and stored in the source_position_table data structure on the
code object.

This also changes the behavior of the SourcePositionTable class. A
problem we uncovered is that the PC that the sampler provides for every
frame except the leaf is the return address of the calling frame. This
address is *after* the call has already happened. It can be attributed
to the next line of the function, rather than the calling line, which
is wrong. We fix that here by using lower_bound in GetSourceLineNumber.

The same problem happens in GetInlineStack - the PC of the caller is
actually the instruction after the call. The information turbofan
generates assumes that the instruction after the call is not part of
the call (fair enough). To fix this we do the same thing as above - use
lower_bound and then iterate back by one.

TBR=alph@chromium.org

Bug: v8:8575, v8:8606
Change-Id: Idc4bd4bdc8fb70b70ecc1a77a1e3744a86f83483
Reviewed-on: https://chromium-review.googlesource.com/c/1374290
Commit-Queue: Peter Marshall <petermarshall@chromium.org>
Reviewed-by: Tobias Tebbi <tebbi@chromium.org>
Reviewed-by: Yang Guo <yangguo@chromium.org>
Cr-Commit-Position: refs/heads/master@{#58545}

src/profiler/profile-generator.cc

@@ -36,7 +36,7 @@ int SourcePositionTable::GetSourceLineNumber(int pc_offset) const {
     return v8::CpuProfileNode::kNoLineNumberInfo;
   }
   auto it =
-      std::upper_bound(pc_offsets_to_lines_.begin(), pc_offsets_to_lines_.end(),
+      std::lower_bound(pc_offsets_to_lines_.begin(), pc_offsets_to_lines_.end(),
                        PCOffsetAndLineNumber{pc_offset, 0});
   if (it != pc_offsets_to_lines_.begin()) --it;
   return it->line_number;
@@ -119,17 +119,17 @@ int CodeEntry::GetSourceLine(int pc_offset) const {
   return v8::CpuProfileNode::kNoLineNumberInfo;
 }
 
-void CodeEntry::AddInlineStack(
-    int pc_offset, std::vector<std::unique_ptr<CodeEntry>> inline_stack) {
+void CodeEntry::AddInlineStack(int pc_offset,
+                               std::vector<InlineEntry> inline_stack) {
   EnsureRareData()->inline_locations_.insert(
       std::make_pair(pc_offset, std::move(inline_stack)));
 }
 
-const std::vector<std::unique_ptr<CodeEntry>>* CodeEntry::GetInlineStack(
-    int pc_offset) const {
-  if (!rare_data_) return nullptr;
-  auto it = rare_data_->inline_locations_.find(pc_offset);
-  return it != rare_data_->inline_locations_.end() ? &it->second : nullptr;
+const std::vector<InlineEntry>* CodeEntry::GetInlineStack(int pc_offset) const {
+  if (!rare_data_ || rare_data_->inline_locations_.empty()) return nullptr;
+  auto it = rare_data_->inline_locations_.lower_bound(pc_offset);
+  if (it != rare_data_->inline_locations_.begin()) it--;
+  return it->second.empty() ? nullptr : &it->second;
 }
 
 void CodeEntry::set_deopt_info(
@@ -759,15 +759,16 @@ void ProfileGenerator::RecordTickSample(const TickSample& sample) {
         int pc_offset =
             static_cast<int>(stack_pos - entry->instruction_start());
         // TODO(petermarshall): pc_offset can still be negative in some cases.
-        const std::vector<std::unique_ptr<CodeEntry>>* inline_stack =
+        const std::vector<InlineEntry>* inline_stack =
             entry->GetInlineStack(pc_offset);
         if (inline_stack) {
-          std::transform(
-              inline_stack->rbegin(), inline_stack->rend(),
-              std::back_inserter(stack_trace),
-              [=](const std::unique_ptr<CodeEntry>& ptr) {
-                return CodeEntryAndLineNumber{ptr.get(), no_line_info};
-              });
+          std::transform(inline_stack->begin(), inline_stack->end(),
+                         std::back_inserter(stack_trace),
+                         [](const InlineEntry& inline_entry) {
+                           return CodeEntryAndLineNumber{
+                               inline_entry.code_entry.get(),
+                               inline_entry.call_line_number};
+                         });
         }
         // Skip unresolved frames (e.g. internal frame) and get source line of
         // the first JS caller.
@@ -779,6 +780,12 @@ void ProfileGenerator::RecordTickSample(const TickSample& sample) {
           src_line_not_found = false;
         }
         line_number = entry->GetSourceLine(pc_offset);
+
+        // The inline stack contains the top-level function i.e. the same
+        // function as entry. We don't want to add it twice. The one from the
+        // inline stack has the correct line number for this particular inlining
+        // so we use it instead of pushing entry to stack_trace.
+        if (inline_stack) continue;
       }
       stack_trace.push_back({entry, line_number});
     }

src/profiler/profile-generator.h

@@ -49,6 +49,8 @@ class SourcePositionTable : public Malloced {
   DISALLOW_COPY_AND_ASSIGN(SourcePositionTable);
 };
 
+struct InlineEntry;
+
 class CodeEntry {
  public:
   // CodeEntry doesn't own name strings, just references them.
@@ -103,10 +105,8 @@ class CodeEntry {
 
   int GetSourceLine(int pc_offset) const;
 
-  void AddInlineStack(int pc_offset,
-                      std::vector<std::unique_ptr<CodeEntry>> inline_stack);
-  const std::vector<std::unique_ptr<CodeEntry>>* GetInlineStack(
-      int pc_offset) const;
+  void AddInlineStack(int pc_offset, std::vector<InlineEntry> inline_stack);
+  const std::vector<InlineEntry>* GetInlineStack(int pc_offset) const;
 
   void set_instruction_start(Address start) { instruction_start_ = start; }
   Address instruction_start() const { return instruction_start_; }
@@ -141,8 +141,7 @@ class CodeEntry {
     const char* deopt_reason_ = kNoDeoptReason;
     const char* bailout_reason_ = kEmptyBailoutReason;
     int deopt_id_ = kNoDeoptimizationId;
-    std::unordered_map<int, std::vector<std::unique_ptr<CodeEntry>>>
-        inline_locations_;
+    std::map<int, std::vector<InlineEntry>> inline_locations_;
     std::vector<CpuProfileDeoptFrame> deopt_inlined_frames_;
   };
 
@@ -188,6 +187,15 @@ class CodeEntry {
   DISALLOW_COPY_AND_ASSIGN(CodeEntry);
 };
 
+// Used to store information about inline call stacks - call_line_number is the
+// line number within the function represented by code_entry. Inlining
+// inherently happens at callsites, so this line number will always be the call
+// to the next inline/noninline frame.
+struct InlineEntry {
+  std::unique_ptr<CodeEntry> code_entry;
+  int call_line_number;
+};
+
 struct CodeEntryAndLineNumber {
   CodeEntry* code_entry;
   int line_number;

src/profiler/profiler-listener.cc

@@ -201,52 +201,57 @@ void ProfilerListener::RecordInliningInfo(CodeEntry* entry,
   if (!abstract_code->IsCode()) return;
   Code code = abstract_code->GetCode();
   if (code->kind() != Code::OPTIMIZED_FUNCTION) return;
-  DeoptimizationData deopt_input_data =
-      DeoptimizationData::cast(code->deoptimization_data());
-  int deopt_count = deopt_input_data->DeoptCount();
-  for (int i = 0; i < deopt_count; i++) {
-    int pc_offset = deopt_input_data->Pc(i)->value();
-    if (pc_offset == -1) continue;
-    int translation_index = deopt_input_data->TranslationIndex(i)->value();
-    TranslationIterator it(deopt_input_data->TranslationByteArray(),
-                           translation_index);
-    Translation::Opcode opcode = static_cast<Translation::Opcode>(it.Next());
-    DCHECK_EQ(Translation::BEGIN, opcode);
-    it.Skip(Translation::NumberOfOperandsFor(opcode));
-    int depth = 0;
-    std::vector<std::unique_ptr<CodeEntry>> inline_stack;
-    while (it.HasNext() &&
-           Translation::BEGIN !=
-               (opcode = static_cast<Translation::Opcode>(it.Next()))) {
-      if (opcode != Translation::INTERPRETED_FRAME) {
-        it.Skip(Translation::NumberOfOperandsFor(opcode));
-        continue;
-      }
-      it.Next();  // Skip ast_id
-      int shared_info_id = it.Next();
-      it.Next();  // Skip height
-      it.Next();  // Skip return value offset
-      it.Next();  // Skip return value count
-      SharedFunctionInfo shared_info = SharedFunctionInfo::cast(
-          deopt_input_data->LiteralArray()->get(shared_info_id));
-      if (!depth++) continue;  // Skip the current function itself.
+
+  // Needed for InliningStack().
+  HandleScope scope(isolate_);
+  int last_inlining_id = -2;
+  for (SourcePositionTableIterator it(abstract_code->source_position_table());
+       !it.done(); it.Advance()) {
+    int code_offset = it.code_offset();
+
+    // Save space by not duplicating repeated entries that map to the same
+    // inlining ID. We might get multiple source positions per inlining ID, but
+    // they all map to the same line. This automatically collapses adjacent
+    // inlining stacks (or empty stacks) that are exactly the same.
+    if (it.source_position().InliningId() == last_inlining_id) continue;
+    last_inlining_id = it.source_position().InliningId();
+
+    // Only look at positions for inlined calls.
+    if (it.source_position().InliningId() == SourcePosition::kNotInlined) {
+      entry->AddInlineStack(code_offset, std::vector<InlineEntry>());
+      continue;
+    }
+
+    std::vector<SourcePositionInfo> stack =
+        it.source_position().InliningStack(handle(code, isolate_));
+    std::vector<InlineEntry> inline_stack;
+    for (SourcePositionInfo& pos_info : stack) {
+      if (pos_info.position.ScriptOffset() == kNoSourcePosition) continue;
+      if (pos_info.script.is_null()) continue;
+
+      int line_number =
+          pos_info.script->GetLineNumber(pos_info.position.ScriptOffset()) + 1;
 
       const char* resource_name =
-          (shared_info->script()->IsScript() &&
-           Script::cast(shared_info->script())->name()->IsName())
-              ? GetName(Name::cast(Script::cast(shared_info->script())->name()))
+          (pos_info.script->name()->IsName())
+              ? GetName(Name::cast(pos_info.script->name()))
               : CodeEntry::kEmptyResourceName;
 
-      CodeEntry* inline_entry =
-          new CodeEntry(entry->tag(), GetName(shared_info->DebugName()),
-                        resource_name, CpuProfileNode::kNoLineNumberInfo,
-                        CpuProfileNode::kNoColumnNumberInfo, nullptr,
-                        code->InstructionStart());
-      inline_entry->FillFunctionInfo(shared_info);
-      inline_stack.emplace_back(inline_entry);
+      // We need the start line number and column number of the function for
+      // kLeafNodeLineNumbers mode. Creating a SourcePositionInfo is a handy way
+      // of getting both easily.
+      SourcePositionInfo start_pos_info(
+          SourcePosition(pos_info.shared->StartPosition()), pos_info.shared);
+
+      std::unique_ptr<CodeEntry> inline_entry = base::make_unique<CodeEntry>(
+          entry->tag(), GetName(pos_info.shared->DebugName()), resource_name,
+          start_pos_info.line + 1, start_pos_info.column + 1, nullptr,
+          code->InstructionStart());
+      inline_entry->FillFunctionInfo(*pos_info.shared);
+      inline_stack.push_back(InlineEntry{std::move(inline_entry), line_number});
     }
     if (!inline_stack.empty()) {
-      entry->AddInlineStack(pc_offset, std::move(inline_stack));
+      entry->AddInlineStack(code_offset, std::move(inline_stack));
     }
   }
 }

src/source-position.cc

@@ -124,6 +124,7 @@ void SourcePosition::Print(std::ostream& out, Code code) const {
 SourcePositionInfo::SourcePositionInfo(SourcePosition pos,
                                        Handle<SharedFunctionInfo> f)
     : position(pos),
+      shared(f),
       script(f.is_null() || !f->script()->IsScript()
                  ? Handle<Script>::null()
                  : handle(Script::cast(f->script()), f->GetIsolate())) {

src/source-position.h

@@ -106,6 +106,7 @@ struct SourcePositionInfo {
   SourcePositionInfo(SourcePosition pos, Handle<SharedFunctionInfo> f);
 
   SourcePosition position;
+  Handle<SharedFunctionInfo> shared;
   Handle<Script> script;
   int line = -1;
   int column = -1;

test/cctest/test-cpu-profiler.cc

@@ -1701,6 +1701,116 @@ TEST(Inlining) {
   profile->Delete();
 }
 
+static const char* inlining_test_source2 = R"(
+    %NeverOptimizeFunction(action);
+    %NeverOptimizeFunction(start);
+    level1();
+    level1();
+    %OptimizeFunctionOnNextCall(level1);
+    %OptimizeFunctionOnNextCall(level2);
+    %OptimizeFunctionOnNextCall(level3);
+    %OptimizeFunctionOnNextCall(level4);
+    level1();
+    function action(n) {
+      var s = 0;
+      for (var i = 0; i < n; ++i) s += i*i*i;
+      return s;
+    }
+    function level4() {
+      return action(200);
+    }
+    function level3() {
+      const a = level4();
+      const b = level4();
+      return a + b * 1.1;
+    }
+    function level2() {
+      return level3() * 2;
+    }
+    function level1() {
+      action(1);
+      action(200);
+      action(1);
+      return level2();
+    }
+    function start(n) {
+      while (--n)
+        level1();
+    };
+  )";
+
+// The simulator builds are extremely slow. We run them with fewer iterations.
+#ifdef USE_SIMULATOR
+const double load_factor = 0.01;
+#else
+const double load_factor = 1.0;
+#endif
+
+// [Top down]:
+//     0  (root):0 0 #1
+//     1    start:33 6 #3
+//              bailed out due to 'Optimization disabled for test'
+//     5      level1:35 6 #4
+//     1        action:28 6 #12
+//                  bailed out due to 'Optimization disabled for test'
+//     3        action:30 6 #13
+//                  bailed out due to 'Optimization disabled for test'
+//     0        level2:31 6 #6
+//     0          level3:25 6 #7
+//     6            level4:20 6 #10
+//   251              action:17 6 #11
+//                        bailed out due to 'Optimization disabled for test'
+//     2            level4:21 6 #8
+//   238              action:17 6 #9
+//                        bailed out due to 'Optimization disabled for test'
+//   245        action:29 6 #5
+//                  bailed out due to 'Optimization disabled for test'
+//     2    (program):0 0 #2
+TEST(Inlining2) {
+  i::FLAG_allow_natives_syntax = true;
+  v8::HandleScope scope(CcTest::isolate());
+  v8::Local<v8::Context> env = CcTest::NewContext(PROFILER_EXTENSION);
+  v8::Context::Scope context_scope(env);
+
+  CompileRun(inlining_test_source2);
+  v8::Local<v8::Function> function = GetFunction(env, "start");
+
+  v8::CpuProfiler* profiler = v8::CpuProfiler::New(CcTest::isolate());
+  v8::Local<v8::String> profile_name = v8_str("inlining");
+  profiler->StartProfiling(profile_name,
+                           v8::CpuProfilingMode::kCallerLineNumbers);
+
+  v8::Local<v8::Value> args[] = {
+      v8::Integer::New(env->GetIsolate(), 50000 * load_factor)};
+  function->Call(env, env->Global(), arraysize(args), args).ToLocalChecked();
+  v8::CpuProfile* profile = profiler->StopProfiling(profile_name);
+  CHECK(profile);
+
+  // Dump collected profile to have a better diagnostic in case of failure.
+  reinterpret_cast<i::CpuProfile*>(profile)->Print();
+
+  const v8::CpuProfileNode* root = profile->GetTopDownRoot();
+  const v8::CpuProfileNode* start_node = GetChild(env, root, "start");
+
+  NameLinePair l4_18[] = {{"level1", 35},
+                          {"level2", 31},
+                          {"level3", 25},
+                          {"level4", 20},
+                          {"action", 17}};
+  CheckBranch(start_node, l4_18, arraysize(l4_18));
+  NameLinePair l4_19[] = {{"level1", 35},
+                          {"level2", 31},
+                          {"level3", 25},
+                          {"level4", 21},
+                          {"action", 17}};
+  CheckBranch(start_node, l4_19, arraysize(l4_19));
+  NameLinePair action_direct[] = {{"level1", 35}, {"action", 29}};
+  CheckBranch(start_node, action_direct, arraysize(action_direct));
+
+  profile->Delete();
+  profiler->Dispose();
+}
+
 // [Top down]:
 //     0   (root) #0 1
 //     2    (program) #0 2
@@ -1885,7 +1995,7 @@ TEST(FunctionDetailsInlining) {
   const v8::CpuProfileNode* beta = FindChild(env, alpha, "beta");
   if (!beta) return;
   CheckFunctionDetails(env->GetIsolate(), beta, "beta", "script_b",
-                       script_b->GetUnboundScript()->GetId(), 0, 0);
+                       script_b->GetUnboundScript()->GetId(), 1, 14);
 }
 
 TEST(DontStopOnFinishedProfileDelete) {
@@ -2528,7 +2638,7 @@ TEST(SourcePositionTable) {
   CHECK_EQ(1, info.GetSourceLineNumber(10));
   CHECK_EQ(1, info.GetSourceLineNumber(11));
   CHECK_EQ(1, info.GetSourceLineNumber(19));
-  CHECK_EQ(2, info.GetSourceLineNumber(20));
+  CHECK_EQ(1, info.GetSourceLineNumber(20));
   CHECK_EQ(2, info.GetSourceLineNumber(21));
   CHECK_EQ(2, info.GetSourceLineNumber(100));
   CHECK_EQ(2, info.GetSourceLineNumber(std::numeric_limits<int>::max()));