Revision: 13074
Author: [email protected]
Date: Wed Nov 28 03:01:10 2012
Log: 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
[email protected]
BUG=
Review URL: https://chromiumcodereview.appspot.com/11428025
http://code.google.com/p/v8/source/detail?r=13074
Modified:
/branches/bleeding_edge/src/log.cc
/branches/bleeding_edge/src/log.h
/branches/bleeding_edge/src/vm-state-inl.h
/branches/bleeding_edge/test/cctest/test-log.cc
/branches/bleeding_edge/test/mjsunit/tools/tickprocessor-test-func-info.log
/branches/bleeding_edge/test/mjsunit/tools/tickprocessor-test.log
/branches/bleeding_edge/tools/plot-timer-events
/branches/bleeding_edge/tools/plot-timer-events.js
/branches/bleeding_edge/tools/tickprocessor.js
=======================================
--- /branches/bleeding_edge/src/log.cc Mon Nov 26 00:56:59 2012
+++ /branches/bleeding_edge/src/log.cc Wed Nov 28 03:01:10 2012
@@ -716,6 +716,20 @@
}
+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 @@
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 @@
}
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 @@
}
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 @@
LogMessageBuilder msg(this);
SmartArrayPointer<char> 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 @@
shared->DebugName()->ToCString(DISALLOW_NULLS,
ROBUST_STRING_TRAVERSAL);
SmartArrayPointer<char> 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 @@
}
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 @@
}
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 @@
msg.AppendAddress(sample->pc);
msg.Append(',');
msg.AppendAddress(sample->sp);
+ msg.Append(",%ld",
+ FLAG_log_timer_events ? static_cast<int>(OS::Ticks() - epoch_) : 0);
if (sample->has_external_callback) {
msg.Append(",1,");
msg.AppendAddress(sample->external_callback);
=======================================
--- /branches/bleeding_edge/src/log.h Mon Nov 26 00:56:59 2012
+++ /branches/bleeding_edge/src/log.h Wed Nov 28 03:01:10 2012
@@ -275,7 +275,10 @@
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 @@
Address prev_code_;
int64_t epoch_;
+ static int64_t enter_external_;
friend class CpuProfiler;
};
=======================================
--- /branches/bleeding_edge/src/vm-state-inl.h Thu Nov 22 05:04:11 2012
+++ /branches/bleeding_edge/src/vm-state-inl.h Wed Nov 28 03:01:10 2012
@@ -66,6 +66,10 @@
LOG(isolate, UncheckedStringEvent("Entering", StateToString(tag)));
LOG(isolate, UncheckedStringEvent("From",
StateToString(previous_tag_)));
}
+
+ if (FLAG_log_timer_events) {
+ LOG(isolate, ExternalSwitch(previous_tag_, tag));
+ }
isolate_->SetCurrentVMState(tag);
}
@@ -79,6 +83,10 @@
LOG(isolate_,
UncheckedStringEvent("To", StateToString(previous_tag_)));
}
+
+ if (FLAG_log_timer_events) {
+ LOG(isolate_, ExternalSwitch(isolate_->current_vm_state(),
previous_tag_));
+ }
isolate_->SetCurrentVMState(previous_tag_);
}
=======================================
--- /branches/bleeding_edge/test/cctest/test-log.cc Mon Sep 19 11:36:47 2011
+++ /branches/bleeding_edge/test/cctest/test-log.cc Wed Nov 28 03:01:10 2012
@@ -392,7 +392,7 @@
i::EmbeddedVector<char, 100> 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 @@
EmbeddedVector<char, 100> 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<char, 100> 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<char, 100> 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()));
=======================================
---
/branches/bleeding_edge/test/mjsunit/tools/tickprocessor-test-func-info.log
Mon Mar 21 11:13:27 2011
+++
/branches/bleeding_edge/test/mjsunit/tools/tickprocessor-test-func-info.log
Wed Nov 28 03:01:10 2012
@@ -2,10 +2,10 @@
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"
=======================================
--- /branches/bleeding_edge/test/mjsunit/tools/tickprocessor-test.log Mon
Mar 21 11:13:27 2011
+++ /branches/bleeding_edge/test/mjsunit/tools/tickprocessor-test.log Wed
Nov 28 03:01:10 2012
@@ -2,24 +2,24 @@
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"
=======================================
--- /branches/bleeding_edge/tools/plot-timer-events Thu Nov 22 05:04:11 2012
+++ /branches/bleeding_edge/tools/plot-timer-events Wed Nov 28 03:01:10 2012
@@ -34,6 +34,7 @@
# 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
=======================================
--- /branches/bleeding_edge/tools/plot-timer-events.js Thu Nov 22 05:04:11
2012
+++ /branches/bleeding_edge/tools/plot-timer-events.js Wed Nov 28 03:01:10
2012
@@ -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 kNumRows = 11;
-var kBarWidth = 0.33;
-var kPauseTolerance = 0.05; // Milliseconds.
-var kY1Offset = 3;
-var kY2Factor = 5;
+var kPauseTolerance = 0.1; // Milliseconds.
+var kY1Offset = 10;
+
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 @@
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 @@
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 @@
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 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 @@
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 @@
}
// 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++) {
=======================================
--- /branches/bleeding_edge/tools/tickprocessor.js Thu Nov 22 05:04:11 2012
+++ /branches/bleeding_edge/tools/tickprocessor.js Wed Nov 28 03:01:10 2012
@@ -73,7 +73,7 @@
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 @@
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 @@
'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 @@
'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.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.processTick = function(pc,
sp,
+ ns_since_start,
is_external_callback,
tos_or_external_callback,
vmState,
--
v8-dev mailing list
[email protected]
http://groups.google.com/group/v8-dev
