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}
This commit is contained in:
loislo 2015-03-24 05:46:13 -07:00 committed by Commit bot
parent 6fcc22dce1
commit ae461b9ed0
7 changed files with 296 additions and 26 deletions

View File

@ -125,7 +125,8 @@ CompilationInfo::CompilationInfo(ParseInfo* parse_info, CodeStub* code_stub,
no_frame_ranges_(isolate->cpu_profiler()->is_profiling()
? new List<OffsetRange>(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),

View File

@ -97,7 +97,7 @@ struct InlinedFunctionInfo {
SourcePosition inline_position;
int script_id;
int start_position;
std::vector<int> deopt_pc_offsets;
std::vector<size_t> 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<InlinedFunctionInfo>& inlined_function_infos() {
return inlined_function_infos_;
}
void LogDeoptCallPosition(int pc_offset, int inlining_id);
int TraceInlinedFunction(Handle<SharedFunctionInfo> shared,

View File

@ -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();

View File

@ -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();
}

View File

@ -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<int>(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<int>(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<int>(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();

View File

@ -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<Frame> 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<OffsetRange>* ranges) {
no_frame_ranges_ = ranges;
}
void set_inlined_function_infos(
const std::vector<InlinedFunctionInfo>& infos) {
inlined_function_infos_ = infos;
}
const std::vector<InlinedFunctionInfo> 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<InlinedFunctionInfo> 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<DeoptInfo>& deopt_infos() const { return deopt_infos_; }
const std::vector<DeoptInfo>& deopt_infos() const { return deopt_infos_; }
void Print(int indent);
@ -186,7 +196,8 @@ class ProfileNode {
unsigned id_;
HashMap line_ticks_;
List<DeoptInfo> deopt_infos_;
std::vector<DeoptInfo> deopt_infos_;
DISALLOW_COPY_AND_ASSIGN(ProfileNode);
};

View File

@ -56,6 +56,11 @@ static v8::Local<v8::Function> GetFunction(v8::Context* env, const char* name) {
}
static int offset(const char* src, const char* substring) {
return static_cast<int>(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<v8::CpuProfile*>(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<v8::Context> 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<i::CpuProfiler*>(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<v8::Script> inlined_script = v8_compile(inlined_source);
inlined_script->Run();
int inlined_script_id = inlined_script->GetUnboundScript()->GetId();
v8::Handle<v8::Script> 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<v8::CpuProfile*>(iprofile);
const char* branch[] = {"", "test"};
const ProfileNode* itest_node =
GetSimpleBranch(profile, branch, arraysize(branch));
const std::vector<i::DeoptInfo>& 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<v8::Context> 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<i::CpuProfiler*>(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<v8::Script> inlined_script = v8_compile(inlined_source);
inlined_script->Run();
int inlined_script_id = inlined_script->GetUnboundScript()->GetId();
v8::Handle<v8::Script> 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<v8::CpuProfile*>(iprofile);
const char* branch[] = {"", "test1"};
const ProfileNode* itest_node =
GetSimpleBranch(profile, branch, arraysize(branch));
const std::vector<i::DeoptInfo>& 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<v8::Context> 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<i::CpuProfiler*>(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<v8::Script> inlined_script = v8_compile(inlined_source);
inlined_script->Run();
v8::Handle<v8::Script> script = v8_compile(source);
script->Run();
i::CpuProfile* iprofile = iprofiler->GetProfile(0);
iprofile->Print();
v8::CpuProfile* profile = reinterpret_cast<v8::CpuProfile*>(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);
}