From ae461b9ed0bbe51f4681902f2c3ad1bd16432986 Mon Sep 17 00:00:00 2001 From: loislo Date: Tue, 24 Mar 2015 05:46:13 -0700 Subject: [PATCH] CpuProfiler: push the collected information about deopts to cpu profiler it is the last patch of https://codereview.chromium.org/1012633002 All that we need here is to push the collected info to the profiler and convert it into actionable information about deopt. On the Next: get the info accessible by embedder. BUG=chromium:452067 LOG=n TEST=DeoptAtFirstLevelInlinedSource, DeoptAtSecondLevelInlinedSource, DeoptUntrackedFunction Review URL: https://codereview.chromium.org/1013143003 Cr-Commit-Position: refs/heads/master@{#27403} --- src/compiler.cc | 3 +- src/compiler.h | 5 +- src/cpu-profiler.cc | 2 + src/hydrogen.cc | 2 +- src/profile-generator.cc | 54 ++++++-- src/profile-generator.h | 37 ++++-- test/cctest/test-cpu-profiler.cc | 219 ++++++++++++++++++++++++++++++- 7 files changed, 296 insertions(+), 26 deletions(-) diff --git a/src/compiler.cc b/src/compiler.cc index 84901c7437..a8120e33d5 100644 --- a/src/compiler.cc +++ b/src/compiler.cc @@ -125,7 +125,8 @@ CompilationInfo::CompilationInfo(ParseInfo* parse_info, CodeStub* code_stub, no_frame_ranges_(isolate->cpu_profiler()->is_profiling() ? new List(2) : nullptr), - track_positions_(FLAG_hydrogen_track_positions), + track_positions_(FLAG_hydrogen_track_positions || + isolate->cpu_profiler()->is_profiling()), opt_count_(has_shared_info() ? shared_info()->opt_count() : 0), parameter_count_(0), optimization_id_(-1), diff --git a/src/compiler.h b/src/compiler.h index 0de1fc76fd..2efff21c85 100644 --- a/src/compiler.h +++ b/src/compiler.h @@ -97,7 +97,7 @@ struct InlinedFunctionInfo { SourcePosition inline_position; int script_id; int start_position; - std::vector deopt_pc_offsets; + std::vector deopt_pc_offsets; static const int kNoParentId = -1; }; @@ -348,6 +348,9 @@ class CompilationInfo { int start_position_for(uint32_t inlining_id) { return inlined_function_infos_.at(inlining_id).start_position; } + const std::vector& inlined_function_infos() { + return inlined_function_infos_; + } void LogDeoptCallPosition(int pc_offset, int inlining_id); int TraceInlinedFunction(Handle shared, diff --git a/src/cpu-profiler.cc b/src/cpu-profiler.cc index 89c975da9f..03d70521ae 100644 --- a/src/cpu-profiler.cc +++ b/src/cpu-profiler.cc @@ -251,6 +251,7 @@ void CpuProfiler::CodeCreateEvent(Logger::LogEventsAndTags tag, Code* code, NULL, code->instruction_start()); if (info) { rec->entry->set_no_frame_ranges(info->ReleaseNoFrameRanges()); + rec->entry->set_inlined_function_infos(info->inlined_function_infos()); } rec->entry->FillFunctionInfo(shared); rec->size = code->ExecutableSize(); @@ -288,6 +289,7 @@ void CpuProfiler::CodeCreateEvent(Logger::LogEventsAndTags tag, Code* code, column, line_table, code->instruction_start()); if (info) { rec->entry->set_no_frame_ranges(info->ReleaseNoFrameRanges()); + rec->entry->set_inlined_function_infos(info->inlined_function_infos()); } rec->entry->FillFunctionInfo(shared); rec->size = code->ExecutableSize(); diff --git a/src/hydrogen.cc b/src/hydrogen.cc index 5302216689..230939fe56 100644 --- a/src/hydrogen.cc +++ b/src/hydrogen.cc @@ -3483,7 +3483,7 @@ void HGraph::FinalizeUniqueness() { int HGraph::SourcePositionToScriptPosition(SourcePosition pos) { - return (info()->is_tracking_positions() && !pos.IsUnknown()) + return (FLAG_hydrogen_track_positions && !pos.IsUnknown()) ? info()->start_position_for(pos.inlining_id()) + pos.position() : pos.raw(); } diff --git a/src/profile-generator.cc b/src/profile-generator.cc index d030b681ec..385e753025 100644 --- a/src/profile-generator.cc +++ b/src/profile-generator.cc @@ -112,8 +112,42 @@ void CodeEntry::FillFunctionInfo(SharedFunctionInfo* shared) { } +DeoptInfo CodeEntry::GetDeoptInfo() { + DCHECK(has_deopt_info()); + + DeoptInfo info; + info.deopt_reason = deopt_reason_; + if (inlined_function_infos_.empty()) { + info.stack.push_back(DeoptInfo::Frame( + {script_id_, + static_cast(position_ + deopt_position_.position())})); + return info; + } + // Copy the only branch from the inlining tree where the deopt happened. + SourcePosition position = deopt_position_; + int inlining_id = InlinedFunctionInfo::kNoParentId; + for (size_t i = 0; i < inlined_function_infos_.size(); ++i) { + InlinedFunctionInfo& current_info = inlined_function_infos_.at(i); + if (std::binary_search(current_info.deopt_pc_offsets.begin(), + current_info.deopt_pc_offsets.end(), pc_offset_)) { + inlining_id = static_cast(i); + break; + } + } + while (inlining_id != InlinedFunctionInfo::kNoParentId) { + InlinedFunctionInfo& inlined_info = inlined_function_infos_.at(inlining_id); + info.stack.push_back(DeoptInfo::Frame( + {inlined_info.script_id, + static_cast(inlined_info.start_position + position.raw())})); + position = inlined_info.inline_position; + inlining_id = inlined_info.parent_id; + } + return info; +} + + void ProfileNode::CollectDeoptInfo(CodeEntry* entry) { - deopt_infos_.Add(DeoptInfo(entry->deopt_reason(), entry->deopt_position())); + deopt_infos_.push_back(entry->GetDeoptInfo()); entry->clear_deopt_info(); } @@ -181,14 +215,16 @@ void ProfileNode::Print(int indent) { if (entry_->resource_name()[0] != '\0') base::OS::Print(" %s:%d", entry_->resource_name(), entry_->line_number()); base::OS::Print("\n"); - for (auto info : deopt_infos_) { - if (FLAG_hydrogen_track_positions) { - base::OS::Print("%*s deopted at %d_%d with reason '%s'\n", indent + 10, - "", info.deopt_position.inlining_id(), - info.deopt_position.position(), info.deopt_reason); - } else { - base::OS::Print("%*s deopted at %d with reason '%s'\n", indent + 10, "", - info.deopt_position.raw(), info.deopt_reason); + for (size_t i = 0; i < deopt_infos_.size(); ++i) { + DeoptInfo& info = deopt_infos_[i]; + base::OS::Print( + "%*s;;; deopted at script_id: %d position: %d with reason '%s'.\n", + indent + 10, "", info.stack[0].script_id, info.stack[0].position, + info.deopt_reason); + for (size_t index = 1; index < info.stack.size(); ++index) { + base::OS::Print("%*s;;; Inline point: script_id %d position: %d.\n", + indent + 10, "", info.stack[index].script_id, + info.stack[index].position); } } const char* bailout_reason = entry_->bailout_reason(); diff --git a/src/profile-generator.h b/src/profile-generator.h index 4f44c4c8ab..e013e29c5d 100644 --- a/src/profile-generator.h +++ b/src/profile-generator.h @@ -36,6 +36,17 @@ class JITLineInfoTable : public Malloced { DISALLOW_COPY_AND_ASSIGN(JITLineInfoTable); }; + +struct DeoptInfo { + const char* deopt_reason; + struct Frame { + int script_id; + int position; + }; + std::vector stack; +}; + + class CodeEntry { public: // CodeEntry doesn't own name strings, just references them. @@ -72,6 +83,7 @@ class CodeEntry { deopt_position_ = position; pc_offset_ = pc_offset; } + DeoptInfo GetDeoptInfo(); const char* deopt_reason() const { return deopt_reason_; } SourcePosition deopt_position() const { return deopt_position_; } bool has_deopt_info() const { return !deopt_position_.IsUnknown(); } @@ -88,6 +100,13 @@ class CodeEntry { void set_no_frame_ranges(List* ranges) { no_frame_ranges_ = ranges; } + void set_inlined_function_infos( + const std::vector& infos) { + inlined_function_infos_ = infos; + } + const std::vector inlined_function_infos() { + return inlined_function_infos_; + } void SetBuiltinId(Builtins::Name id); Builtins::Name builtin_id() const { @@ -127,6 +146,8 @@ class CodeEntry { JITLineInfoTable* line_info_; Address instruction_start_; + std::vector inlined_function_infos_; + DISALLOW_COPY_AND_ASSIGN(CodeEntry); }; @@ -134,17 +155,6 @@ class CodeEntry { class ProfileTree; class ProfileNode { - private: - struct DeoptInfo { - DeoptInfo(const char* deopt_reason, SourcePosition deopt_position) - : deopt_reason(deopt_reason), deopt_position(deopt_position) {} - DeoptInfo(const DeoptInfo& info) - : deopt_reason(info.deopt_reason), - deopt_position(info.deopt_position) {} - const char* deopt_reason; - SourcePosition deopt_position; - }; - public: inline ProfileNode(ProfileTree* tree, CodeEntry* entry); @@ -163,7 +173,7 @@ class ProfileNode { bool GetLineTicks(v8::CpuProfileNode::LineTick* entries, unsigned int length) const; void CollectDeoptInfo(CodeEntry* entry); - const List& deopt_infos() const { return deopt_infos_; } + const std::vector& deopt_infos() const { return deopt_infos_; } void Print(int indent); @@ -186,7 +196,8 @@ class ProfileNode { unsigned id_; HashMap line_ticks_; - List deopt_infos_; + std::vector deopt_infos_; + DISALLOW_COPY_AND_ASSIGN(ProfileNode); }; diff --git a/test/cctest/test-cpu-profiler.cc b/test/cctest/test-cpu-profiler.cc index 249221d192..a8cbdd505c 100644 --- a/test/cctest/test-cpu-profiler.cc +++ b/test/cctest/test-cpu-profiler.cc @@ -56,6 +56,11 @@ static v8::Local GetFunction(v8::Context* env, const char* name) { } +static int offset(const char* src, const char* substring) { + return static_cast(strstr(src, substring) - src); +} + + static const char* reason(const i::Deoptimizer::DeoptReason reason) { return i::Deoptimizer::GetDeoptReason(reason); } @@ -1714,7 +1719,7 @@ const char* GetBranchDeoptReason(i::CpuProfile* iprofile, const char* branch[], v8::CpuProfile* profile = reinterpret_cast(iprofile); const ProfileNode* iopt_function = NULL; iopt_function = GetSimpleBranch(profile, branch, length); - CHECK_EQ(1, iopt_function->deopt_infos().length()); + CHECK_EQ(1, iopt_function->deopt_infos().size()); return iopt_function->deopt_infos()[0].deopt_reason; } @@ -1777,6 +1782,24 @@ TEST(CollectDeoptEvents) { v8::Script::Compile(v8_str(source))->Run(); i::CpuProfile* iprofile = iprofiler->GetProfile(0); iprofile->Print(); + /* The expected profile + [Top down]: + 0 (root) 0 #1 + 23 32 #2 + 1 opt_function2 31 #7 + 1 opt_function2 31 #8 + ;;; deopted at script_id: 31 position: 106 with reason + 'division by zero'. + 2 opt_function0 29 #3 + 4 opt_function0 29 #4 + ;;; deopted at script_id: 29 position: 108 with reason 'not a + heap number'. + 0 opt_function1 30 #5 + 1 opt_function1 30 #6 + ;;; deopted at script_id: 30 position: 108 with reason 'lost + precision or NaN'. + */ + { const char* branch[] = {"", "opt_function0", "opt_function0"}; CHECK_EQ(reason(i::Deoptimizer::kNotAHeapNumber), @@ -1814,3 +1837,197 @@ TEST(SourceLocation) { v8::Script::Compile(v8_str(source))->Run(); } + + +static const char* inlined_source = + "function opt_function(left, right) { var k = left / 10; var r = 10 / " + "right; return k + r; }\n"; +// 0.........1.........2.........3.........4....*....5.........6......*..7 + + +// deopt at the first level inlined function +TEST(DeoptAtFirstLevelInlinedSource) { + if (!CcTest::i_isolate()->use_crankshaft() || i::FLAG_always_opt) return; + i::FLAG_allow_natives_syntax = true; + v8::HandleScope scope(CcTest::isolate()); + v8::Local env = CcTest::NewContext(PROFILER_EXTENSION); + v8::Context::Scope context_scope(env); + v8::Isolate* isolate = env->GetIsolate(); + v8::CpuProfiler* profiler = isolate->GetCpuProfiler(); + i::CpuProfiler* iprofiler = reinterpret_cast(profiler); + + // 0.........1.........2.........3.........4.........5.........6.........7 + const char* source = + "function test(left, right) { return opt_function(left, right); }\n" + "\n" + "startProfiling();\n" + "\n" + "test(10, 10);\n" + "\n" + "%OptimizeFunctionOnNextCall(test)\n" + "\n" + "test(10, 10);\n" + "\n" + "test(undefined, 10);\n" + "\n" + "stopProfiling();\n" + "\n"; + + v8::Handle inlined_script = v8_compile(inlined_source); + inlined_script->Run(); + int inlined_script_id = inlined_script->GetUnboundScript()->GetId(); + + v8::Handle script = v8_compile(source); + script->Run(); + int script_id = script->GetUnboundScript()->GetId(); + + i::CpuProfile* iprofile = iprofiler->GetProfile(0); + iprofile->Print(); + /* The expected profile output + [Top down]: + 0 (root) 0 #1 + 10 30 #2 + 1 test 30 #3 + ;;; deopted at script_id: 29 position: 45 with reason 'not a + heap number'. + ;;; Inline point: script_id 30 position: 36. + 4 opt_function 29 #4 + */ + v8::CpuProfile* profile = reinterpret_cast(iprofile); + + const char* branch[] = {"", "test"}; + const ProfileNode* itest_node = + GetSimpleBranch(profile, branch, arraysize(branch)); + const std::vector& deopt_infos = itest_node->deopt_infos(); + CHECK_EQ(1, deopt_infos.size()); + + const i::DeoptInfo& info = deopt_infos[0]; + CHECK_EQ(reason(i::Deoptimizer::kNotAHeapNumber), info.deopt_reason); + CHECK_EQ(2, info.stack.size()); + CHECK_EQ(inlined_script_id, info.stack[0].script_id); + CHECK_EQ(offset(inlined_source, "left /"), info.stack[0].position); + CHECK_EQ(script_id, info.stack[1].script_id); + CHECK_EQ(offset(source, "opt_function(left,"), info.stack[1].position); + + iprofiler->DeleteProfile(iprofile); +} + + +// deopt at the second level inlined function +TEST(DeoptAtSecondLevelInlinedSource) { + if (!CcTest::i_isolate()->use_crankshaft() || i::FLAG_always_opt) return; + i::FLAG_allow_natives_syntax = true; + v8::HandleScope scope(CcTest::isolate()); + v8::Local env = CcTest::NewContext(PROFILER_EXTENSION); + v8::Context::Scope context_scope(env); + v8::Isolate* isolate = env->GetIsolate(); + v8::CpuProfiler* profiler = isolate->GetCpuProfiler(); + i::CpuProfiler* iprofiler = reinterpret_cast(profiler); + + // 0.........1.........2.........3.........4.........5.........6.........7 + const char* source = + "function test2(left, right) { return opt_function(left, right); }\n" + "function test1(left, right) { return test2(left, right); }\n" + "\n" + "startProfiling();\n" + "\n" + "test1(10, 10);\n" + "\n" + "%OptimizeFunctionOnNextCall(test1)\n" + "\n" + "test1(10, 10);\n" + "\n" + "test1(undefined, 10);\n" + "\n" + "stopProfiling();\n" + "\n"; + + v8::Handle inlined_script = v8_compile(inlined_source); + inlined_script->Run(); + int inlined_script_id = inlined_script->GetUnboundScript()->GetId(); + + v8::Handle script = v8_compile(source); + script->Run(); + int script_id = script->GetUnboundScript()->GetId(); + + i::CpuProfile* iprofile = iprofiler->GetProfile(0); + iprofile->Print(); + /* The expected profile output + [Top down]: + 0 (root) 0 #1 + 11 30 #2 + 1 test1 30 #3 + ;;; deopted at script_id: 29 position: 45 with reason 'not a + heap number'. + ;;; Inline point: script_id 30 position: 37. + ;;; Inline point: script_id 30 position: 103. + 1 test2 30 #4 + 3 opt_function 29 #5 + */ + + v8::CpuProfile* profile = reinterpret_cast(iprofile); + + const char* branch[] = {"", "test1"}; + const ProfileNode* itest_node = + GetSimpleBranch(profile, branch, arraysize(branch)); + const std::vector& deopt_infos = itest_node->deopt_infos(); + CHECK_EQ(1, deopt_infos.size()); + + const i::DeoptInfo info = deopt_infos[0]; + CHECK_EQ(reason(i::Deoptimizer::kNotAHeapNumber), info.deopt_reason); + CHECK_EQ(3, info.stack.size()); + CHECK_EQ(inlined_script_id, info.stack[0].script_id); + CHECK_EQ(offset(inlined_source, "left /"), info.stack[0].position); + CHECK_EQ(script_id, info.stack[1].script_id); + CHECK_EQ(offset(source, "opt_function(left,"), info.stack[1].position); + CHECK_EQ(offset(source, "test2(left, right);"), info.stack[2].position); + + iprofiler->DeleteProfile(iprofile); +} + + +// deopt in untracked function +TEST(DeoptUntrackedFunction) { + if (!CcTest::i_isolate()->use_crankshaft() || i::FLAG_always_opt) return; + i::FLAG_allow_natives_syntax = true; + v8::HandleScope scope(CcTest::isolate()); + v8::Local env = CcTest::NewContext(PROFILER_EXTENSION); + v8::Context::Scope context_scope(env); + v8::Isolate* isolate = env->GetIsolate(); + v8::CpuProfiler* profiler = isolate->GetCpuProfiler(); + i::CpuProfiler* iprofiler = reinterpret_cast(profiler); + + // 0.........1.........2.........3.........4.........5.........6.........7 + const char* source = + "function test(left, right) { return opt_function(left, right); }\n" + "\n" + "test(10, 10);\n" + "\n" + "%OptimizeFunctionOnNextCall(test)\n" + "\n" + "test(10, 10);\n" + "\n" + "startProfiling();\n" // profiler started after compilation. + "\n" + "test(undefined, 10);\n" + "\n" + "stopProfiling();\n" + "\n"; + + v8::Handle inlined_script = v8_compile(inlined_source); + inlined_script->Run(); + + v8::Handle script = v8_compile(source); + script->Run(); + + i::CpuProfile* iprofile = iprofiler->GetProfile(0); + iprofile->Print(); + v8::CpuProfile* profile = reinterpret_cast(iprofile); + + const char* branch[] = {"", "test"}; + const ProfileNode* itest_node = + GetSimpleBranch(profile, branch, arraysize(branch)); + CHECK_EQ(0, itest_node->deopt_infos().size()); + + iprofiler->DeleteProfile(iprofile); +}