Correctly report callstack when current function is FunctionCall builtin

When current function is FunctionCall builtin we have no reliable way to determine its caller function (in many cases the top of the sampled stack contains address of the caller but sometimes it does not). Instead of dropping the sample or its two top frames we simply mark the caller frame as '(unresolved function)'. It seems like a better approach that dropping whole sample as knowing the top function and the rest of the stack the user should be able to figure out what the caller was.

This change adds builtin id to CodeEntry objects. It will be used later to add similar top frame analysis for FunctionApply and probably other builtins.

BUG=None
R=jkummerow@chromium.org, loislo@chromium.org

Review URL: https://codereview.chromium.org/18316004

git-svn-id: http://v8.googlecode.com/svn/branches/bleeding_edge@15426 ce2b1a6d-e550-0410-aec6-3dcde31c8c00

src/cpu-profiler-inl.h

@@ -56,6 +56,17 @@ void SharedFunctionInfoMoveEventRecord::UpdateCodeMap(CodeMap* code_map) {
 }
 
 
+void ReportBuiltinEventRecord::UpdateCodeMap(CodeMap* code_map) {
+  CodeEntry* entry = code_map->FindEntry(start);
+  if (!entry) {
+    // Code objects for builtins should already have been added to the map.
+    UNREACHABLE();
+    return;
+  }
+  entry->SetBuiltinId(builtin_id);
+}
+
+
 TickSample* ProfilerEventsProcessor::TickSampleEvent() {
   generator_->Tick();
   TickSampleEventRecord* evt =

src/cpu-profiler.cc

@@ -446,6 +446,7 @@ void CpuProfiler::StartProcessorIfNotStarted() {
     }
     logger->LogCompiledFunctions();
     logger->LogAccessorCallbacks();
+    LogBuiltins();
     // Enable stack sampling.
     Sampler* sampler = logger->sampler();
     sampler->IncreaseProfilingDepth();
@@ -506,4 +507,18 @@ void CpuProfiler::StopProcessor() {
 }
 
 
+void CpuProfiler::LogBuiltins() {
+  Builtins* builtins = isolate_->builtins();
+  ASSERT(builtins->is_initialized());
+  for (int i = 0; i < Builtins::builtin_count; i++) {
+    CodeEventsContainer evt_rec(CodeEventRecord::REPORT_BUILTIN);
+    ReportBuiltinEventRecord* rec = &evt_rec.ReportBuiltinEventRecord_;
+    Builtins::Name id = static_cast<Builtins::Name>(i);
+    rec->start = builtins->builtin(id)->address();
+    rec->builtin_id = id;
+    processor_->Enqueue(evt_rec);
+  }
+}
+
+
 } }  // namespace v8::internal

src/cpu-profiler.h

@@ -49,7 +49,8 @@ class TokenEnumerator;
 #define CODE_EVENTS_TYPE_LIST(V)                                   \
   V(CODE_CREATION,    CodeCreateEventRecord)                       \
   V(CODE_MOVE,        CodeMoveEventRecord)                         \
-  V(SHARED_FUNC_MOVE, SharedFunctionInfoMoveEventRecord)
+  V(SHARED_FUNC_MOVE, SharedFunctionInfoMoveEventRecord)           \
+  V(REPORT_BUILTIN,   ReportBuiltinEventRecord)
 
 
 class CodeEventRecord {
@@ -96,6 +97,15 @@ class SharedFunctionInfoMoveEventRecord : public CodeEventRecord {
 };
 
 
+class ReportBuiltinEventRecord : public CodeEventRecord {
+ public:
+  Address start;
+  Builtins::Name builtin_id;
+
+  INLINE(void UpdateCodeMap(CodeMap* code_map));
+};
+
+
 class TickSampleEventRecord {
  public:
   // The parameterless constructor is used when we dequeue data from
@@ -246,6 +256,7 @@ class CpuProfiler {
   void StopProcessorIfLastProfile(const char* title);
   void StopProcessor();
   void ResetProfiles();
+  void LogBuiltins();
 
   Isolate* isolate_;
   CpuProfilesCollection* profiles_;

src/profile-generator-inl.h

@@ -50,6 +50,7 @@ CodeEntry::CodeEntry(Logger::LogEventsAndTags tag,
                      const char* resource_name,
                      int line_number)
     : tag_(tag),
+      builtin_id_(Builtins::builtin_count),
       name_prefix_(name_prefix),
       name_(name),
       resource_name_(resource_name),

src/profile-generator.cc

@@ -235,6 +235,12 @@ bool CodeEntry::IsSameAs(CodeEntry* entry) const {
 }
 
 
+void CodeEntry::SetBuiltinId(Builtins::Name id) {
+  tag_ = Logger::BUILTIN_TAG;
+  builtin_id_ = id;
+}
+
+
 ProfileNode* ProfileNode::FindChild(CodeEntry* entry) {
   HashMap::Entry* map_entry =
       children_.Lookup(entry, CodeEntryHash(entry), false);
@@ -847,6 +853,8 @@ const char* const ProfileGenerator::kProgramEntryName =
     "(program)";
 const char* const ProfileGenerator::kGarbageCollectorEntryName =
     "(garbage collector)";
+const char* const ProfileGenerator::kUnresolvedFunctionName =
+    "(unresolved function)";
 
 
 ProfileGenerator::ProfileGenerator(CpuProfilesCollection* profiles)
@@ -855,7 +863,10 @@ ProfileGenerator::ProfileGenerator(CpuProfilesCollection* profiles)
           profiles->NewCodeEntry(Logger::FUNCTION_TAG, kProgramEntryName)),
       gc_entry_(
           profiles->NewCodeEntry(Logger::BUILTIN_TAG,
-                                 kGarbageCollectorEntryName)) {
+                                 kGarbageCollectorEntryName)),
+      unresolved_entry_(
+          profiles->NewCodeEntry(Logger::FUNCTION_TAG,
+                                 kUnresolvedFunctionName)) {
 }
 
 
@@ -867,6 +878,12 @@ void ProfileGenerator::RecordTickSample(const TickSample& sample) {
   CodeEntry** entry = entries.start();
   memset(entry, 0, entries.length() * sizeof(*entry));
   if (sample.pc != NULL) {
+    if (sample.has_external_callback) {
+      // 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
@@ -877,7 +894,8 @@ void ProfileGenerator::RecordTickSample(const TickSample& sample) {
         List<OffsetRange>* ranges = pc_entry->no_frame_ranges();
         if (ranges) {
           Code* code = Code::cast(HeapObject::FromAddress(start));
-        int pc_offset = static_cast<int>(sample.pc - code->instruction_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) {
@@ -885,15 +903,15 @@ void ProfileGenerator::RecordTickSample(const TickSample& sample) {
             }
           }
         }
-    }
         *entry++ = pc_entry;
 
-    if (sample.has_external_callback) {
-      // 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.
-      *(entries.start()) = NULL;
-      *entry++ = code_map_.FindEntry(sample.external_callback);
+        if (pc_entry->builtin_id() == Builtins::kFunctionCall) {
+          // When current function is FunctionCall builtin tos is sometimes
+          // address of the function that invoked it but sometimes it's one
+          // of the arguments. We simply replace the frame with 'unknown' entry.
+          *entry++ = unresolved_entry_;
+        }
+      }
     }
 
     for (const Address* stack_pos = sample.stack,

src/profile-generator.h

@@ -120,6 +120,9 @@ class CodeEntry {
     no_frame_ranges_ = ranges;
   }
 
+  void SetBuiltinId(Builtins::Name id);
+  Builtins::Name builtin_id() const { return builtin_id_; }
+
   void CopyData(const CodeEntry& source);
   uint32_t GetCallUid() const;
   bool IsSameAs(CodeEntry* entry) const;
@@ -128,7 +131,8 @@ class CodeEntry {
   static const char* const kEmptyResourceName;
 
  private:
-  Logger::LogEventsAndTags tag_;
+  Logger::LogEventsAndTags tag_ : 8;
+  Builtins::Name builtin_id_ : 8;
   const char* name_prefix_;
   const char* name_;
   const char* resource_name_;
@@ -422,6 +426,9 @@ class ProfileGenerator {
   static const char* const kAnonymousFunctionName;
   static const char* const kProgramEntryName;
   static const char* const kGarbageCollectorEntryName;
+  // Used to represent frames for which we have no reliable way to
+  // detect function.
+  static const char* const kUnresolvedFunctionName;
 
  private:
   INLINE(CodeEntry* EntryForVMState(StateTag tag));
@@ -430,6 +437,7 @@ class ProfileGenerator {
   CodeMap code_map_;
   CodeEntry* program_entry_;
   CodeEntry* gc_entry_;
+  CodeEntry* unresolved_entry_;
   SampleRateCalculator sample_rate_calc_;
 
   DISALLOW_COPY_AND_ASSIGN(ProfileGenerator);

test/cctest/test-cpu-profiler.cc

@@ -1023,3 +1023,80 @@ TEST(BoundFunctionCall) {
 
   cpu_profiler->DeleteAllCpuProfiles();
 }
+
+
+static const char* call_function_test_source = "function bar(iterations) {\n"
+"}\n"
+"function start(duration) {\n"
+"  var start = Date.now();\n"
+"  while (Date.now() - start < duration) {\n"
+"    try {\n"
+"      bar.call(this, 10 * 1000);\n"
+"    } catch(e) {}\n"
+"  }\n"
+"}";
+
+
+// Test that if we sampled thread when it was inside FunctionCall buitin then
+// its caller frame will be '(unresolved function)' as we have no reliable way
+// to resolve it.
+//
+// [Top down]:
+//    96     0   (root) [-1] #1
+//     1     1    (garbage collector) [-1] #4
+//     5     0    (unresolved function) [-1] #5
+//     5     5      call [-1] #6
+//    71    70    start [-1] #3
+//     1     1      bar [-1] #7
+//    19    19    (program) [-1] #2
+TEST(FunctionCallSample) {
+  LocalContext env;
+  v8::HandleScope scope(env->GetIsolate());
+
+  v8::Script::Compile(v8::String::New(call_function_test_source))->Run();
+  v8::Local<v8::Function> function = v8::Local<v8::Function>::Cast(
+      env->Global()->Get(v8::String::New("start")));
+
+  v8::CpuProfiler* cpu_profiler = env->GetIsolate()->GetCpuProfiler();
+  v8::Local<v8::String> profile_name = v8::String::New("my_profile");
+
+  cpu_profiler->StartCpuProfiling(profile_name);
+  int32_t duration_ms = 100;
+  v8::Handle<v8::Value> args[] = { v8::Integer::New(duration_ms) };
+  function->Call(env->Global(), ARRAY_SIZE(args), args);
+  const v8::CpuProfile* profile = cpu_profiler->StopCpuProfiling(profile_name);
+
+  CHECK_NE(NULL, profile);
+  // Dump collected profile to have a better diagnostic in case of failure.
+  reinterpret_cast<i::CpuProfile*>(
+      const_cast<v8::CpuProfile*>(profile))->Print();
+
+  const v8::CpuProfileNode* root = profile->GetTopDownRoot();
+  {
+    ScopedVector<v8::Handle<v8::String> > names(4);
+    names[0] = v8::String::New(ProfileGenerator::kGarbageCollectorEntryName);
+    names[1] = v8::String::New(ProfileGenerator::kProgramEntryName);
+    names[2] = v8::String::New("start");
+    names[3] = v8::String::New(i::ProfileGenerator::kUnresolvedFunctionName);
+    // Don't allow |bar| and |call| nodes to be at the top level.
+    CheckChildrenNames(root, names);
+  }
+
+  const v8::CpuProfileNode* startNode = GetChild(root, "start");
+  {
+    ScopedVector<v8::Handle<v8::String> > names(1);
+    names[0] = v8::String::New("bar");
+    CheckChildrenNames(startNode, names);
+  }
+
+  const v8::CpuProfileNode* unresolvedNode =
+      FindChild(root, i::ProfileGenerator::kUnresolvedFunctionName);
+  if (unresolvedNode) {
+    ScopedVector<v8::Handle<v8::String> > names(1);
+    names[0] = v8::String::New("call");
+    CheckChildrenNames(unresolvedNode, names);
+  }
+
+  cpu_profiler->DeleteAllCpuProfiles();
+}
+