v8/tools/profviz/composer.js
jkummerow eca64a2a8c [ic] Drop TimerEventScopes from *IC_Miss runtime functions
This is mostly a performance experiment. If it provides no speedup,
it can be reverted to keep IC miss events in timeline plots.
Otherwise, the RuntimeCallStats system is the replacement tool for
investigating performance issues related to IC misses.

This effectively reverts 1f8adc15 / r21736.

Review-Url: https://codereview.chromium.org/2480343002
Cr-Commit-Position: refs/heads/master@{#40893}
2016-11-10 13:10:25 +00:00

550 lines
20 KiB
JavaScript

// 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;
};
}