Add parallel recompilation time to histogram and plot execution pause times.

tools/plot-timer-events.js

+// Copyright 2012 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.
+
+var TimerEvents = {
+  'V8.ScriptRun'      :
+       { ranges: [], color: "#444444", pause: false, index:  1 },
+  'V8.Compile'        :
+       { ranges: [], color: "#CC0000", pause:  true, index:  2 },
+  'V8.CompileLazy'    :
+       { ranges: [], color: "#CC4400", pause:  true, index:  3 },
+  'V8.CompileEval'    :
+       { ranges: [], color: "#CC0044", pause:  true, index:  4 },
+  'V8.CompileParallel':
+       { ranges: [], color: "#CC4444", 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 kBarWidth = 0.33;
+var kMergeTolerance = 0.05;
+var kY1Offset = 3;
+var kY2Factor = 5;
+var kResX = 1600;
+var kResY = 500;
+var kLabelPadding = 5;
+var kNumPauseLabels = 7;
+
+var xrange = 0;
+var obj_index = 0;
+var execution_pauses = [];
+
+function Range(start, end) {
+  // Everthing from here are in milliseconds.
+  this.start = start;
+  this.end = end;
+}
+
+Range.prototype.duration = function() { return this.end - this.start; }
+
+
+function ProcessTimerEvent(name, start, length) {
+  var event = TimerEvents[name];
+  if (event === undefined) return;
+  start /= 1000;  // Convert to milliseconds.
+  length /= 1000;
+  var end = start + length;
+  event.ranges.push(new Range(start, end));
+  if (end > xrange) xrange = end;
+}
+
+
+function CollectData() {
+  // Collect data from log.
+  var logreader = new LogReader(
+    { 'timer-event' : { parsers: [null, parseInt, parseInt],
+                        processor: ProcessTimerEvent
+                      } });
+
+  var line;
+  while (line = readline()) {
+    logreader.processLogLine(line);
+  }
+
+  // Collect execution pauses.
+  for (name in TimerEvents) {
+    var event = TimerEvents[name];
+    if (!event.pause) 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]);
+    }
+  }
+}
+
+
+function drawBar(row, color, start, end) {
+  obj_index++;
+  command = "set object " + obj_index + " rect";
+  command += " from " + start + ", " + (row - kBarWidth + kY1Offset);
+  command += " to " + end + ", " + (row + kBarWidth + kY1Offset);
+  command += " fc rgb \"" + color + "\"";
+  print(command);
+}
+
+
+function MergeRanges(ranges, merge_tolerance) {
+  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;
+    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.
+      if (next_range.start >= merge_end + kMergeTolerance) break;
+      // Merge ranges.
+      if ((next_range.end > merge_end)) {  // Extend range end.
+        merge_end = next_range.end;
+      }
+    }
+    result.push(new Range(merge_start, merge_end));
+  }
+  return result;
+}
+
+
+function GnuplotOutput() {
+  print("set terminal pngcairo size 1600,400 enhanced font 'Helvetica,10'");
+  print("set yrange [0:15]");
+  print("set xlabel \"execution time in ms\"");
+  print("set xrange [0:" + xrange + "]");
+  print("set style fill pattern 2 bo 1");
+  print("set style rect fc lt -1 fs solid 1 noborder");
+  print("set style line 1 lt 1 lw 1 lc rgb \"#000000\"");
+  print("set xtics out nomirror");
+  print("unset key");
+
+  // Name Y-axis.
+  var ytics = [];
+  for (name in TimerEvents) {
+    var index = TimerEvents[name].index;
+    ytics.push('"' + name + '"' + ' ' + (index + kY1Offset));
+  }
+  print("set ytics out nomirror (" + ytics.join(', ') + ")");
+
+  // Smallest visible gap given our resolution.
+  // We remove superfluous objects to go easy on Gnuplot.
+  var visible_gap = xrange / kResX / 2;
+
+  // Plot timeline.
+  for (var name in TimerEvents) {
+    var event = TimerEvents[name];
+    var ranges = MergeRanges(event.ranges, visible_gap);
+    for (var i = 0; i < ranges.length; i++) {
+      drawBar(event.index, event.color, ranges[i].start, ranges[i].end);
+    }
+  }
+
+  if (execution_pauses.length == 0) {
+    print("plot 1/0");
+    return;
+  }
+
+  // Exclude execution pauses from the execution timeline.
+  var execution_row = TimerEvents['V8.ScriptRun'].index;
+  exclude_ranges = MergeRanges(execution_pauses,
+                               Math.max(visible_gap, kMergeTolerance));
+  for (var i = 0; i < exclude_ranges.length; i++) {
+    var pause = execution_pauses[i];
+    drawBar(execution_row, "#FFFFFF", pause.start, pause.end);
+  }
+
+
+  // Plot execution pauses as impulses.  This may be better resolved
+  // due to possibly smaller merge tolerance.
+  execution_pauses = MergeRanges(execution_pauses, kMergeTolerance);
+
+  // 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 / kResX;
+  var y_scale = kY1Offset / max_pause_time;
+  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));
+    print("set label \"" + label_content + "\" at " +
+          label_x + "," + label_y + " font \"Helvetica,7'\"");
+  }
+
+  // Scale second Y-axis appropriately.
+  print("set y2range [0:" + (max_pause_time * kY2Factor) + "]");
+
+  print("plot '-' using 1:2 axes x1y2 with impulses ls 1");
+  for (var i = 0; i < execution_pauses.length; i++) {
+    var pause = execution_pauses[i];
+    print(pause.end + " " + pause.duration());
+  }
+  print("e");
+}
+
+CollectData();
+GnuplotOutput();
+