Extend CPU profiler with mapping ticks to source lines

src/profile-generator.cc

 // Copyright 2012 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.
 
 #include "src/v8.h"
 
 #include "src/profile-generator-inl.h"
 
 #include "src/compiler.h"
 #include "src/debug.h"
@@ skipping 121 matching lines @@
 }
 
 
 const char* const CodeEntry::kEmptyNamePrefix = "";
 const char* const CodeEntry::kEmptyResourceName = "";
 const char* const CodeEntry::kEmptyBailoutReason = "";
 
 
 CodeEntry::~CodeEntry() {
   delete no_frame_ranges_;
+  delete line_info_;
 }
 
 
 uint32_t CodeEntry::GetCallUid() const {
   uint32_t hash = ComputeIntegerHash(tag_, v8::internal::kZeroHashSeed);
   if (shared_id_ != 0) {
     hash ^= ComputeIntegerHash(static_cast<uint32_t>(shared_id_),
                                v8::internal::kZeroHashSeed);
   } else {
     hash ^= ComputeIntegerHash(
@@ skipping 22 matching lines @@
                   && line_number_ == entry->line_number_)));
 }
 
 
 void CodeEntry::SetBuiltinId(Builtins::Name id) {
   tag_ = Logger::BUILTIN_TAG;
   builtin_id_ = id;
 }
 
 
+int CodeEntry::GetSourceLine(int pc_offset) const {
+  if (line_info_ && !line_info_->Empty()) {
+    return line_info_->GetSourceLineNumber(pc_offset);
+  }
+  return v8::CpuProfileNode::kNoLineNumberInfo;
+}
+
+
 ProfileNode* ProfileNode::FindChild(CodeEntry* entry) {
   HashMap::Entry* map_entry =
       children_.Lookup(entry, CodeEntryHash(entry), false);
   return map_entry != NULL ?
       reinterpret_cast<ProfileNode*>(map_entry->value) : NULL;
 }
 
 
 ProfileNode* ProfileNode::FindOrAddChild(CodeEntry* entry) {
   HashMap::Entry* map_entry =
       children_.Lookup(entry, CodeEntryHash(entry), true);
   if (map_entry->value == NULL) {
     // New node added.
     ProfileNode* new_node = new ProfileNode(tree_, entry);
     map_entry->value = new_node;
     children_list_.Add(new_node);
   }
   return reinterpret_cast<ProfileNode*>(map_entry->value);
 }
 
 
+void ProfileNode::IncrementLineTicks(int src_line) {
+  if (src_line == v8::CpuProfileNode::kNoLineNumberInfo) return;
+  // Increment a hit counter of a certain source line.
+  // Add a new source line if not found.
+  HashMap::Entry* e =
+      line_ticks_.Lookup(reinterpret_cast<void*>(src_line), src_line, true);
+  DCHECK(e);
+  e->value = reinterpret_cast<void*>(reinterpret_cast<uintptr_t>(e->value) + 1);
+}
+
+
+bool ProfileNode::GetLineTicks(v8::CpuProfileNode::LineTick* entries,
+                               unsigned int length) const {
+  if (entries == NULL || length == 0) return false;
+
+  unsigned line_count = line_ticks_.occupancy();
+
+  if (line_count == 0) return false;
+  if (length < line_count) return false;
+
+  v8::CpuProfileNode::LineTick* entry = entries;
+
+  for (HashMap::Entry* p = line_ticks_.Start(); p != NULL;
+       p = line_ticks_.Next(p), entry++) {
+    entry->line =
+        static_cast<unsigned int>(reinterpret_cast<uintptr_t>(p->key));
+    entry->hit_count =
+        static_cast<unsigned int>(reinterpret_cast<uintptr_t>(p->value));
+  }
+
+  return true;
+}
+
+
 void ProfileNode::Print(int indent) {
   base::OS::Print("%5u %*s %s%s %d #%d %s", self_ticks_, indent, "",
                   entry_->name_prefix(), entry_->name(), entry_->script_id(),
                   id(), entry_->bailout_reason());
   if (entry_->resource_name()[0] != '\0')
     base::OS::Print(" %s:%d", entry_->resource_name(), entry_->line_number());
   base::OS::Print("\n");
   for (HashMap::Entry* p = children_.Start();
        p != NULL;
        p = children_.Next(p)) {
@@ skipping 20 matching lines @@
       root_(new ProfileNode(this, &root_entry_)) {
 }
 
 
 ProfileTree::~ProfileTree() {
   DeleteNodesCallback cb;
   TraverseDepthFirst(&cb);
 }
 
 
-ProfileNode* ProfileTree::AddPathFromEnd(const Vector<CodeEntry*>& path) {
+ProfileNode* ProfileTree::AddPathFromEnd(const Vector<CodeEntry*>& path,
+                                         int src_line) {
   ProfileNode* node = root_;
   for (CodeEntry** entry = path.start() + path.length() - 1;
        entry != path.start() - 1;
        --entry) {
     if (*entry != NULL) {
       node = node->FindOrAddChild(*entry);
     }
   }
   node->IncrementSelfTicks();
+  if (src_line != v8::CpuProfileNode::kNoLineNumberInfo) {
+    node->IncrementLineTicks(src_line);
+  }
   return node;
 }
 
 
-void ProfileTree::AddPathFromStart(const Vector<CodeEntry*>& path) {
+void ProfileTree::AddPathFromStart(const Vector<CodeEntry*>& path,
+                                   int src_line) {
   ProfileNode* node = root_;
   for (CodeEntry** entry = path.start();
        entry != path.start() + path.length();
        ++entry) {
     if (*entry != NULL) {
       node = node->FindOrAddChild(*entry);
     }
   }
   node->IncrementSelfTicks();
+  if (src_line != v8::CpuProfileNode::kNoLineNumberInfo) {
+    node->IncrementLineTicks(src_line);
+  }
 }
 
 
 struct NodesPair {
   NodesPair(ProfileNode* src, ProfileNode* dst)
       : src(src), dst(dst) { }
   ProfileNode* src;
   ProfileNode* dst;
 };
 
@@ skipping 41 matching lines @@
 
 
 CpuProfile::CpuProfile(const char* title, bool record_samples)
     : title_(title),
       record_samples_(record_samples),
       start_time_(base::TimeTicks::HighResolutionNow()) {
 }
 
 
 void CpuProfile::AddPath(base::TimeTicks timestamp,
-                         const Vector<CodeEntry*>& path) {
-  ProfileNode* top_frame_node = top_down_.AddPathFromEnd(path);
+                         const Vector<CodeEntry*>& path, int src_line) {
+  ProfileNode* top_frame_node = top_down_.AddPathFromEnd(path, src_line);
   if (record_samples_) {
     timestamps_.Add(timestamp);
     samples_.Add(top_frame_node);
   }
 }
 
 
 void CpuProfile::CalculateTotalTicksAndSamplingRate() {
   end_time_ = base::TimeTicks::HighResolutionNow();
 }
@@ skipping 168 matching lines @@
     if (profile == finished_profiles_[i]) {
       finished_profiles_.Remove(i);
       return;
     }
   }
   UNREACHABLE();
 }
 
 
 void CpuProfilesCollection::AddPathToCurrentProfiles(
-    base::TimeTicks timestamp, const Vector<CodeEntry*>& path) {
+    base::TimeTicks timestamp, const Vector<CodeEntry*>& path, int src_line) {
   // As starting / stopping profiles is rare relatively to this
   // method, we don't bother minimizing the duration of lock holding,
   // e.g. copying contents of the list to a local vector.
   current_profiles_semaphore_.Wait();
   for (int i = 0; i < current_profiles_.length(); ++i) {
-    current_profiles_[i]->AddPath(timestamp, path);
+    current_profiles_[i]->AddPath(timestamp, path, src_line);
   }
   current_profiles_semaphore_.Signal();
 }
 
 
 CodeEntry* CpuProfilesCollection::NewCodeEntry(
-      Logger::LogEventsAndTags tag,
-      const char* name,
-      const char* name_prefix,
-      const char* resource_name,
-      int line_number,
-      int column_number) {
-  CodeEntry* code_entry = new CodeEntry(tag,
-                                        name,
-                                        name_prefix,
-                                        resource_name,
-                                        line_number,
-                                        column_number);
+    Logger::LogEventsAndTags tag, const char* name, const char* name_prefix,
+    const char* resource_name, int line_number, int column_number,
+    JITLineInfoTable* line_info) {
+  CodeEntry* code_entry = new CodeEntry(tag, name, name_prefix, resource_name,
+                                        line_number, column_number, line_info);
   code_entries_.Add(code_entry);
   return code_entry;
 }
 
 
 const char* const ProfileGenerator::kProgramEntryName =
     "(program)";
 const char* const ProfileGenerator::kIdleEntryName =
     "(idle)";
 const char* const ProfileGenerator::kGarbageCollectorEntryName =
@@ skipping 17 matching lines @@
 }
 
 
 void ProfileGenerator::RecordTickSample(const TickSample& sample) {
   // Allocate space for stack frames + pc + function + vm-state.
   ScopedVector<CodeEntry*> entries(sample.frames_count + 3);
   // As actual number of decoded code entries may vary, initialize
   // entries vector with NULL values.
   CodeEntry** entry = entries.start();
   memset(entry, 0, entries.length() * sizeof(*entry));
+
+  // The ProfileNode knows nothing about all versions of generated code for
+  // the same JS function. The line number information associated with
+  // the latest version of generated code is used to find a source line number
+  // for a JS function. Then, the detected source line is passed to
+  // ProfileNode to accumulate the samples.
+  int src_line = v8::CpuProfileNode::kNoLineNumberInfo;
+
   if (sample.pc != NULL) {
     if (sample.has_external_callback && sample.state == EXTERNAL &&
         sample.top_frame_type == StackFrame::EXIT) {
       // Don't use PC when in external callback code, as it can point
       // inside callback's code, and we will erroneously report
       // that a callback calls itself.
       *entry++ = code_map_.FindEntry(sample.external_callback);
     } else {
       Address start;
       CodeEntry* pc_entry = code_map_.FindEntry(sample.pc, &start);
       // If pc is in the function code before it set up stack frame or after the
       // frame was destroyed SafeStackFrameIterator incorrectly thinks that
       // ebp contains return address of the current function and skips caller's
       // frame. Check for this case and just skip such samples.
       if (pc_entry) {
         List<OffsetRange>* ranges = pc_entry->no_frame_ranges();
+        Code* code = Code::cast(HeapObject::FromAddress(start));
+        int pc_offset = static_cast<int>(sample.pc - code->instruction_start());
+        src_line = pc_entry->GetSourceLine(pc_offset);

[yurys, 2014/09/10 08:05:14]

nit: move assignment to src_line after the "if" below.

         if (ranges) {
-          Code* code = Code::cast(HeapObject::FromAddress(start));
-          int pc_offset = static_cast<int>(
-              sample.pc - code->instruction_start());
           for (int i = 0; i < ranges->length(); i++) {
             OffsetRange& range = ranges->at(i);
             if (range.from <= pc_offset && pc_offset < range.to) {
               return;
             }
           }
         }
         *entry++ = pc_entry;
 
         if (pc_entry->builtin_id() == Builtins::kFunctionCall ||
             pc_entry->builtin_id() == Builtins::kFunctionApply) {
           // When current function is FunctionCall or FunctionApply builtin the
           // top frame is either frame of the calling JS function or internal
           // frame. In the latter case we know the caller for sure but in the
           // former case we don't so we simply replace the frame with
           // 'unresolved' entry.
           if (sample.top_frame_type == StackFrame::JAVA_SCRIPT) {
             *entry++ = unresolved_entry_;
           }
         }
       }
     }
 
+    bool src_line_not_found = src_line == v8::CpuProfileNode::kNoLineNumberInfo;
+
     for (const Address* stack_pos = sample.stack,
            *stack_end = stack_pos + sample.frames_count;
          stack_pos != stack_end;
          ++stack_pos) {
-      *entry++ = code_map_.FindEntry(*stack_pos);
+      Address start = NULL;
+      *entry = code_map_.FindEntry(*stack_pos, &start);
+
+      // Skip unresolved frames (e.g. internal frame) and get source line of
+      // the JS caller.
+      if (src_line_not_found && *entry) {

[yurys, 2014/09/10 08:05:14]

With this approach we may end up with top entry being pc_entry while src_line
will be calculated for another entry which is wrong. We should also check here
that current entry is the first one non-null in the path.

[Denis Pravdin, 2014/09/11 08:14:44]

pc_offset that used to calculate src_line is taken for the first non-null entry
in the path only. Exactly this entry will represent a node in profile (when the
path and src_line go to AddPathToCurrentProfiles).

[yurys, 2014/09/12 13:46:28]

If src_line = pc_entry->GetSourceLine(pc_offset); (line 652) returns
kNoLineNumberInfo you will end up calculating line number for the first non-null
entry after it here. This will result in entries = [pc_entry, entry1,
entry2,...NULL] and src_line calculated for entry1 or am I missing something?

+        Code* code = Code::cast(HeapObject::FromAddress(start));
+        int pc_offset =
+            static_cast<int>(*stack_pos - code->instruction_start());
+        src_line = (*entry)->GetSourceLine(pc_offset);
+        if (src_line == v8::CpuProfileNode::kNoLineNumberInfo) {
+          src_line = (*entry)->line_number();
+        }
+        src_line_not_found = false;
+      }
+
+      entry++;
     }
   }
 
   if (FLAG_prof_browser_mode) {
     bool no_symbolized_entries = true;
     for (CodeEntry** e = entries.start(); e != entry; ++e) {
       if (*e != NULL) {
         no_symbolized_entries = false;
         break;
       }
     }
     // If no frames were symbolized, put the VM state entry in.
     if (no_symbolized_entries) {
       *entry++ = EntryForVMState(sample.state);
     }
   }
 
-  profiles_->AddPathToCurrentProfiles(sample.timestamp, entries);
+  profiles_->AddPathToCurrentProfiles(sample.timestamp, entries, src_line);
 }
 
 
 CodeEntry* ProfileGenerator::EntryForVMState(StateTag tag) {
   switch (tag) {
     case GC:
       return gc_entry_;
     case JS:
     case COMPILER:
     // DOM events handlers are reported as OTHER / EXTERNAL entries.
     // To avoid confusing people, let's put all these entries into
     // one bucket.
     case OTHER:
     case EXTERNAL:
       return program_entry_;
     case IDLE:
       return idle_entry_;
     default: return NULL;
   }
 }
 
 } }  // namespace v8::internal