From 12d815b36e5d0b79688ba399d25ed1d44e69dd15 Mon Sep 17 00:00:00 2001 From: jarin Date: Wed, 22 Mar 2017 09:02:25 -0700 Subject: [PATCH] [profiler] Web UI: add summary of opts/deopts. This adds optimization and deoptimization counts to the Web UI. Also, the function timeline now shows optimization and deoptimization marks. Review-Url: https://codereview.chromium.org/2753543006 Cr-Commit-Position: refs/heads/master@{#44033} --- src/code-events.h | 9 +- src/deoptimizer.cc | 22 +- src/log.cc | 67 ++- src/log.h | 6 +- src/profiler/profiler-listener.cc | 2 +- src/profiler/profiler-listener.h | 3 +- test/cctest/test-log.cc | 8 +- test/mjsunit/tools/profile.js | 6 +- .../tools/tickprocessor-test-func-info.log | 6 +- test/mjsunit/tools/tickprocessor-test.log | 12 +- tools/profile.js | 44 +- tools/profview/index.html | 12 +- tools/profview/profile-utils.js | 90 ++++ tools/profview/profview.js | 429 ++++++++++++++---- tools/tickprocessor.js | 23 +- 15 files changed, 606 insertions(+), 133 deletions(-) diff --git a/src/code-events.h b/src/code-events.h index db43d88b68..056aa4139d 100644 --- a/src/code-events.h +++ b/src/code-events.h @@ -105,7 +105,9 @@ class CodeEventListener { virtual void CodeMovingGCEvent() = 0; virtual void CodeDisableOptEvent(AbstractCode* code, SharedFunctionInfo* shared) = 0; - virtual void CodeDeoptEvent(Code* code, Address pc, int fp_to_sp_delta) = 0; + enum DeoptKind { kSoft, kLazy, kEager }; + virtual void CodeDeoptEvent(Code* code, DeoptKind kind, Address pc, + int fp_to_sp_delta) = 0; }; class CodeEventDispatcher { @@ -170,8 +172,9 @@ class CodeEventDispatcher { void CodeDisableOptEvent(AbstractCode* code, SharedFunctionInfo* shared) { CODE_EVENT_DISPATCH(CodeDisableOptEvent(code, shared)); } - void CodeDeoptEvent(Code* code, Address pc, int fp_to_sp_delta) { - CODE_EVENT_DISPATCH(CodeDeoptEvent(code, pc, fp_to_sp_delta)); + void CodeDeoptEvent(Code* code, CodeEventListener::DeoptKind kind, Address pc, + int fp_to_sp_delta) { + CODE_EVENT_DISPATCH(CodeDeoptEvent(code, kind, pc, fp_to_sp_delta)); } #undef CODE_EVENT_DISPATCH diff --git a/src/deoptimizer.cc b/src/deoptimizer.cc index beb9945c47..9421080075 100644 --- a/src/deoptimizer.cc +++ b/src/deoptimizer.cc @@ -445,6 +445,24 @@ const char* Deoptimizer::MessageFor(BailoutType type) { return NULL; } +namespace { + +CodeEventListener::DeoptKind DeoptKindOfBailoutType( + Deoptimizer::BailoutType bailout_type) { + switch (bailout_type) { + case Deoptimizer::EAGER: + return CodeEventListener::kEager; + case Deoptimizer::SOFT: + return CodeEventListener::kSoft; + case Deoptimizer::LAZY: + return CodeEventListener::kLazy; + } + UNREACHABLE(); + return CodeEventListener::kEager; +} + +} // namespace + Deoptimizer::Deoptimizer(Isolate* isolate, JSFunction* function, BailoutType type, unsigned bailout_id, Address from, int fp_to_sp_delta) @@ -509,7 +527,9 @@ Deoptimizer::Deoptimizer(Isolate* isolate, JSFunction* function, disallow_heap_allocation_ = new DisallowHeapAllocation(); #endif // DEBUG if (compiled_code_->kind() == Code::OPTIMIZED_FUNCTION) { - PROFILE(isolate_, CodeDeoptEvent(compiled_code_, from_, fp_to_sp_delta_)); + PROFILE(isolate_, + CodeDeoptEvent(compiled_code_, DeoptKindOfBailoutType(type), from_, + fp_to_sp_delta_)); } unsigned size = ComputeInputFrameSize(); int parameter_count = diff --git a/src/log.cc b/src/log.cc index 46872a150c..d32ce1aa8e 100644 --- a/src/log.cc +++ b/src/log.cc @@ -843,12 +843,41 @@ void Logger::SharedLibraryEvent(const std::string& library_path, msg.WriteToLogFile(); } - -void Logger::CodeDeoptEvent(Code* code, Address pc, int fp_to_sp_delta) { - if (!log_->IsEnabled() || !FLAG_log_internal_timer_events) return; +void Logger::CodeDeoptEvent(Code* code, DeoptKind kind, Address pc, + int fp_to_sp_delta) { + if (!log_->IsEnabled()) return; + Deoptimizer::DeoptInfo info = Deoptimizer::GetDeoptInfo(code, pc); Log::MessageBuilder msg(log_); int since_epoch = static_cast(timer_.Elapsed().InMicroseconds()); - msg.Append("code-deopt,%d,%d", since_epoch, code->CodeSize()); + msg.Append("code-deopt,%d,%d,", since_epoch, code->CodeSize()); + msg.AppendAddress(code->address()); + + // Deoptimization position. + std::ostringstream deopt_location; + int inlining_id = -1; + int script_offset = -1; + if (info.position.IsKnown()) { + info.position.Print(deopt_location, code); + inlining_id = info.position.InliningId(); + script_offset = info.position.ScriptOffset(); + } else { + deopt_location << ""; + } + msg.Append(",%d,%d,", inlining_id, script_offset); + switch (kind) { + case kLazy: + msg.Append("\"lazy\","); + break; + case kSoft: + msg.Append("\"soft\","); + break; + case kEager: + msg.Append("\"eager\","); + break; + } + msg.AppendDoubleQuotedString(deopt_location.str().c_str()); + msg.Append(","); + msg.AppendDoubleQuotedString(DeoptimizeReasonToString(info.deopt_reason)); msg.WriteToLogFile(); } @@ -972,6 +1001,10 @@ void Logger::CallbackEventInternal(const char* prefix, Name* name, msg.Append("%s,%s,-2,", kLogEventsNames[CodeEventListener::CODE_CREATION_EVENT], kLogEventsNames[CodeEventListener::CALLBACK_TAG]); + int timestamp = timer_.IsStarted() + ? static_cast(timer_.Elapsed().InMicroseconds()) + : -1; + msg.Append("%d,", timestamp); msg.AppendAddress(entry_point); if (name->IsString()) { std::unique_ptr str = @@ -1007,23 +1040,31 @@ void Logger::SetterCallbackEvent(Name* name, Address entry_point) { CallbackEventInternal("set ", name, entry_point); } -static void AppendCodeCreateHeader(Log::MessageBuilder* msg, - CodeEventListener::LogEventsAndTags tag, - AbstractCode* code) { +namespace { + +void AppendCodeCreateHeader(Log::MessageBuilder* msg, + CodeEventListener::LogEventsAndTags tag, + AbstractCode* code, base::ElapsedTimer* timer) { DCHECK(msg); msg->Append("%s,%s,%d,", kLogEventsNames[CodeEventListener::CODE_CREATION_EVENT], kLogEventsNames[tag], code->kind()); + int timestamp = timer->IsStarted() + ? static_cast(timer->Elapsed().InMicroseconds()) + : -1; + msg->Append("%d,", timestamp); msg->AppendAddress(code->address()); msg->Append(",%d,", code->ExecutableSize()); } +} // namespace + void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag, AbstractCode* code, const char* comment) { if (!is_logging_code_events()) return; if (!FLAG_log_code || !log_->IsEnabled()) return; Log::MessageBuilder msg(log_); - AppendCodeCreateHeader(&msg, tag, code); + AppendCodeCreateHeader(&msg, tag, code, &timer_); msg.AppendDoubleQuotedString(comment); msg.WriteToLogFile(); } @@ -1033,7 +1074,7 @@ void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag, if (!is_logging_code_events()) return; if (!FLAG_log_code || !log_->IsEnabled()) return; Log::MessageBuilder msg(log_); - AppendCodeCreateHeader(&msg, tag, code); + AppendCodeCreateHeader(&msg, tag, code, &timer_); if (name->IsString()) { msg.Append('"'); msg.AppendDetailed(String::cast(name), false); @@ -1055,7 +1096,7 @@ void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag, } Log::MessageBuilder msg(log_); - AppendCodeCreateHeader(&msg, tag, code); + AppendCodeCreateHeader(&msg, tag, code, &timer_); if (name->IsString()) { std::unique_ptr str = String::cast(name)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); @@ -1079,7 +1120,7 @@ void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag, if (!is_logging_code_events()) return; if (!FLAG_log_code || !log_->IsEnabled()) return; Log::MessageBuilder msg(log_); - AppendCodeCreateHeader(&msg, tag, code); + AppendCodeCreateHeader(&msg, tag, code, &timer_); std::unique_ptr name = shared->DebugName()->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); msg.Append("\"%s ", name.get()); @@ -1101,7 +1142,7 @@ void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag, if (!is_logging_code_events()) return; if (!FLAG_log_code || !log_->IsEnabled()) return; Log::MessageBuilder msg(log_); - AppendCodeCreateHeader(&msg, tag, code); + AppendCodeCreateHeader(&msg, tag, code, &timer_); msg.Append("\"args_count: %d\"", args_count); msg.WriteToLogFile(); } @@ -1130,7 +1171,7 @@ void Logger::RegExpCodeCreateEvent(AbstractCode* code, String* source) { if (!is_logging_code_events()) return; if (!FLAG_log_code || !log_->IsEnabled()) return; Log::MessageBuilder msg(log_); - AppendCodeCreateHeader(&msg, CodeEventListener::REG_EXP_TAG, code); + AppendCodeCreateHeader(&msg, CodeEventListener::REG_EXP_TAG, code, &timer_); msg.Append('"'); msg.AppendDetailed(source, false); msg.Append('"'); diff --git a/src/log.h b/src/log.h index 837ac8baaf..0ed0580c37 100644 --- a/src/log.h +++ b/src/log.h @@ -185,7 +185,8 @@ class Logger : public CodeEventListener { void CodeNameEvent(Address addr, int pos, const char* code_name); - void CodeDeoptEvent(Code* code, Address pc, int fp_to_sp_delta); + void CodeDeoptEvent(Code* code, DeoptKind kind, Address pc, + int fp_to_sp_delta); void ICEvent(const char* type, bool keyed, const Address pc, int line, int column, Map* map, Object* key, char old_state, @@ -394,7 +395,8 @@ class CodeEventLogger : public CodeEventListener { void SetterCallbackEvent(Name* name, Address entry_point) override {} void SharedFunctionInfoMoveEvent(Address from, Address to) override {} void CodeMovingGCEvent() override {} - void CodeDeoptEvent(Code* code, Address pc, int fp_to_sp_delta) override {} + void CodeDeoptEvent(Code* code, DeoptKind kind, Address pc, + int fp_to_sp_delta) override {} private: class NameBuffer; diff --git a/src/profiler/profiler-listener.cc b/src/profiler/profiler-listener.cc index bacfffaa73..7eb323a14e 100644 --- a/src/profiler/profiler-listener.cc +++ b/src/profiler/profiler-listener.cc @@ -145,7 +145,7 @@ void ProfilerListener::CodeDisableOptEvent(AbstractCode* code, DispatchCodeEvent(evt_rec); } -void ProfilerListener::CodeDeoptEvent(Code* code, Address pc, +void ProfilerListener::CodeDeoptEvent(Code* code, DeoptKind kind, Address pc, int fp_to_sp_delta) { CodeEventsContainer evt_rec(CodeEventRecord::CODE_DEOPT); CodeDeoptEventRecord* rec = &evt_rec.CodeDeoptEventRecord_; diff --git a/src/profiler/profiler-listener.h b/src/profiler/profiler-listener.h index 500b7ae6be..f4a9e24c7d 100644 --- a/src/profiler/profiler-listener.h +++ b/src/profiler/profiler-listener.h @@ -43,7 +43,8 @@ class ProfilerListener : public CodeEventListener { void CodeMoveEvent(AbstractCode* from, Address to) override; void CodeDisableOptEvent(AbstractCode* code, SharedFunctionInfo* shared) override; - void CodeDeoptEvent(Code* code, Address pc, int fp_to_sp_delta) override; + void CodeDeoptEvent(Code* code, DeoptKind kind, Address pc, + int fp_to_sp_delta) override; void GetterCallbackEvent(Name* name, Address entry_point) override; void RegExpCodeCreateEvent(AbstractCode* code, String* source) override; void SetterCallbackEvent(Name* name, Address entry_point) override; diff --git a/test/cctest/test-log.cc b/test/cctest/test-log.cc index f208c5a7b6..d18fd28d3e 100644 --- a/test/cctest/test-log.cc +++ b/test/cctest/test-log.cc @@ -376,7 +376,7 @@ TEST(LogCallbacks) { ObjMethod1_entry = *FUNCTION_ENTRYPOINT_ADDRESS(ObjMethod1_entry); #endif i::EmbeddedVector ref_data; - i::SNPrintF(ref_data, "code-creation,Callback,-2,%p,1,\"method1\"", + i::SNPrintF(ref_data, "code-creation,Callback,-2,-1,%p,1,\"method1\"", static_cast(ObjMethod1_entry)); CHECK(StrNStr(log.start(), ref_data.start(), log.length())); @@ -429,7 +429,7 @@ TEST(LogAccessorCallbacks) { #endif EmbeddedVector prop1_getter_record; i::SNPrintF(prop1_getter_record, - "code-creation,Callback,-2,%p,1,\"get prop1\"", + "code-creation,Callback,-2,-1,%p,1,\"get prop1\"", static_cast(Prop1Getter_entry)); CHECK(StrNStr(log.start(), prop1_getter_record.start(), log.length())); @@ -439,7 +439,7 @@ TEST(LogAccessorCallbacks) { #endif EmbeddedVector prop1_setter_record; i::SNPrintF(prop1_setter_record, - "code-creation,Callback,-2,%p,1,\"set prop1\"", + "code-creation,Callback,-2,-1,%p,1,\"set prop1\"", static_cast(Prop1Setter_entry)); CHECK(StrNStr(log.start(), prop1_setter_record.start(), log.length())); @@ -449,7 +449,7 @@ TEST(LogAccessorCallbacks) { #endif EmbeddedVector prop2_getter_record; i::SNPrintF(prop2_getter_record, - "code-creation,Callback,-2,%p,1,\"get prop2\"", + "code-creation,Callback,-2,-1,%p,1,\"get prop2\"", static_cast(Prop2Getter_entry)); CHECK(StrNStr(log.start(), prop2_getter_record.start(), log.length())); log.Dispose(); diff --git a/test/mjsunit/tools/profile.js b/test/mjsunit/tools/profile.js index fcd3034f4e..c9d2da78dc 100644 --- a/test/mjsunit/tools/profile.js +++ b/test/mjsunit/tools/profile.js @@ -78,9 +78,9 @@ ProfileTestDriver.prototype.addFunctions_ = function() { this.profile.addLibrary('lib2', 0x21000, 0x22000); this.profile.addStaticCode('lib2-f1', 0x21100, 0x21900); this.profile.addStaticCode('lib2-f2', 0x21200, 0x21500); - this.profile.addCode('T', 'F1', 0x50100, 0x100); - this.profile.addCode('T', 'F2', 0x50200, 0x100); - this.profile.addCode('T', 'F3', 0x50400, 0x100); + this.profile.addCode('T', 'F1', 1, 0x50100, 0x100); + this.profile.addCode('T', 'F2', 2, 0x50200, 0x100); + this.profile.addCode('T', 'F3', 3, 0x50400, 0x100); }; diff --git a/test/mjsunit/tools/tickprocessor-test-func-info.log b/test/mjsunit/tools/tickprocessor-test-func-info.log index fcbf3b1a65..0d7f39d29e 100644 --- a/test/mjsunit/tools/tickprocessor-test-func-info.log +++ b/test/mjsunit/tools/tickprocessor-test-func-info.log @@ -2,9 +2,9 @@ shared-library,"shell",0x08048000,0x081ee000,0 shared-library,"/lib32/libm-2.7.so",0xf7db6000,0xf7dd9000,0 shared-library,"ffffe000-fffff000",0xffffe000,0xfffff000,0 profiler,"begin",1 -code-creation,Stub,0,0x424260,348,"CompareStub_GE" -code-creation,LazyCompile,0,0x2a8100,18535,"DrawQube 3d-cube.js:188",0xf43abcac, -code-creation,LazyCompile,0,0x480100,3908,"DrawLine 3d-cube.js:17",0xf43abc50, +code-creation,Stub,0,100,0x424260,348,"CompareStub_GE" +code-creation,LazyCompile,0,101,0x2a8100,18535,"DrawQube 3d-cube.js:188",0xf43abcac, +code-creation,LazyCompile,0,102,0x480100,3908,"DrawLine 3d-cube.js:17",0xf43abc50, tick,0x424284,0,0,0x480600,0,0x2aaaa5 tick,0x42429f,0,0,0x480600,0,0x2aacb4 tick,0x48063d,0,0,0x2d0f7c,0,0x2aaec6 diff --git a/test/mjsunit/tools/tickprocessor-test.log b/test/mjsunit/tools/tickprocessor-test.log index fbc868ebf2..713790015d 100644 --- a/test/mjsunit/tools/tickprocessor-test.log +++ b/test/mjsunit/tools/tickprocessor-test.log @@ -2,13 +2,13 @@ shared-library,"shell",0x08048000,0x081ee000,0 shared-library,"/lib32/libm-2.7.so",0xf7db6000,0xf7dd9000,0 shared-library,"ffffe000-fffff000",0xffffe000,0xfffff000,0 profiler,"begin",1 -code-creation,Stub,0,0xf540a100,474,"CEntryStub" -code-creation,Script,0,0xf541cd80,736,"exp.js" -code-creation,Stub,0,0xf541d0e0,47,"RuntimeStub_Math_exp" -code-creation,LazyCompile,0,0xf541d120,145,"exp native math.js:41" +code-creation,Stub,0,100,0xf540a100,474,"CEntryStub" +code-creation,Script,0,101,0xf541cd80,736,"exp.js" +code-creation,Stub,0,102,0xf541d0e0,47,"RuntimeStub_Math_exp" +code-creation,LazyCompile,0,103,0xf541d120,145,"exp native math.js:41" function-creation,0xf441d280,0xf541d120 -code-creation,LoadIC,0,0xf541d280,117,"j" -code-creation,LoadIC,0,0xf541d360,63,"i" +code-creation,LoadIC,0,104,0xf541d280,117,"j" +code-creation,LoadIC,0,105,0xf541d360,63,"i" tick,0x80f82d1,0,0,0,0,0xf541ce5c tick,0x80f89a1,0,0,0,0,0xf541ce5c tick,0x8123b5c,0,0,0,0,0xf541d1a1,0xf541ceea diff --git a/tools/profile.js b/tools/profile.js index c04bed31f1..de9c42c5b1 100644 --- a/tools/profile.js +++ b/tools/profile.js @@ -135,7 +135,7 @@ Profile.prototype.addStaticCode = function( * @param {number} size Code entry size. */ Profile.prototype.addCode = function( - type, name, start, size) { + type, name, timestamp, start, size) { var entry = new Profile.DynamicCodeEntry(size, type, name); this.codeMap_.addCode(start, entry); return entry; @@ -153,7 +153,7 @@ Profile.prototype.addCode = function( * @param {Profile.CodeState} state Optimization state. */ Profile.prototype.addFuncCode = function( - type, name, start, size, funcAddr, state) { + type, name, timestamp, start, size, funcAddr, state) { // As code and functions are in the same address space, // it is safe to put them in a single code map. var func = this.codeMap_.findDynamicEntryByStartAddress(funcAddr); @@ -192,6 +192,10 @@ Profile.prototype.moveCode = function(from, to) { } }; +Profile.prototype.deoptCode = function( + timestamp, code, inliningId, scriptOffset, bailoutType, + sourcePositionText, deoptReasonText) { +}; /** * Reports about deletion of a dynamic code entry. @@ -864,18 +868,23 @@ JsonProfile.prototype.addStaticCode = function( }; JsonProfile.prototype.addCode = function( - kind, name, start, size) { + kind, name, timestamp, start, size) { var entry = new CodeMap.CodeEntry(size, name, 'CODE'); this.codeMap_.addCode(start, entry); entry.codeId = this.codeEntries_.length; - this.codeEntries_.push({name : entry.name, type : entry.type, kind : kind}); + this.codeEntries_.push({ + name : entry.name, + timestamp: timestamp, + type : entry.type, + kind : kind + }); return entry; }; JsonProfile.prototype.addFuncCode = function( - kind, name, start, size, funcAddr, state) { + kind, name, timestamp, start, size, funcAddr, state) { // As code and functions are in the same address space, // it is safe to put them in a single code map. var func = this.codeMap_.findDynamicEntryByStartAddress(funcAddr); @@ -921,7 +930,8 @@ JsonProfile.prototype.addFuncCode = function( name : entry.name, type : entry.type, kind : kind, - func : func.funcId + func : func.funcId, + tm : timestamp }); } return entry; @@ -935,6 +945,28 @@ JsonProfile.prototype.moveCode = function(from, to) { } }; +JsonProfile.prototype.deoptCode = function( + timestamp, code, inliningId, scriptOffset, bailoutType, + sourcePositionText, deoptReasonText) { + let entry = this.codeMap_.findDynamicEntryByStartAddress(code); + if (entry) { + let codeId = entry.codeId; + if (!this.codeEntries_[codeId].deopt) { + // Only add the deopt if there was no deopt before. + // The subsequent deoptimizations should be lazy deopts for + // other on-stack activations. + this.codeEntries_[codeId].deopt = { + tm : timestamp, + inliningId : inliningId, + scriptOffset : scriptOffset, + posText : sourcePositionText, + reason : deoptReasonText, + bailoutType : bailoutType + }; + } + } +}; + JsonProfile.prototype.deleteCode = function(start) { try { this.codeMap_.deleteCode(start); diff --git a/tools/profview/index.html b/tools/profview/index.html index b281de4c33..32f7c7b70f 100644 --- a/tools/profview/index.html +++ b/tools/profview/index.html @@ -64,10 +64,10 @@ found in the LICENSE file. -->
-