From 106bfd074d78e8f0206971a14ba9369e5e5ac23c Mon Sep 17 00:00:00 2001 From: Denis Pravdin Date: Wed, 3 Sep 2014 15:13:00 +0400 Subject: [PATCH] V8 CPU profiler: source level support --- include/v8-profiler.h | 20 ++++++ src/api.cc | 13 ++++ src/cpu-profiler.cc | 30 +++++++-- src/full-codegen.cc | 1 + src/profile-generator-inl.h | 14 +++- src/profile-generator.cc | 109 +++++++++++++++++++++++++++---- src/profile-generator.h | 62 ++++++++++++++++-- test/cctest/test-cpu-profiler.cc | 105 +++++++++++++++++++++++++++++ 8 files changed, 325 insertions(+), 29 deletions(-) diff --git a/include/v8-profiler.h b/include/v8-profiler.h index 7fc193db58e..d0215205f5f 100644 --- a/include/v8-profiler.h +++ b/include/v8-profiler.h @@ -22,6 +22,14 @@ typedef uint32_t SnapshotObjectId; */ class V8_EXPORT CpuProfileNode { public: + struct LineTick { + /** The 1-based number of the source line where the function originates. */ + int line; + + /** The count of samples associated with the source line. */ + unsigned int hit_count; + }; + /** Returns function name (empty string for anonymous functions.) */ Handle GetFunctionName() const; @@ -43,6 +51,18 @@ class V8_EXPORT CpuProfileNode { */ int GetColumnNumber() const; + /** + * Returns the number of the function's source lines that collect the samples. + */ + unsigned int GetHitLineCount() const; + + /** Returns the set of source lines that collect the samples. + * The caller allocates buffer and responsible for releasing it. + * True if all available entries are copied, otherwise false. + * The function copies nothing if buffer is not large enough. + */ + bool GetLineTicks(LineTick* entries, unsigned int length) const; + /** Returns bailout reason for the function * if the optimization was disabled for it. */ diff --git a/src/api.cc b/src/api.cc index 3d9e9d8310a..0552d6ff412 100644 --- a/src/api.cc +++ b/src/api.cc @@ -7037,6 +7037,19 @@ int CpuProfileNode::GetColumnNumber() const { } +unsigned int CpuProfileNode::GetHitLineCount() const { + const i::ProfileNode* node = reinterpret_cast(this); + return node->GetHitLineCount(); +} + + +bool CpuProfileNode::GetLineTicks(LineTick* entries, + unsigned int length) const { + const i::ProfileNode* node = reinterpret_cast(this); + return node->GetLineTicks(entries, length); +} + + const char* CpuProfileNode::GetBailoutReason() const { const i::ProfileNode* node = reinterpret_cast(this); return node->entry()->bailout_reason(); diff --git a/src/cpu-profiler.cc b/src/cpu-profiler.cc index 68a565c73a2..115324c459a 100644 --- a/src/cpu-profiler.cc +++ b/src/cpu-profiler.cc @@ -256,20 +256,38 @@ void CpuProfiler::CodeCreateEvent(Logger::LogEventsAndTags tag, Code* code, CodeEventsContainer evt_rec(CodeEventRecord::CODE_CREATION); CodeCreateEventRecord* rec = &evt_rec.CodeCreateEventRecord_; rec->start = code->address(); + Script* script = NULL; + JITLineInfoTable* line_table = NULL; + if (shared->script()->IsScript()) { + DCHECK(Script::cast(shared->script())); + script = Script::cast(shared->script()); + line_table = new JITLineInfoTable(); + for (RelocIterator it(code); !it.done(); it.next()) { + RelocInfo::Mode mode = it.rinfo()->rmode(); + if (RelocInfo::IsPosition(mode)) { + int position = static_cast(it.rinfo()->data()); + if (position >= 0) { + int pc_offset = static_cast(it.rinfo()->pc() - code->address()); + int line_number = script->GetLineNumber(position) + 1; + line_table->SetPosition(pc_offset, line_number); + } + } + } + } rec->entry = profiles_->NewCodeEntry( tag, profiles_->GetFunctionName(shared->DebugName()), CodeEntry::kEmptyNamePrefix, profiles_->GetName(script_name), line, - column); + column, line_table); if (info) { rec->entry->set_no_frame_ranges(info->ReleaseNoFrameRanges()); } - DCHECK(Script::cast(shared->script())); - Script* script = Script::cast(shared->script()); - rec->entry->set_script_id(script->id()->value()); - rec->size = code->ExecutableSize(); - rec->shared = shared->address(); + if (script) { + rec->entry->set_script_id(script->id()->value()); + } rec->entry->set_bailout_reason( GetBailoutReason(shared->DisableOptimizationReason())); + rec->size = code->ExecutableSize(); + rec->shared = shared->address(); processor_->Enqueue(evt_rec); } diff --git a/src/full-codegen.cc b/src/full-codegen.cc index 0297f88f581..ea8b73f172a 100644 --- a/src/full-codegen.cc +++ b/src/full-codegen.cc @@ -848,6 +848,7 @@ void FullCodeGenerator::SetExpressionPosition(Expression* expr) { void FullCodeGenerator::SetSourcePosition(int pos) { if (pos != RelocInfo::kNoPosition) { masm_->positions_recorder()->RecordPosition(pos); + masm_->positions_recorder()->WriteRecordedPositions(); } } diff --git a/src/profile-generator-inl.h b/src/profile-generator-inl.h index 58c124fe62b..b27a009a228 100644 --- a/src/profile-generator-inl.h +++ b/src/profile-generator-inl.h @@ -15,7 +15,8 @@ CodeEntry::CodeEntry(Logger::LogEventsAndTags tag, const char* name_prefix, const char* resource_name, int line_number, - int column_number) + int column_number, + JITLineInfoTable* line_info) : tag_(tag), builtin_id_(Builtins::builtin_count), name_prefix_(name_prefix), @@ -26,7 +27,8 @@ CodeEntry::CodeEntry(Logger::LogEventsAndTags tag, shared_id_(0), script_id_(v8::UnboundScript::kNoScriptId), no_frame_ranges_(NULL), - bailout_reason_(kEmptyBailoutReason) { } + bailout_reason_(kEmptyBailoutReason), + line_info_(line_info) { } bool CodeEntry::is_js_function_tag(Logger::LogEventsAndTags tag) { @@ -39,12 +41,18 @@ bool CodeEntry::is_js_function_tag(Logger::LogEventsAndTags tag) { } +static bool LineTickMatch(void* a, void* b) { + return a == b; +} + + ProfileNode::ProfileNode(ProfileTree* tree, CodeEntry* entry) : tree_(tree), entry_(entry), self_ticks_(0), children_(CodeEntriesMatch), - id_(tree->next_node_id()) { } + id_(tree->next_node_id()), + line_ticks_(LineTickMatch) { } } } // namespace v8::internal diff --git a/src/profile-generator.cc b/src/profile-generator.cc index 6017f12dc67..3f79c6af810 100644 --- a/src/profile-generator.cc +++ b/src/profile-generator.cc @@ -139,6 +139,7 @@ const char* const CodeEntry::kEmptyBailoutReason = ""; CodeEntry::~CodeEntry() { delete no_frame_ranges_; + delete line_info_; } @@ -181,6 +182,14 @@ void CodeEntry::SetBuiltinId(Builtins::Name 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); @@ -202,6 +211,41 @@ ProfileNode* ProfileNode::FindOrAddChild(CodeEntry* entry) { } +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(src_line), src_line, true); + DCHECK(e); + e->value = reinterpret_cast(reinterpret_cast(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(reinterpret_cast(p->key)); + entry->hit_count = + static_cast(reinterpret_cast(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(), @@ -242,7 +286,8 @@ ProfileTree::~ProfileTree() { } -ProfileNode* ProfileTree::AddPathFromEnd(const Vector& path) { +ProfileNode* ProfileTree::AddPathFromEnd(const Vector& path, + int src_line) { ProfileNode* node = root_; for (CodeEntry** entry = path.start() + path.length() - 1; entry != path.start() - 1; @@ -252,11 +297,15 @@ ProfileNode* ProfileTree::AddPathFromEnd(const Vector& path) { } } node->IncrementSelfTicks(); + if (src_line != v8::CpuProfileNode::kNoLineNumberInfo) { + node->IncrementLineTicks(src_line); + } return node; } -void ProfileTree::AddPathFromStart(const Vector& path) { +void ProfileTree::AddPathFromStart(const Vector& path, + int src_line) { ProfileNode* node = root_; for (CodeEntry** entry = path.start(); entry != path.start() + path.length(); @@ -266,6 +315,9 @@ void ProfileTree::AddPathFromStart(const Vector& path) { } } node->IncrementSelfTicks(); + if (src_line != v8::CpuProfileNode::kNoLineNumberInfo) { + node->IncrementLineTicks(src_line); + } } @@ -327,8 +379,9 @@ CpuProfile::CpuProfile(const char* title, bool record_samples) void CpuProfile::AddPath(base::TimeTicks timestamp, - const Vector& path) { - ProfileNode* top_frame_node = top_down_.AddPathFromEnd(path); + const Vector& 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); @@ -517,13 +570,15 @@ void CpuProfilesCollection::RemoveProfile(CpuProfile* profile) { void CpuProfilesCollection::AddPathToCurrentProfiles( - base::TimeTicks timestamp, const Vector& path) { + base::TimeTicks timestamp, + const Vector& 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(); } @@ -535,13 +590,15 @@ CodeEntry* CpuProfilesCollection::NewCodeEntry( 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; } @@ -579,6 +636,14 @@ void ProfileGenerator::RecordTickSample(const TickSample& sample) { // 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) { @@ -595,10 +660,10 @@ void ProfileGenerator::RecordTickSample(const TickSample& sample) { // frame. Check for this case and just skip such samples. if (pc_entry) { List* ranges = pc_entry->no_frame_ranges(); + Code* code = Code::cast(HeapObject::FromAddress(start)); + int pc_offset = static_cast(sample.pc - code->instruction_start()); + src_line = pc_entry->GetSourceLine(pc_offset); 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) { @@ -622,11 +687,29 @@ void ProfileGenerator::RecordTickSample(const TickSample& sample) { } } + 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) { + Code* code = Code::cast(HeapObject::FromAddress(start)); + int pc_offset = + static_cast(*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++; } } @@ -644,7 +727,7 @@ void ProfileGenerator::RecordTickSample(const TickSample& sample) { } } - profiles_->AddPathToCurrentProfiles(sample.timestamp, entries); + profiles_->AddPathToCurrentProfiles(sample.timestamp, entries, src_line); } diff --git a/src/profile-generator.h b/src/profile-generator.h index 5ebb92bba3b..f973eb2737a 100644 --- a/src/profile-generator.h +++ b/src/profile-generator.h @@ -5,6 +5,7 @@ #ifndef V8_PROFILE_GENERATOR_H_ #define V8_PROFILE_GENERATOR_H_ +#include #include "include/v8-profiler.h" #include "src/allocation.h" #include "src/hashmap.h" @@ -44,6 +45,36 @@ class StringsStorage { }; +// Provides a mapping from the offsets within generated code to +// the source line. +class JITLineInfoTable : public Malloced { + public: + JITLineInfoTable() {} + ~JITLineInfoTable() {} + + void SetPosition(int pc_offset, int line) { + DCHECK(pc_offset >= 0); + DCHECK(line > 0); // The 1-based number of the source line. + pc_offset_map_.insert(std::make_pair(pc_offset, line)); + } + + int GetSourceLineNumber(int pc_offset) const { + PcOffsetMap::const_iterator it = pc_offset_map_.lower_bound(pc_offset); + if (it == pc_offset_map_.end()) { + return v8::CpuProfileNode::kNoLineNumberInfo; + } + return it->second; + } + + bool Empty() const { return pc_offset_map_.empty(); } + + private: + // pc_offset -> source line + typedef std::map PcOffsetMap; + PcOffsetMap pc_offset_map_; + DISALLOW_COPY_AND_ASSIGN(JITLineInfoTable); +}; + class CodeEntry { public: // CodeEntry doesn't own name strings, just references them. @@ -52,7 +83,8 @@ class CodeEntry { const char* name_prefix = CodeEntry::kEmptyNamePrefix, const char* resource_name = CodeEntry::kEmptyResourceName, int line_number = v8::CpuProfileNode::kNoLineNumberInfo, - int column_number = v8::CpuProfileNode::kNoColumnNumberInfo); + int column_number = v8::CpuProfileNode::kNoColumnNumberInfo, + JITLineInfoTable* line_info = NULL); ~CodeEntry(); bool is_js_function() const { return is_js_function_tag(tag_); } @@ -62,6 +94,7 @@ class CodeEntry { const char* resource_name() const { return resource_name_; } int line_number() const { return line_number_; } int column_number() const { return column_number_; } + const JITLineInfoTable* line_info() const { return line_info_; } void set_shared_id(int shared_id) { shared_id_ = shared_id; } int script_id() const { return script_id_; } void set_script_id(int script_id) { script_id_ = script_id; } @@ -83,6 +116,8 @@ class CodeEntry { uint32_t GetCallUid() const; bool IsSameAs(CodeEntry* entry) const; + int GetSourceLine(int pc_offset) const; + static const char* const kEmptyNamePrefix; static const char* const kEmptyResourceName; static const char* const kEmptyBailoutReason; @@ -99,6 +134,7 @@ class CodeEntry { int script_id_; List* no_frame_ranges_; const char* bailout_reason_; + JITLineInfoTable* line_info_; DISALLOW_COPY_AND_ASSIGN(CodeEntry); }; @@ -114,11 +150,15 @@ class ProfileNode { ProfileNode* FindOrAddChild(CodeEntry* entry); void IncrementSelfTicks() { ++self_ticks_; } void IncreaseSelfTicks(unsigned amount) { self_ticks_ += amount; } + void IncrementLineTicks(int src_line); CodeEntry* entry() const { return entry_; } unsigned self_ticks() const { return self_ticks_; } const List* children() const { return &children_list_; } unsigned id() const { return id_; } + unsigned int GetHitLineCount() const { return line_ticks_.occupancy(); } + bool GetLineTicks(v8::CpuProfileNode::LineTick* entries, + unsigned int length) const; void Print(int indent); @@ -139,6 +179,7 @@ class ProfileNode { HashMap children_; List children_list_; unsigned id_; + HashMap line_ticks_; DISALLOW_COPY_AND_ASSIGN(ProfileNode); }; @@ -149,8 +190,11 @@ class ProfileTree { ProfileTree(); ~ProfileTree(); - ProfileNode* AddPathFromEnd(const Vector& path); - void AddPathFromStart(const Vector& path); + ProfileNode* AddPathFromEnd( + const Vector& path, + int src_line = v8::CpuProfileNode::kNoLineNumberInfo); + void AddPathFromStart(const Vector& path, + int src_line = v8::CpuProfileNode::kNoLineNumberInfo); ProfileNode* root() const { return root_; } unsigned next_node_id() { return next_node_id_++; } @@ -175,7 +219,9 @@ class CpuProfile { CpuProfile(const char* title, bool record_samples); // Add pc -> ... -> main() call path to the profile. - void AddPath(base::TimeTicks timestamp, const Vector& path); + void AddPath(base::TimeTicks timestamp, + const Vector& path, + int src_line); void CalculateTotalTicksAndSamplingRate(); const char* title() const { return title_; } @@ -282,11 +328,13 @@ class CpuProfilesCollection { const char* name_prefix = CodeEntry::kEmptyNamePrefix, const char* resource_name = CodeEntry::kEmptyResourceName, int line_number = v8::CpuProfileNode::kNoLineNumberInfo, - int column_number = v8::CpuProfileNode::kNoColumnNumberInfo); + int column_number = v8::CpuProfileNode::kNoColumnNumberInfo, + JITLineInfoTable* line_info = NULL); // Called from profile generator thread. - void AddPathToCurrentProfiles( - base::TimeTicks timestamp, const Vector& path); + void AddPathToCurrentProfiles(base::TimeTicks timestamp, + const Vector& path, + int src_line); // Limits the number of profiles that can be simultaneously collected. static const int kMaxSimultaneousProfiles = 100; diff --git a/test/cctest/test-cpu-profiler.cc b/test/cctest/test-cpu-profiler.cc index 6051c3fd7f6..ee2d14985c6 100644 --- a/test/cctest/test-cpu-profiler.cc +++ b/test/cctest/test-cpu-profiler.cc @@ -1064,6 +1064,111 @@ TEST(BoundFunctionCall) { } +// This tests checks distribution of the samples through the source lines. +TEST(TickLines) { + CcTest::InitializeVM(); + LocalContext env; + i::Isolate* isolate = CcTest::i_isolate(); + i::Factory* factory = isolate->factory(); + i::HandleScope scope(isolate); + + i::EmbeddedVector script; + + const char* func_name = "func"; + i::SNPrintF(script, + "function %s() {\n" + " for (var i = 0; i < 10; ++i) {\n" + " var n = 0;\n" + " var m = 100*100;\n" + " while (m > 1) {\n" + " m--;\n" + " n += m * m * m;\n" + " }\n" + " }\n" + "}\n" + "%s();\n", func_name, func_name); + + CompileRun(script.start()); + + i::Handle func = v8::Utils::OpenHandle( + *v8::Local::Cast( + (*env)->Global()->Get(v8_str(func_name)))); + CHECK_NE(NULL, func->shared()); + CHECK_NE(NULL, func->shared()->code()); + i::Code* code = NULL; + if (func->code()->is_optimized_code()) { + code = func->code(); + } else { + CHECK(func->shared()->code() == func->code() || !i::FLAG_crankshaft); + code = func->shared()->code(); + } + CHECK_NE(NULL, code); + i::Address code_address = code->address(); + CHECK_NE(NULL, code_address); + + CpuProfilesCollection* profiles = new CpuProfilesCollection(isolate->heap()); + profiles->StartProfiling("", false); + ProfileGenerator generator(profiles); + SmartPointer processor(new ProfilerEventsProcessor( + &generator, NULL, v8::base::TimeDelta::FromMicroseconds(100))); + processor->Start(); + CpuProfiler profiler(isolate, profiles, &generator, processor.get()); + + // Enqueue code creation events. + i::Handle str = factory->NewStringFromAsciiChecked(func_name); + int line = 1; + int column = 1; + profiler.CodeCreateEvent(i::Logger::FUNCTION_TAG, + code, + func->shared(), + NULL, + *str, + line, + column); + + // Enqueue a tick event to enable code events processing. + EnqueueTickSampleEvent(processor.get(), code_address); + + processor->StopSynchronously(); + + CpuProfile* profile = profiles->StopProfiling(""); + CHECK_NE(NULL, profile); + + // Check the state of profile generator. + CodeEntry* func_entry = generator.code_map()->FindEntry(code_address); + CHECK_NE(NULL, func_entry); + CHECK_EQ(func_name, func_entry->name()); + const i::JITLineInfoTable* line_info = func_entry->line_info(); + CHECK_NE(NULL, line_info); + CHECK_EQ(false, line_info->Empty()); + + // Check the hit source lines using V8 Public APIs. + const i::ProfileTree* tree = profile->top_down(); + ProfileNode* root = tree->root(); + CHECK_NE(NULL, root); + ProfileNode* func_node = root->FindChild(func_entry); + CHECK_NE(NULL, func_node); + + // Add 10 faked ticks to source line #5. + int hit_line = 5; + int hit_count = 10; + for (int i = 0; i < hit_count; i++) + func_node->IncrementLineTicks(hit_line); + + unsigned int line_count = func_node->GetHitLineCount(); + CHECK_EQ(2, line_count); // Expect two hit source lines - #1 and #5. + ScopedVector entries(line_count); + CHECK_EQ(true, func_node->GetLineTicks(&entries[0], line_count)); + int value = 0; + for (int i = 0; i < entries.length(); i++) + if (entries[i].line == hit_line) { + value = entries[i].hit_count; + break; + } + CHECK_EQ(hit_count, value); +} + + static const char* call_function_test_source = "function bar(iterations) {\n" "}\n" "function start(duration) {\n"