From 028f85a244289a8daed21b6e984de574452b7df5 Mon Sep 17 00:00:00 2001 From: "yangguo@chromium.org" Date: Wed, 28 Nov 2012 11:01:10 +0000 Subject: [PATCH] Include more information in --prof log. Main changes: - include timestamps in profile ticks - include code kind in code create events - time execution in external code - changed plot-timer-events.js to show the code kind being executed R=jkummerow@chromium.org BUG= Review URL: https://chromiumcodereview.appspot.com/11428025 git-svn-id: http://v8.googlecode.com/svn/branches/bleeding_edge@13074 ce2b1a6d-e550-0410-aec6-3dcde31c8c00 --- src/log.cc | 45 +++- src/log.h | 4 + src/vm-state-inl.h | 8 + test/cctest/test-log.cc | 8 +- .../mjsunit/tools/tickprocessor-test-func-info.log | 12 +- test/mjsunit/tools/tickprocessor-test.log | 38 +-- tools/plot-timer-events | 1 + tools/plot-timer-events.js | 285 +++++++++++++++------ tools/tickprocessor.js | 11 +- 9 files changed, 290 insertions(+), 122 deletions(-) diff --git a/src/log.cc b/src/log.cc index 463ecc1..a40bd92 100644 --- a/src/log.cc +++ b/src/log.cc @@ -716,6 +716,20 @@ void Logger::TimerEvent(const char* name, int64_t start, int64_t end) { } +void Logger::ExternalSwitch(StateTag old_tag, StateTag new_tag) { + if (old_tag != EXTERNAL && new_tag == EXTERNAL) { + enter_external_ = OS::Ticks(); + } + if (old_tag == EXTERNAL && new_tag != EXTERNAL && enter_external_ != 0) { + TimerEvent("V8.External", enter_external_, OS::Ticks()); + enter_external_ = 0; + } +} + + +int64_t Logger::enter_external_ = 0; + + void Logger::TimerEventScope::LogTimerEvent() { LOG(isolate_, TimerEvent(name_, start_, OS::Ticks())); } @@ -900,7 +914,7 @@ void Logger::CallbackEventInternal(const char* prefix, const char* name, Address entry_point) { if (!log_->IsEnabled() || !FLAG_log_code) return; LogMessageBuilder msg(this); - msg.Append("%s,%s,", + msg.Append("%s,%s,-3,", kLogEventsNames[CODE_CREATION_EVENT], kLogEventsNames[CALLBACK_TAG]); msg.AppendAddress(entry_point); @@ -956,9 +970,10 @@ void Logger::CodeCreateEvent(LogEventsAndTags tag, } if (!FLAG_log_code) return; LogMessageBuilder msg(this); - msg.Append("%s,%s,", + msg.Append("%s,%s,%d,", kLogEventsNames[CODE_CREATION_EVENT], - kLogEventsNames[tag]); + kLogEventsNames[tag], + code->kind()); msg.AppendAddress(code->address()); msg.Append(",%d,\"", code->ExecutableSize()); for (const char* p = comment; *p != '\0'; p++) { @@ -995,9 +1010,10 @@ void Logger::CodeCreateEvent(LogEventsAndTags tag, } if (!FLAG_log_code) return; LogMessageBuilder msg(this); - msg.Append("%s,%s,", + msg.Append("%s,%s,%d,", kLogEventsNames[CODE_CREATION_EVENT], - kLogEventsNames[tag]); + kLogEventsNames[tag], + code->kind()); msg.AppendAddress(code->address()); msg.Append(",%d,\"", code->ExecutableSize()); msg.AppendDetailed(name, false); @@ -1047,9 +1063,10 @@ void Logger::CodeCreateEvent(LogEventsAndTags tag, LogMessageBuilder msg(this); SmartArrayPointer str = name->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); - msg.Append("%s,%s,", + msg.Append("%s,%s,%d,", kLogEventsNames[CODE_CREATION_EVENT], - kLogEventsNames[tag]); + kLogEventsNames[tag], + code->kind()); msg.AppendAddress(code->address()); msg.Append(",%d,\"%s\",", code->ExecutableSize(), *str); msg.AppendAddress(shared->address()); @@ -1094,9 +1111,10 @@ void Logger::CodeCreateEvent(LogEventsAndTags tag, shared->DebugName()->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); SmartArrayPointer sourcestr = source->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); - msg.Append("%s,%s,", + msg.Append("%s,%s,%d,", kLogEventsNames[CODE_CREATION_EVENT], - kLogEventsNames[tag]); + kLogEventsNames[tag], + code->kind()); msg.AppendAddress(code->address()); msg.Append(",%d,\"%s %s:%d\",", code->ExecutableSize(), @@ -1130,9 +1148,10 @@ void Logger::CodeCreateEvent(LogEventsAndTags tag, Code* code, int args_count) { } if (!FLAG_log_code) return; LogMessageBuilder msg(this); - msg.Append("%s,%s,", + msg.Append("%s,%s,%d,", kLogEventsNames[CODE_CREATION_EVENT], - kLogEventsNames[tag]); + kLogEventsNames[tag], + code->kind()); msg.AppendAddress(code->address()); msg.Append(",%d,\"args_count: %d\"", code->ExecutableSize(), args_count); msg.Append('\n'); @@ -1167,7 +1186,7 @@ void Logger::RegExpCodeCreateEvent(Code* code, String* source) { } if (!FLAG_log_code) return; LogMessageBuilder msg(this); - msg.Append("%s,%s,", + msg.Append("%s,%s,-2,", kLogEventsNames[CODE_CREATION_EVENT], kLogEventsNames[REG_EXP_TAG]); msg.AppendAddress(code->address()); @@ -1347,6 +1366,8 @@ void Logger::TickEvent(TickSample* sample, bool overflow) { msg.AppendAddress(sample->pc); msg.Append(','); msg.AppendAddress(sample->sp); + msg.Append(",%ld", + FLAG_log_timer_events ? static_cast(OS::Ticks() - epoch_) : 0); if (sample->has_external_callback) { msg.Append(",1,"); msg.AppendAddress(sample->external_callback); diff --git a/src/log.h b/src/log.h index c8f81bc..97f9ffe 100644 --- a/src/log.h +++ b/src/log.h @@ -275,7 +275,10 @@ class Logger { void SharedLibraryEvent(const wchar_t* library_path, uintptr_t start, uintptr_t end); + + // ==== Events logged by --log-timer-events. ==== void TimerEvent(const char* name, int64_t start, int64_t end); + void ExternalSwitch(StateTag old_tag, StateTag new_tag); class TimerEventScope { public: @@ -476,6 +479,7 @@ class Logger { Address prev_code_; int64_t epoch_; + static int64_t enter_external_; friend class CpuProfiler; }; diff --git a/src/vm-state-inl.h b/src/vm-state-inl.h index 97febd0..bc48160 100644 --- a/src/vm-state-inl.h +++ b/src/vm-state-inl.h @@ -67,6 +67,10 @@ VMState::VMState(Isolate* isolate, StateTag tag) LOG(isolate, UncheckedStringEvent("From", StateToString(previous_tag_))); } + if (FLAG_log_timer_events) { + LOG(isolate, ExternalSwitch(previous_tag_, tag)); + } + isolate_->SetCurrentVMState(tag); } @@ -80,6 +84,10 @@ VMState::~VMState() { UncheckedStringEvent("To", StateToString(previous_tag_))); } + if (FLAG_log_timer_events) { + LOG(isolate_, ExternalSwitch(isolate_->current_vm_state(), previous_tag_)); + } + isolate_->SetCurrentVMState(previous_tag_); } diff --git a/test/cctest/test-log.cc b/test/cctest/test-log.cc index 6f2324d..892a542 100644 --- a/test/cctest/test-log.cc +++ b/test/cctest/test-log.cc @@ -392,7 +392,7 @@ TEST(LogCallbacks) { i::EmbeddedVector ref_data; i::OS::SNPrintF(ref_data, - "code-creation,Callback,0x%" V8PRIxPTR ",1,\"method1\"\0", + "code-creation,Callback,-3,0x%" V8PRIxPTR ",1,\"method1\"\0", ObjMethod1); CHECK_NE(NULL, StrNStr(log.start(), ref_data.start(), log.length())); @@ -435,21 +435,21 @@ TEST(LogAccessorCallbacks) { EmbeddedVector prop1_getter_record; i::OS::SNPrintF(prop1_getter_record, - "code-creation,Callback,0x%" V8PRIxPTR ",1,\"get prop1\"", + "code-creation,Callback,-3,0x%" V8PRIxPTR ",1,\"get prop1\"", Prop1Getter); CHECK_NE(NULL, StrNStr(log.start(), prop1_getter_record.start(), log.length())); EmbeddedVector prop1_setter_record; i::OS::SNPrintF(prop1_setter_record, - "code-creation,Callback,0x%" V8PRIxPTR ",1,\"set prop1\"", + "code-creation,Callback,-3,0x%" V8PRIxPTR ",1,\"set prop1\"", Prop1Setter); CHECK_NE(NULL, StrNStr(log.start(), prop1_setter_record.start(), log.length())); EmbeddedVector prop2_getter_record; i::OS::SNPrintF(prop2_getter_record, - "code-creation,Callback,0x%" V8PRIxPTR ",1,\"get prop2\"", + "code-creation,Callback,-3,0x%" V8PRIxPTR ",1,\"get prop2\"", Prop2Getter); CHECK_NE(NULL, StrNStr(log.start(), prop2_getter_record.start(), log.length())); diff --git a/test/mjsunit/tools/tickprocessor-test-func-info.log b/test/mjsunit/tools/tickprocessor-test-func-info.log index e4015d4..5e64dc0 100644 --- a/test/mjsunit/tools/tickprocessor-test-func-info.log +++ b/test/mjsunit/tools/tickprocessor-test-func-info.log @@ -2,10 +2,10 @@ shared-library,"shell",0x08048000,0x081ee000 shared-library,"/lib32/libm-2.7.so",0xf7db6000,0xf7dd9000 shared-library,"ffffe000-fffff000",0xffffe000,0xfffff000 profiler,"begin",1 -code-creation,Stub,0x424260,348,"CompareStub_GE" -code-creation,LazyCompile,0x2a8100,18535,"DrawQube 3d-cube.js:188",0xf43abcac, -code-creation,LazyCompile,0x480100,3908,"DrawLine 3d-cube.js:17",0xf43abc50, -tick,0x424284,0xbfffeea0,0,0x480600,0,0x2aaaa5 -tick,0x42429f,0xbfffed88,0,0x480600,0,0x2aacb4 -tick,0x48063d,0xbfffec7c,0,0x2d0f7c,0,0x2aaec6 +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, +tick,0x424284,0xbfffeea0,0,0,0x480600,0,0x2aaaa5 +tick,0x42429f,0xbfffed88,0,0,0x480600,0,0x2aacb4 +tick,0x48063d,0xbfffec7c,0,0,0x2d0f7c,0,0x2aaec6 profiler,"end" diff --git a/test/mjsunit/tools/tickprocessor-test.log b/test/mjsunit/tools/tickprocessor-test.log index db8be79..5ddad89 100644 --- a/test/mjsunit/tools/tickprocessor-test.log +++ b/test/mjsunit/tools/tickprocessor-test.log @@ -2,24 +2,24 @@ shared-library,"shell",0x08048000,0x081ee000 shared-library,"/lib32/libm-2.7.so",0xf7db6000,0xf7dd9000 shared-library,"ffffe000-fffff000",0xffffe000,0xfffff000 profiler,"begin",1 -code-creation,Stub,0xf540a100,474,"CEntryStub" -code-creation,Script,0xf541cd80,736,"exp.js" -code-creation,Stub,0xf541d0e0,47,"RuntimeStub_Math_exp" -code-creation,LazyCompile,0xf541d120,145,"exp native math.js:41" +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" function-creation,0xf441d280,0xf541d120 -code-creation,LoadIC,0xf541d280,117,"j" -code-creation,LoadIC,0xf541d360,63,"i" -tick,0x80f82d1,0xffdfe880,0,0,0,0xf541ce5c -tick,0x80f89a1,0xffdfecf0,0,0,0,0xf541ce5c -tick,0x8123b5c,0xffdff1a0,0,0,0,0xf541d1a1,0xf541ceea -tick,0x8123b65,0xffdff1a0,0,0,0,0xf541d1a1,0xf541ceea -tick,0xf541d2be,0xffdff1e4,0,0,0 -tick,0xf541d320,0xffdff1dc,0,0,0 -tick,0xf541d384,0xffdff1d8,0,0,0 -tick,0xf7db94da,0xffdff0ec,0,0,0,0xf541d1a1,0xf541ceea -tick,0xf7db951c,0xffdff0f0,0,0,0,0xf541d1a1,0xf541ceea -tick,0xf7dbc508,0xffdff14c,0,0,0,0xf541d1a1,0xf541ceea -tick,0xf7dbff21,0xffdff198,0,0,0,0xf541d1a1,0xf541ceea -tick,0xf7edec90,0xffdff0ec,0,0,0,0xf541d1a1,0xf541ceea -tick,0xffffe402,0xffdff488,0,0,0 +code-creation,LoadIC,0,0xf541d280,117,"j" +code-creation,LoadIC,0,0xf541d360,63,"i" +tick,0x80f82d1,0xffdfe880,0,0,0,0,0xf541ce5c +tick,0x80f89a1,0xffdfecf0,0,0,0,0,0xf541ce5c +tick,0x8123b5c,0xffdff1a0,0,0,0,0,0xf541d1a1,0xf541ceea +tick,0x8123b65,0xffdff1a0,0,0,0,0,0xf541d1a1,0xf541ceea +tick,0xf541d2be,0xffdff1e4,0,0,0,0 +tick,0xf541d320,0xffdff1dc,0,0,0,0 +tick,0xf541d384,0xffdff1d8,0,0,0,0 +tick,0xf7db94da,0xffdff0ec,0,0,0,0,0xf541d1a1,0xf541ceea +tick,0xf7db951c,0xffdff0f0,0,0,0,0,0xf541d1a1,0xf541ceea +tick,0xf7dbc508,0xffdff14c,0,0,0,0,0xf541d1a1,0xf541ceea +tick,0xf7dbff21,0xffdff198,0,0,0,0,0xf541d1a1,0xf541ceea +tick,0xf7edec90,0xffdff0ec,0,0,0,0,0xf541d1a1,0xf541ceea +tick,0xffffe402,0xffdff488,0,0,0,0 profiler,"end" diff --git a/tools/plot-timer-events b/tools/plot-timer-events index 1db2c31..efa82bc 100755 --- a/tools/plot-timer-events +++ b/tools/plot-timer-events @@ -34,6 +34,7 @@ fi # nm spits out 'no symbols found' messages to stderr. cat $log_file | $d8_exec $tools_path/csvparser.js \ + $tools_path/splaytree.js $tools_path/codemap.js \ $tools_path/logreader.js $tools_path/plot-timer-events.js \ 2>/dev/null | gnuplot > timer-events.png diff --git a/tools/plot-timer-events.js b/tools/plot-timer-events.js index 8ef0b8e..a41f080 100644 --- a/tools/plot-timer-events.js +++ b/tools/plot-timer-events.js @@ -25,50 +25,83 @@ // (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE // OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE. -var kExecutionName = 'V8.Execute'; +var kV8BinarySuffixes = ["/d8", "/libv8.so"]; +var kStackFrames = 8; -var TimerEvents = { - 'V8.Execute': - { ranges: [], color: "#444444", pause: false, index: 1 }, - 'V8.CompileFullCode': - { ranges: [], color: "#CC0000", pause: true, index: 2 }, - 'V8.RecompileSynchronous': - { ranges: [], color: "#CC0044", pause: true, index: 3 }, - 'V8.RecompileParallel': - { ranges: [], color: "#CC4499", pause: false, index: 4 }, - 'V8.CompileEval': - { ranges: [], color: "#CC4400", pause: true, index: 5 }, - 'V8.Parse': - { ranges: [], color: "#00CC00", pause: true, index: 6 }, - 'V8.PreParse': - { ranges: [], color: "#44CC00", pause: true, index: 7 }, - 'V8.ParseLazy': - { ranges: [], color: "#00CC44", pause: true, index: 8 }, - 'V8.GCScavenger': - { ranges: [], color: "#0044CC", pause: true, index: 9 }, - 'V8.GCCompactor': - { ranges: [], color: "#4444CC", pause: true, index: 10 }, - 'V8.GCContext': - { ranges: [], color: "#4400CC", pause: true, index: 11 }, -} +var kTimerEventWidth = 0.33; +var kExecutionFrameWidth = 0.2; +var kStackFrameWidth = 0.1; +var kGapWidth = 0.05; + +var kPauseTolerance = 0.1; // Milliseconds. +var kY1Offset = 10; -var kNumRows = 11; -var kBarWidth = 0.33; -var kPauseTolerance = 0.05; // Milliseconds. -var kY1Offset = 3; -var kY2Factor = 5; var kResX = 1600; -var kResY = 400; -var kLabelPadding = 5; +var kResY = 600; +var kPauseLabelPadding = 5; var kNumPauseLabels = 7; +var kTickHalfDuration = 0.5; // Milliseconds +var kCodeKindLabelPadding = 100; var kOverrideRangeStart = undefined; var kOverrideRangeEnd = undefined; +var num_timer_event = kY1Offset + 0.5; + + +function TimerEvent(color, pause, no_execution) { + this.color = color; + this.pause = pause; + this.ranges = []; + this.no_execution = no_execution; + this.index = ++num_timer_event; +} + + +var TimerEvents = { + 'V8.Execute': new TimerEvent("#000000", false, false), + 'V8.External': new TimerEvent("#3399FF", false, true), + 'V8.CompileFullCode': new TimerEvent("#CC0000", true, true), + 'V8.RecompileSynchronous': new TimerEvent("#CC0044", true, true), + 'V8.RecompileParallel': new TimerEvent("#CC4499", false, false), + 'V8.CompileEval': new TimerEvent("#CC4400", true, true), + 'V8.Parse': new TimerEvent("#00CC00", true, true), + 'V8.PreParse': new TimerEvent("#44CC00", true, true), + 'V8.ParseLazy': new TimerEvent("#00CC44", true, true), + 'V8.GCScavenger': new TimerEvent("#0044CC", true, true), + 'V8.GCCompactor': new TimerEvent("#4444CC", true, true), + 'V8.GCContext': new TimerEvent("#4400CC", true, true), +} + +var kExecutionEvent = TimerEvents['V8.Execute']; + + +function CodeKind(color, kinds) { + this.color = color; + this.in_execution = []; + this.stack_frames = []; + for (var i = 0; i < kStackFrames; i++) this.stack_frames.push([]); + this.kinds = kinds; +} + + +var CodeKinds = { + 'external ': new CodeKind("#3399FF", [-3]), + 'reg.exp. ': new CodeKind("#0000FF", [-2]), + 'runtime ': new CodeKind("#000000", [-1]), + 'full code': new CodeKind("#DD0000", [0]), + 'opt code ': new CodeKind("#00EE00", [1]), + 'code stub': new CodeKind("#FF00FF", [2]), + 'built-in ': new CodeKind("#AA00AA", [3]), + 'inl.cache': new CodeKind("#4444AA", [4, 5, 6, 7, 8, 9, 10, 11, 12, 13]), +} + + var xrange_start = Infinity; var xrange_end = 0; var obj_index = 0; var execution_pauses = []; +var code_map = new CodeMap(); function Range(start, end) { @@ -88,19 +121,89 @@ function ProcessTimerEvent(name, start, length) { length /= 1000; var end = start + length; event.ranges.push(new Range(start, end)); - if (name == kExecutionName) { + if (event == kExecutionEvent) { if (start < xrange_start) xrange_start = start; if (end > xrange_end) xrange_end = end; } } +function ProcessCodeCreateEvent(type, kind, address, size, name) { + var code_entry = new CodeMap.CodeEntry(size, name); + code_entry.kind = kind; + code_map.addCode(address, code_entry); +} + + +function ProcessCodeMoveEvent(from, to) { + code_map.moveCode(from, to); +} + + +function ProcessCodeDeleteEvent(address) { + code_map.deleteCode(address); +} + + +function ProcessSharedLibrary(name, start, end) { + var code_entry = new CodeMap.CodeEntry(end - start, name); + code_entry.kind = -3; // External code kind. + for (var i = 0; i < kV8BinarySuffixes.length; i++) { + var suffix = kV8BinarySuffixes[i]; + if (name.indexOf(suffix, name.length - suffix.length) >= 0) { + code_entry.kind = -1; // V8 runtime code kind. + break; + } + } + code_map.addLibrary(start, code_entry); +} + + +function FindCodeKind(kind) { + for (name in CodeKinds) { + if (CodeKinds[name].kinds.indexOf(kind) >= 0) { + return CodeKinds[name]; + } + } +} + + +function ProcessTickEvent(pc, sp, timer, unused_x, unused_y, vmstate, stack) { + timer /= 1000; + var tick = new Range(timer - kTickHalfDuration, timer + kTickHalfDuration); + + var entry = code_map.findEntry(pc); + if (entry) { + FindCodeKind(entry.kind).in_execution.push(tick); + } + + for (var i = 0; i < kStackFrames; i++) { + if (!stack[i]) break; + var entry = code_map.findEntry(stack[i]); + if (entry) { + FindCodeKind(entry.kind).stack_frames[i].push(tick); + } + } +} + + function CollectData() { // Collect data from log. var logreader = new LogReader( - { 'timer-event' : { parsers: [null, parseInt, parseInt], - processor: ProcessTimerEvent - } }); + { 'timer-event' : { parsers: [null, parseInt, parseInt], + processor: ProcessTimerEvent }, + 'shared-library': { parsers: [null, parseInt, parseInt], + processor: ProcessSharedLibrary }, + 'code-creation': { parsers: [null, parseInt, parseInt, parseInt, null], + processor: ProcessCodeCreateEvent }, + 'code-move': { parsers: [parseInt, parseInt], + processor: ProcessCodeMoveEvent }, + 'code-delete': { parsers: [parseInt], + processor: ProcessCodeDeleteEvent }, + 'tick': { parsers: [parseInt, parseInt, parseInt, + null, null, parseInt, 'var-args'], + processor: ProcessTickEvent }, + }); var line; while (line = readline()) { @@ -112,25 +215,42 @@ function CollectData() { var event = TimerEvents[name]; if (!event.pause) continue; var ranges = event.ranges; + for (var j = 0; j < ranges.length; j++) execution_pauses.push(ranges[j]); + } + execution_pauses = MergeRanges(execution_pauses); + + // Knock out time not spent in javascript execution. Note that this also + // includes time spent external code, which do not contribute to execution + // pauses. + var exclude_ranges = []; + for (name in TimerEvents) { + var event = TimerEvents[name]; + if (!event.no_execution) continue; + var ranges = event.ranges; // Add ranges of this event to the pause list. for (var j = 0; j < ranges.length; j++) { - execution_pauses.push(ranges[j]); + exclude_ranges.push(ranges[j]); } } + + kExecutionEvent.ranges = MergeRanges(kExecutionEvent.ranges); + exclude_ranges = MergeRanges(exclude_ranges); + kExecutionEvent.ranges = ExcludeRanges(kExecutionEvent.ranges, + exclude_ranges); } -function drawBar(row, color, start, end) { +function DrawBar(row, color, start, end, width) { obj_index++; command = "set object " + obj_index + " rect"; - command += " from " + start + ", " + (row - kBarWidth + kY1Offset); - command += " to " + end + ", " + (row + kBarWidth + kY1Offset); + command += " from " + start + ", " + (row - width); + command += " to " + end + ", " + (row + width); command += " fc rgb \"" + color + "\""; print(command); } -function MergeRanges(ranges, merge_tolerance) { +function MergeRanges(ranges) { ranges.sort(function(a, b) { return a.start - b.start; }); var result = []; var j = 0; @@ -141,7 +261,7 @@ function MergeRanges(ranges, merge_tolerance) { for (j = i + 1; j < ranges.length; j++) { var next_range = ranges[j]; // Don't merge ranges if there is no overlap (including merge tolerance). - if (next_range.start >= merge_end + kPauseTolerance) break; + if (next_range.start > merge_end + kPauseTolerance) break; // Merge ranges. if (next_range.end > merge_end) { // Extend range end. merge_end = next_range.end; @@ -239,10 +359,9 @@ function ExcludeRanges(include, exclude) { function GnuplotOutput() { xrange_start = kOverrideRangeStart ? kOverrideRangeStart : xrange_start; xrange_end = kOverrideRangeEnd ? kOverrideRangeEnd : xrange_end; - print("set terminal pngcairo size " + kResX + "," + kResY + " enhanced font 'Helvetica,10'"); - print("set yrange [0:" + (kNumRows + kY1Offset + 1) + "]"); + print("set yrange [0:" + (num_timer_event + 1) + "]"); print("set xlabel \"execution time in ms\""); print("set xrange [" + xrange_start + ":" + xrange_end + "]"); print("set style fill pattern 2 bo 1"); @@ -255,57 +374,71 @@ function GnuplotOutput() { var ytics = []; for (name in TimerEvents) { var index = TimerEvents[name].index; - ytics.push('"' + name + '"' + ' ' + (index + kY1Offset)); + ytics.push('"' + name + '"' + ' ' + index); } + ytics.push('"code kind being executed"' + ' ' + (kY1Offset - 1)); + ytics.push('"top ' + kStackFrames + ' js stack frames"' + ' ' + + (kY1Offset - 2)); + ytics.push('"pause times" 0'); print("set ytics out nomirror (" + ytics.join(', ') + ")"); - // Smallest visible gap given our resolution. - // We remove superfluous objects to go easy on Gnuplot. - var tolerance = (xrange_end - xrange_start) / kResX / 2; - - // Sort, merge and remove invisible gaps for each time row. - for (var name in TimerEvents) { - var event = TimerEvents[name]; - event.ranges = MergeRanges(event.ranges, tolerance); - } - - // Knock out execution pauses. - var execution_event = TimerEvents[kExecutionName]; - var exclude_ranges = MergeRanges(execution_pauses, tolerance); - execution_event.ranges = ExcludeRanges(execution_event.ranges, - exclude_ranges); - execution_event.ranges = MergeRanges(execution_event.ranges, tolerance); - // Plot timeline. for (var name in TimerEvents) { var event = TimerEvents[name]; - var ranges = event.ranges; + var ranges = MergeRanges(event.ranges); for (var i = 0; i < ranges.length; i++) { - drawBar(event.index, event.color, ranges[i].start, ranges[i].end); + DrawBar(event.index, event.color, + ranges[i].start, ranges[i].end, + kTimerEventWidth); + } + } + + // Plot code kind gathered from ticks. + for (var name in CodeKinds) { + var code_kind = CodeKinds[name]; + var offset = kY1Offset - 1; + // Top most frame. + var row = MergeRanges(code_kind.in_execution); + for (var j = 0; j < row.length; j++) { + DrawBar(offset, code_kind.color, + row[j].start, row[j].end, kExecutionFrameWidth); + } + offset = offset - 2 * kExecutionFrameWidth - kGapWidth; + // Javascript frames. + for (var i = 0; i < kStackFrames; i++) { + offset = offset - 2 * kStackFrameWidth - kGapWidth; + row = MergeRanges(code_kind.stack_frames[i]); + for (var j = 0; j < row.length; j++) { + DrawBar(offset, code_kind.color, + row[j].start, row[j].end, kStackFrameWidth); + } } } + // Add labels as legend for code kind colors. + var padding = kCodeKindLabelPadding * (xrange_end - xrange_start) / kResX; + var label_x = xrange_start; + var label_y = kY1Offset; + for (var name in CodeKinds) { + label_x += padding; + print("set label \"" + name + "\" at " + label_x + "," + label_y + + " textcolor rgb \"" + CodeKinds[name].color + "\"" + + " font \"Helvetica,9'\""); + } + if (execution_pauses.length == 0) { // Force plot and return without plotting execution pause impulses. print("plot 1/0"); return; } - // Plot execution pauses as impulses. This may be better resolved - // due to possibly smaller merge tolerance. - if (tolerance > kPauseTolerance) { - execution_pauses = MergeRanges(execution_pauses, kPauseTolerance); - } else { - execution_pauses = exclude_ranges; - } - // Label the longest pauses. execution_pauses.sort( function(a, b) { return b.duration() - a.duration(); }); var max_pause_time = execution_pauses[0].duration(); - var padding = kLabelPadding * (xrange_end - xrange_start) / kResX; - var y_scale = kY1Offset / max_pause_time; + padding = kPauseLabelPadding * (xrange_end - xrange_start) / kResX; + var y_scale = kY1Offset / max_pause_time / 2; for (var i = 0; i < execution_pauses.length && i < kNumPauseLabels; i++) { var pause = execution_pauses[i]; var label_content = (pause.duration() | 0) + " ms"; @@ -316,8 +449,8 @@ function GnuplotOutput() { } // Scale second Y-axis appropriately. - print("set y2range [0:" + (max_pause_time * kY2Factor) + "]"); - + var y2range = max_pause_time * num_timer_event / kY1Offset * 2; + print("set y2range [0:" + y2range + "]"); // Plot graph with impulses as data set. print("plot '-' using 1:2 axes x1y2 with impulses ls 1"); for (var i = 0; i < execution_pauses.length; i++) { diff --git a/tools/tickprocessor.js b/tools/tickprocessor.js index 78f4cee..7530c6b 100644 --- a/tools/tickprocessor.js +++ b/tools/tickprocessor.js @@ -73,7 +73,7 @@ function parseState(s) { function SnapshotLogProcessor() { LogReader.call(this, { 'code-creation': { - parsers: [null, parseInt, parseInt, null, 'var-args'], + parsers: [null, parseInt, parseInt, parseInt, null, 'var-args'], processor: this.processCodeCreation }, 'code-move': { parsers: [parseInt, parseInt], processor: this.processCodeMove }, @@ -107,7 +107,7 @@ inherits(SnapshotLogProcessor, LogReader); SnapshotLogProcessor.prototype.processCodeCreation = function( - type, start, size, name, maybe_func) { + type, kind, start, size, name, maybe_func) { if (maybe_func.length) { var funcAddr = parseInt(maybe_func[0]); var state = parseState(maybe_func[1]); @@ -156,7 +156,7 @@ function TickProcessor( 'shared-library': { parsers: [null, parseInt, parseInt], processor: this.processSharedLibrary }, 'code-creation': { - parsers: [null, parseInt, parseInt, null, 'var-args'], + parsers: [null, parseInt, parseInt, parseInt, null, 'var-args'], processor: this.processCodeCreation }, 'code-move': { parsers: [parseInt, parseInt], processor: this.processCodeMove }, @@ -167,7 +167,7 @@ function TickProcessor( 'snapshot-pos': { parsers: [parseInt, parseInt], processor: this.processSnapshotPosition }, 'tick': { - parsers: [parseInt, parseInt, parseInt, + parsers: [parseInt, parseInt, parseInt, parseInt, parseInt, parseInt, 'var-args'], processor: this.processTick }, 'heap-sample-begin': { parsers: [null, null, parseInt], @@ -309,7 +309,7 @@ TickProcessor.prototype.processSharedLibrary = function( TickProcessor.prototype.processCodeCreation = function( - type, start, size, name, maybe_func) { + type, kind, start, size, name, maybe_func) { name = this.deserializedEntriesNames_[start] || name; if (maybe_func.length) { var funcAddr = parseInt(maybe_func[0]); @@ -350,6 +350,7 @@ TickProcessor.prototype.includeTick = function(vmState) { TickProcessor.prototype.processTick = function(pc, sp, + ns_since_start, is_external_callback, tos_or_external_callback, vmState, -- 2.7.4