v8/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.Execute';

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 kNumRows = 11;
var kBarWidth = 0.33;
var kPauseTolerance = 0.05;  // Milliseconds.
var kY1Offset = 3;
var kY2Factor = 5;
var kResX = 1600;
var kResY = 400;
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 = [];


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.
        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_end;
      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();