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 kExecutionName = 'V8.ScriptRun';
+
+var TimerEvents = {
+  'V8.ScriptRun'      :

[Jakob Kummerow, 2012/11/22 10:56:08]

nit: free-floating colons look weird. I'd remove the spaces before them.

[Yang, 2012/11/22 13:04:20]

Done.

+       { 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.CompileFullCode':
+       { ranges: [], color: "#CC44CC", pause:  true, index:  5 },
+  'V8.RecompileSynchronous':
+       { ranges: [], color: "#AA44EE", pause:  true, index:  6 },
+  'V8.RecompileParallel':
+       { ranges: [], color: "#EE44AA", pause: false, index:  7 },
+  'V8.Parse'          :
+       { ranges: [], color: "#00CC00", pause:  true, index:  8 },
+  'V8.PreParse'       :
+       { ranges: [], color: "#44CC00", pause:  true, index:  9 },
+  'V8.ParseLazy'      :
+       { ranges: [], color: "#00CC44", pause:  true, index: 10 },
+  'V8.GCScavenger'    :
+       { ranges: [], color: "#0044CC", pause:  true, index: 11 },
+  'V8.GCCompactor'    :
+       { ranges: [], color: "#4444CC", pause:  true, index: 12 },
+  'V8.GCContext'      :
+       { ranges: [], color: "#4400CC", pause:  true, index: 13 },
+}
+
+var kNumRows = 13;
+var kBarWidth = 0.33;
+var kPauseTolerance = 0.05;  // Milliseconds.
+var kY1Offset = 3;
+var kY2Factor = 5;
+var kResX = 1600;
+var kResY = 600;
+var kLabelPadding = 5;
+var kNumPauseLabels = 7;
+
+var kOverrideRangeStart = undefined;
+var kOverrideRangeEnd = undefined;
+
+var xrange_start = Infinity;
+var xrange_end = 0;
+var obj_index = 0;
+var execution_pauses = [];
+

[Jakob Kummerow, 2012/11/22 10:56:08]

nit: two empty lines between top-level statements.

[Yang, 2012/11/22 13:04:20]

Done.

+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 (name == kExecutionName) {
+    if (start < xrange_start) xrange_start = start;
+    if (end > xrange_end) xrange_end = 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;
+    if (merge_start > xrange_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 (including merge tolerance).
+      if (next_range.start >= merge_end + kPauseTolerance) break;
+      // Merge ranges.
+      if ((next_range.end > merge_end)) {  // Extend range end.

[Jakob Kummerow, 2012/11/22 10:56:08]

nit: duplicate parentheses

[Yang, 2012/11/22 13:04:20]

Done.

+        merge_end = next_range.end;
+      }
+    }
+    if (merge_end < xrange_start) continue;  // Out of plot range.
+    result.push(new Range(merge_start, merge_end));
+  }
+  return result;
+}
+
+
+function ExcludeRanges(include, exclude) {
+  // We assume that both input lists are sorted and merged with MergeRanges.
+  var result = [];
+  var exclude_index = 0;
+  var include_index = 0;
+  var include_start, include_end, exclude_start, exclude_end;
+
+  function NextInclude() {
+    if (include_index >= include.length) return false;
+    include_start = include[include_index].start;
+    include_end = include[include_index].end;
+    include_index++;
+    return true;
+  }
+
+  function NextExclude() {
+    if (exclude_index >= exclude.length) {
+      // No more exclude, finish by repeating case (2).
+      exclude_start = Infinity;
+      exclude_end = Infinity;
+      return false;
+    }
+    exclude_start = exclude[exclude_index].start;
+    exclude_end = exclude[exclude_index].end;
+    exclude_index++;
+    return true;
+  }
+
+  if (!NextInclude() || !NextExclude()) return include;
+
+  while (true) {
+    if (exclude_end <= include_start) {
+      // (1) Exclude and include do not overlap.
+      // Include       #####
+      // Exclude   ##
+      NextExclude();
+    } else if (include_end <= exclude_start) {
+      // (2) Exclude and include do not overlap.
+      // Include   #####
+      // Exclude         ###
+      result.push(new Range(include_start, include_end));
+      if (!NextInclude()) break;
+    } else if (exclude_start <= include_start &&
+               exclude_end < include_end &&
+               include_start < exclude_end) {
+      // (3) Exclude overlaps with begin of include.
+      // Include    #######
+      // Exclude  #####
+      // Result        ####
+      include_start = exclude_start;

[Jakob Kummerow, 2012/11/22 10:56:08]

s/exclude_start/exclude_end/, I think

[Yang, 2012/11/22 13:04:20]

Nice catch. Thanks.

+      NextExclude();
+    } else if (include_start < exclude_start &&
+               include_end <= exclude_end &&
+               exclude_start < include_end) {
+      // (4) Exclude overlaps with end of include.
+      // Include    #######
+      // Exclude        #####
+      // Result     ####
+      result.push(new Range(include_start, exclude_start));
+      if (!NextInclude()) break;
+    } else if (exclude_start > include_start && exclude_end < include_end) {
+      // (5) Exclude splits include into two parts.
+      // Include    #######
+      // Exclude      ##
+      // Result     ##  ###
+      result.push(new Range(include_start, exclude_start));
+      include_start = exclude_end;
+      NextExclude();
+    } else if (exclude_start <= include_start && exclude_end >= include_end) {
+      // (6) Exclude entirely covers include.
+      // Include    ######
+      // Exclude   #########
+      if (!NextInclude()) break;
+    } else {
+      throw new Error("this should not happen!");
+    }
+  }
+
+  return result;
+}
+
+
+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 xlabel \"execution time in ms\"");
+  print("set xrange [" + xrange_start + ":" + xrange_end + "]");
+  print("set style fill pattern 2 bo 1");
+  print("set style rect 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 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;
+    for (var i = 0; i < ranges.length; i++) {
+      drawBar(event.index, event.color, ranges[i].start, ranges[i].end);
+    }
+  }
+
+  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;
+  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) + "]");
+
+  // 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++) {
+    var pause = execution_pauses[i];
+    print(pause.end + " " + pause.duration());
+  }
+  print("e");
+}
+
+CollectData();
+GnuplotOutput();
+