From: yurys@chromium.org Date: Mon, 1 Jul 2013 14:57:58 +0000 (+0000) Subject: Correctly report callstack when current function is FunctionCall builtin X-Git-Tag: upstream/4.7.83~13591 X-Git-Url: http://review.tizen.org/git/?a=commitdiff_plain;h=91dc6dd632be2e18215479fed202b3c372eba762;p=platform%2Fupstream%2Fv8.git 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 --- diff --git a/src/cpu-profiler-inl.h b/src/cpu-profiler-inl.h index 408d46b..925a28e 100644 --- a/src/cpu-profiler-inl.h +++ b/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 = diff --git a/src/cpu-profiler.cc b/src/cpu-profiler.cc index b6cfbc5..270da8f 100644 --- a/src/cpu-profiler.cc +++ b/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(i); + rec->start = builtins->builtin(id)->address(); + rec->builtin_id = id; + processor_->Enqueue(evt_rec); + } +} + + } } // namespace v8::internal diff --git a/src/cpu-profiler.h b/src/cpu-profiler.h index 98096be..61d40f0 100644 --- a/src/cpu-profiler.h +++ b/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_; diff --git a/src/profile-generator-inl.h b/src/profile-generator-inl.h index f2e6ec6..115e813 100644 --- a/src/profile-generator-inl.h +++ b/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), diff --git a/src/profile-generator.cc b/src/profile-generator.cc index a7f7a44..1354487 100644 --- a/src/profile-generator.cc +++ b/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,33 +878,40 @@ void ProfileGenerator::RecordTickSample(const TickSample& sample) { CodeEntry** entry = entries.start(); memset(entry, 0, entries.length() * sizeof(*entry)); if (sample.pc != NULL) { - 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* ranges = pc_entry->no_frame_ranges(); - if (ranges) { - Code* code = Code::cast(HeapObject::FromAddress(start)); - int pc_offset = static_cast(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 (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); + } 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* ranges = pc_entry->no_frame_ranges(); + if (ranges) { + Code* code = Code::cast(HeapObject::FromAddress(start)); + int pc_offset = static_cast( + 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) { + // 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, diff --git a/src/profile-generator.h b/src/profile-generator.h index 38451d1..2783a08 100644 --- a/src/profile-generator.h +++ b/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); diff --git a/test/cctest/test-cpu-profiler.cc b/test/cctest/test-cpu-profiler.cc index 251a4a5..f4d9936 100644 --- a/test/cctest/test-cpu-profiler.cc +++ b/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 function = v8::Local::Cast( + env->Global()->Get(v8::String::New("start"))); + + v8::CpuProfiler* cpu_profiler = env->GetIsolate()->GetCpuProfiler(); + v8::Local profile_name = v8::String::New("my_profile"); + + cpu_profiler->StartCpuProfiling(profile_name); + int32_t duration_ms = 100; + v8::Handle 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( + const_cast(profile))->Print(); + + const v8::CpuProfileNode* root = profile->GetTopDownRoot(); + { + ScopedVector > 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 > names(1); + names[0] = v8::String::New("bar"); + CheckChildrenNames(startNode, names); + } + + const v8::CpuProfileNode* unresolvedNode = + FindChild(root, i::ProfileGenerator::kUnresolvedFunctionName); + if (unresolvedNode) { + ScopedVector > names(1); + names[0] = v8::String::New("call"); + CheckChildrenNames(unresolvedNode, names); + } + + cpu_profiler->DeleteAllCpuProfiles(); +} +