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 189 matching lines @@
   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);
+  if (NULL != e) {

[alph, 2014/07/29 12:55:56]

It couldn't be NULL if insert arg is true.
style: move const to the right hand side

+    e->value = static_cast<char*>(e->value) + 1;

[alph, 2014/07/29 12:55:56]

why char*? uintptr_t?

[yurys, 2014/07/29 13:15:10]

intptr_t

+  }
+}
+
+
+bool ProfileNode::GetLineTicks(LineTick* entries,
+                               unsigned int number) const {
+  if (NULL == entries || number == 0) {

[alph, 2014/07/29 12:55:56]

ditto

+    return false;
+  }
+
+  unsigned lineNumber = line_ticks_.occupancy();
+  if (lineNumber == 0) return false;

[alph, 2014/07/29 12:55:56]

should return true.

+  if (number < lineNumber) return false;
+
+  LineTick* entry = entries;
+
+  for (HashMap::Entry* p = line_ticks_.Start();
+       p != NULL;
+       p = line_ticks_.Next(p), entry++) {
+    entry->line = reinterpret_cast<intptr_t>(p->key);

[alph, 2014/07/29 12:55:56]

entry->line is unsigned int, i.e. 32 bits. So it should produce a compile error
on x64 (for sure on Win64).

+    entry->ticks = reinterpret_cast<intptr_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) {

[yurys, 2014/07/29 13:15:10]

It seems that with per line self tick count it would make sense to also collect
per line total tick counts for each function so that the user can tell how many
ticks we spent inside particular call. In other words we may need src_line for
all frames not only the topmost one. This is a topic for a separate patch
though.

+  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) {
+      int column_number,
+      JITLineInfoTable* line_info) {
   CodeEntry* code_entry = new CodeEntry(tag,
                                         name,
                                         name_prefix,
                                         resource_name,
                                         line_number,
-                                        column_number);
+                                        column_number,
+                                        line_info);
   code_entries_.Add(code_entry);
   return code_entry;
 }
 
 
 const char* const ProfileGenerator::kAnonymousFunctionName =
     "(anonymous function)";
 const char* const ProfileGenerator::kProgramEntryName =
     "(program)";
 const char* const ProfileGenerator::kIdleEntryName =
@@ skipping 12 matching lines @@
           profiles->NewCodeEntry(Logger::FUNCTION_TAG, kIdleEntryName)),
       gc_entry_(
           profiles->NewCodeEntry(Logger::BUILTIN_TAG,
                                  kGarbageCollectorEntryName)),
       unresolved_entry_(
           profiles->NewCodeEntry(Logger::FUNCTION_TAG,
                                  kUnresolvedFunctionName)) {
 }
 
 
+static int GetSourceLine(unsigned int pc_offset, CodeEntry* entry) {
+  int src_line = v8::CpuProfileNode::kNoLineNumberInfo;
+  const JITLineInfoTable& table = entry->line_info();
+  if (!table.entries()->length()) return src_line;
+  src_line = table.GetSourceLineNumber(pc_offset);
+  return src_line;
+}

[alph, 2014/07/29 12:55:56]

could you please make it more readable, e.g.:

int src_line = entry->line_info().GetSourceLineNumber(pc_offset);
if (src_line)
  return src_line;
return v8::CpuProfileNode::kNoLineNumberInfo;

+
+
 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));
+  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) {
+        Code* code = Code::cast(HeapObject::FromAddress(start));
         List<OffsetRange>* ranges = pc_entry->no_frame_ranges();
+        src_line = GetSourceLine(sample.pc - code->instruction_start(),
+                                 pc_entry);
         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 unresolved_src = (src_line == v8::CpuProfileNode::kNoLineNumberInfo) ?

[yurys, 2014/07/29 13:15:10]

bool unresolved_src = src_line == v8::CpuProfileNode::kNoLineNumberInfo;

+                          true : false;
+
     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);
+      if (unresolved_src && NULL != *entry) {
+          Code* code = Code::cast(HeapObject::FromAddress(start));
+          src_line = GetSourceLine(*stack_pos - code->instruction_start(),
+                                   *entry);
+          if (src_line == v8::CpuProfileNode::kNoLineNumberInfo) {
+            src_line = (*entry)->line_number();
+          }
+          unresolved_src = 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