// Copyright 2013 the V8 project authors. All rights reserved.
// Redistribution and use in source and binary forms, with or without
// modification, are permitted provided that the following conditions are
// met:
//
// * Redistributions of source code must retain the above copyright
// notice, this list of conditions and the following disclaimer.
// * Redistributions in binary form must reproduce the above
// copyright notice, this list of conditions and the following
// disclaimer in the documentation and/or other materials provided
// with the distribution.
// * Neither the name of Google Inc. nor the names of its
// contributors may be used to endorse or promote products derived
// from this software without specific prior written permission.
//
// THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS
// "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT
// LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR
// A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT
// OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL,
// SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT
// LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE,
// DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY
// THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
// (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE
// OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
Array.prototype.top = function() {
if (this.length == 0) return undefined;
return this[this.length - 1];
}
function PlotScriptComposer(kResX, kResY, error_output) {
// Constants.
var kV8BinarySuffixes = ["/d8", "/libv8.so"];
var kStackFrames = 8; // Stack frames to display in the plot.
var kTimerEventWidth = 0.33; // Width of each timeline.
var kExecutionFrameWidth = 0.2; // Width of the top stack frame line.
var kStackFrameWidth = 0.1; // Width of the lower stack frame lines.
var kGapWidth = 0.05; // Gap between stack frame lines.
var kY1Offset = 11; // Offset for stack frame vs. event lines.
var kDeoptRow = 7; // Row displaying deopts.
var kGetTimeHeight = 0.5; // Height of marker displaying timed part.
var kMaxDeoptLength = 4; // Draw size of the largest deopt.
var kPauseLabelPadding = 5; // Padding for pause time labels.
var kNumPauseLabels = 7; // Number of biggest pauses to label.
var kCodeKindLabelPadding = 100; // Padding for code kind labels.
var kTickHalfDuration = 0.5; // Duration of half a tick in ms.
var kMinRangeLength = 0.0005; // Minimum length for an event in ms.
var kNumThreads = 2; // Number of threads.
var kExecutionThreadId = 0; // ID of main thread.
// Init values.
var num_timer_event = kY1Offset + 0.5;
// Data structures.
function TimerEvent(label, color, pause, thread_id) {
assert(thread_id >= 0 && thread_id < kNumThreads, "invalid thread id");
this.label = label;
this.color = color;
this.pause = pause;
this.ranges = [];
this.thread_id = thread_id;
this.index = ++num_timer_event;
}
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;
}
function Range(start, end) {
this.start = start; // In milliseconds.
this.end = end; // In milliseconds.
}
function Deopt(time, size) {
this.time = time; // In milliseconds.
this.size = size; // In bytes.
}
Range.prototype.duration = function() { return this.end - this.start; }
function Tick(tick) {
this.tick = tick;
}
var TimerEvents = {
'V8.Execute':
new TimerEvent("execution", "#000000", false, 0),
'V8.External':
new TimerEvent("external", "#3399FF", false, 0),
'V8.CompileFullCode':
new TimerEvent("compile unopt", "#CC0000", true, 0),
'V8.RecompileSynchronous':
new TimerEvent("recompile sync", "#CC0044", true, 0),
'V8.RecompileConcurrent':
new TimerEvent("recompile async", "#CC4499", false, 1),
'V8.CompileEvalMicroSeconds':
new TimerEvent("compile eval", "#CC4400", true, 0),
'V8.ParseMicroSeconds':
new TimerEvent("parse", "#00CC00", true, 0),
'V8.PreParseMicroSeconds':
new TimerEvent("preparse", "#44CC00", true, 0),
'V8.ParseLazyMicroSeconds':
new TimerEvent("lazy parse", "#00CC44", true, 0),
'V8.GCScavenger':
new TimerEvent("gc scavenge", "#0044CC", true, 0),
'V8.GCCompactor':
new TimerEvent("gc compaction", "#4444CC", true, 0),
'V8.GCContext':
new TimerEvent("gc context", "#4400CC", true, 0),
};
var CodeKinds = {
'external ': new CodeKind("#3399FF", [-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, 14]),
'reg.exp. ': new CodeKind("#0000FF", [15]),
};
var code_map = new CodeMap();
var execution_pauses = [];
var deopts = [];
var gettime = [];
var event_stack = [];
var last_time_stamp = [];
for (var i = 0; i < kNumThreads; i++) {
event_stack[i] = [];
last_time_stamp[i] = -1;
}
var range_start = undefined;
var range_end = undefined;
var obj_index = 0;
var pause_tolerance = 0.005; // Milliseconds.
var distortion = 0;
// Utility functions.
function assert(something, message) {
if (!something) {
var error = new Error(message);
error_output(error.stack);
}
}
function FindCodeKind(kind) {
for (name in CodeKinds) {
if (CodeKinds[name].kinds.indexOf(kind) >= 0) {
return CodeKinds[name];
}
}
}
function TicksToRanges(ticks) {
var ranges = [];
for (var i = 0; i < ticks.length; i++) {
var tick = ticks[i].tick;
ranges.push(
new Range(tick - kTickHalfDuration, tick + kTickHalfDuration));
}
return ranges;
}
function MergeRanges(ranges) {
ranges.sort(function(a, b) { return a.start - b.start; });
var result = [];
var j = 0;
for (var i = 0; i < ranges.length; i = j) {
var merge_start = ranges[i].start;
if (merge_start > range_end) break; // Out of plot range.
var merge_end = ranges[i].end;
for (j = i + 1; j < ranges.length; j++) {
var next_range = ranges[j];
// Don't merge ranges if there is no overlap (incl. merge tolerance).
if (next_range.start > merge_end + pause_tolerance) break;
// Merge ranges.
if (next_range.end > merge_end) { // Extend range end.
merge_end = next_range.end;
}
}
if (merge_end < range_start) continue; // Out of plot range.
if (merge_end < merge_start) continue; // Not an actual range.
result.push(new Range(merge_start, merge_end));
}
return result;
}
function RestrictRangesTo(ranges, start, end) {
var result = [];
for (var i = 0; i < ranges.length; i++) {
if (ranges[i].start <= end && ranges[i].end >= start) {
result.push(new Range(Math.max(ranges[i].start, start),
Math.min(ranges[i].end, end)));
}
}
return result;
}
// Public methods.
this.collectData = function(input, distortion_per_entry) {
var last_timestamp = 0;
// Parse functions.
var parseTimeStamp = function(timestamp) {
int_timestamp = parseInt(timestamp);
assert(int_timestamp >= last_timestamp, "Inconsistent timestamps.");
last_timestamp = int_timestamp;
distortion += distortion_per_entry;
return int_timestamp / 1000 - distortion;
}
var processTimerEventStart = function(name, start) {
// Find out the thread id.
var new_event = TimerEvents[name];
if (new_event === undefined) return;
var thread_id = new_event.thread_id;
start = Math.max(last_time_stamp[thread_id] + kMinRangeLength, start);
// Last event on this thread is done with the start of this event.
var last_event = event_stack[thread_id].top();
if (last_event !== undefined) {
var new_range = new Range(last_time_stamp[thread_id], start);
last_event.ranges.push(new_range);
}
event_stack[thread_id].push(new_event);
last_time_stamp[thread_id] = start;
};
var processTimerEventEnd = function(name, end) {
// Find out about the thread_id.
var finished_event = TimerEvents[name];
var thread_id = finished_event.thread_id;
assert(finished_event === event_stack[thread_id].pop(),
"inconsistent event stack");
end = Math.max(last_time_stamp[thread_id] + kMinRangeLength, end);
var new_range = new Range(last_time_stamp[thread_id], end);
finished_event.ranges.push(new_range);
last_time_stamp[thread_id] = end;
};
var processCodeCreateEvent = function(type, kind, address, size, name) {
var code_entry = new CodeMap.CodeEntry(size, name);
code_entry.kind = kind;
code_map.addCode(address, code_entry);
};
var processCodeMoveEvent = function(from, to) {
code_map.moveCode(from, to);
};
var processCodeDeleteEvent = function(address) {
code_map.deleteCode(address);
};
var processCodeDeoptEvent = function(time, size) {
deopts.push(new Deopt(time, size));
}
var processCurrentTimeEvent = function(time) {
gettime.push(time);
}
var processSharedLibrary = function(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);
};
var processTickEvent = function(
pc, timer, unused_x, unused_y, vmstate, stack) {
var tick = new Tick(timer);
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);
}
};
// Collect data from log.
var logreader = new LogReader(
{ 'timer-event-start': { parsers: [null, parseTimeStamp],
processor: processTimerEventStart },
'timer-event-end': { parsers: [null, parseTimeStamp],
processor: processTimerEventEnd },
'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 },
'code-deopt': { parsers: [parseTimeStamp, parseInt],
processor: processCodeDeoptEvent },
'current-time': { parsers: [parseTimeStamp],
processor: processCurrentTimeEvent },
'tick': { parsers: [parseInt, parseTimeStamp,
null, null, parseInt, 'var-args'],
processor: processTickEvent }
});
var line;
while (line = input()) {
for (var s of line.split("\n")) logreader.processLogLine(s);
}
// Collect execution pauses.
for (name in TimerEvents) {
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);
};
this.findPlotRange = function(
range_start_override, range_end_override, result_callback) {
var start_found = (range_start_override || range_start_override == 0);
var end_found = (range_end_override || range_end_override == 0);
range_start = start_found ? range_start_override : Infinity;
range_end = end_found ? range_end_override : -Infinity;
if (!start_found || !end_found) {
for (name in TimerEvents) {
var ranges = TimerEvents[name].ranges;
for (var i = 0; i < ranges.length; i++) {
if (ranges[i].start < range_start && !start_found) {
range_start = ranges[i].start;
}
if (ranges[i].end > range_end && !end_found) {
range_end = ranges[i].end;
}
}
}
for (codekind in CodeKinds) {
var ticks = CodeKinds[codekind].in_execution;
for (var i = 0; i < ticks.length; i++) {
if (ticks[i].tick < range_start && !start_found) {
range_start = ticks[i].tick;
}
if (ticks[i].tick > range_end && !end_found) {
range_end = ticks[i].tick;
}
}
}
}
// Set pause tolerance to something appropriate for the plot resolution
// to make it easier for gnuplot.
pause_tolerance = (range_end - range_start) / kResX / 10;
if (typeof result_callback === 'function') {
result_callback(range_start, range_end);
}
};
this.assembleOutput = function(output) {
output("set yrange [0:" + (num_timer_event + 1) + "]");
output("set xlabel \"execution time in ms\"");
output("set xrange [" + range_start + ":" + range_end + "]");
output("set style fill pattern 2 bo 1");
output("set style rect fs solid 1 noborder");
output("set style line 1 lt 1 lw 1 lc rgb \"#000000\"");
output("set border 15 lw 0.2"); // Draw thin border box.
output("set style line 2 lt 1 lw 1 lc rgb \"#9944CC\"");
output("set xtics out nomirror");
output("unset key");
function DrawBarBase(color, start, end, top, bottom, transparency) {
obj_index++;
command = "set object " + obj_index + " rect";
command += " from " + start + ", " + top;
command += " to " + end + ", " + bottom;
command += " fc rgb \"" + color + "\"";
if (transparency) {
command += " fs transparent solid " + transparency;
}
output(command);
}
function DrawBar(row, color, start, end, width) {
DrawBarBase(color, start, end, row + width, row - width);
}
function DrawHalfBar(row, color, start, end, width) {
DrawBarBase(color, start, end, row, row - width);
}
var percentages = {};
var total = 0;
for (var name in TimerEvents) {
var event = TimerEvents[name];
var ranges = RestrictRangesTo(event.ranges, range_start, range_end);
var sum =
ranges.map(function(range) { return range.duration(); })
.reduce(function(a, b) { return a + b; }, 0);
percentages[name] = (sum / (range_end - range_start) * 100).toFixed(1);
}
// Plot deopts.
deopts.sort(function(a, b) { return b.size - a.size; });
var max_deopt_size = deopts.length > 0 ? deopts[0].size : Infinity;
for (var i = 0; i < deopts.length; i++) {
var deopt = deopts[i];
DrawHalfBar(kDeoptRow, "#9944CC", deopt.time,
deopt.time + 10 * pause_tolerance,
deopt.size / max_deopt_size * kMaxDeoptLength);
}
// Plot current time polls.
if (gettime.length > 1) {
var start = gettime[0];
var end = gettime.pop();
DrawBarBase("#0000BB", start, end, kGetTimeHeight, 0, 0.2);
}
// Name Y-axis.
var ytics = [];
for (name in TimerEvents) {
var index = TimerEvents[name].index;
var label = TimerEvents[name].label;
ytics.push('"' + label + ' (' + percentages[name] + '%%)" ' + index);
}
ytics.push('"code kind color coding" ' + kY1Offset);
ytics.push('"code kind in execution" ' + (kY1Offset - 1));
ytics.push('"top ' + kStackFrames + ' js stack frames"' + ' ' +
(kY1Offset - 2));
ytics.push('"pause times" 0');
ytics.push('"max deopt size: ' + (max_deopt_size / 1024).toFixed(1) +
' kB" ' + kDeoptRow);
output("set ytics out nomirror (" + ytics.join(', ') + ")");
// Plot timeline.
for (var name in TimerEvents) {
var event = TimerEvents[name];
var ranges = MergeRanges(event.ranges);
for (var i = 0; i < ranges.length; i++) {
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(TicksToRanges(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(TicksToRanges(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 * (range_end - range_start) / kResX;
var label_x = range_start;
var label_y = kY1Offset;
for (var name in CodeKinds) {
label_x += padding;
output("set label \"" + name + "\" at " + label_x + "," + label_y +
" textcolor rgb \"" + CodeKinds[name].color + "\"" +
" font \"Helvetica,9'\"");
obj_index++;
}
if (execution_pauses.length == 0) {
// Force plot and return without plotting execution pause impulses.
output("plot 1/0");
return;
}
// Label the longest pauses.
execution_pauses =
RestrictRangesTo(execution_pauses, range_start, range_end);
execution_pauses.sort(
function(a, b) { return b.duration() - a.duration(); });
var max_pause_time = execution_pauses.length > 0
? execution_pauses[0].duration() : 0;
padding = kPauseLabelPadding * (range_end - range_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";
var label_x = pause.end + padding;
var label_y = Math.max(1, (pause.duration() * y_scale));
output("set label \"" + label_content + "\" at " +
label_x + "," + label_y + " font \"Helvetica,7'\"");
obj_index++;
}
// Scale second Y-axis appropriately.
var y2range = max_pause_time * num_timer_event / kY1Offset * 2;
output("set y2range [0:" + y2range + "]");
// Plot graph with impulses as data set.
output("plot '-' using 1:2 axes x1y2 with impulses ls 1");
for (var i = 0; i < execution_pauses.length; i++) {
var pause = execution_pauses[i];
output(pause.end + " " + pause.duration());
obj_index++;
}
output("e");
return obj_index;
};
}