Take instrumentation overhead into account when plotting.

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
@@ skipping 25 matching lines @@
 var kPauseTolerance = 0.1;  // Milliseconds.
 var kY1Offset = 10;
 
 var kResX = 1600;
 var kResY = 600;
 var kPauseLabelPadding = 5;
 var kNumPauseLabels = 7;
 var kTickHalfDuration = 0.5;  // Milliseconds
 var kCodeKindLabelPadding = 100;
 
-var kOverrideRangeStart = undefined;
-var kOverrideRangeEnd = undefined;
-
 var num_timer_event = kY1Offset + 0.5;
 
 
 function TimerEvent(color, pause, no_execution) {
   this.color = color;
   this.pause = pause;
   this.ranges = [];
   this.no_execution = no_execution;
   this.index = ++num_timer_event;
 }
@@ skipping 37 matching lines @@
   'inl.cache': new CodeKind("#4444AA", [4, 5, 6, 7, 8, 9, 10, 11, 12, 13]),
 }
 
 
 var xrange_start = Infinity;
 var xrange_end = 0;
 var obj_index = 0;
 var execution_pauses = [];
 var code_map = new CodeMap();
 
+var xrange_start_override = undefined;
+var xrange_end_override = undefined;
+var distortion_per_entry = 0.005;  // Milliseconds
+
+var sort_by_start = [];
+var sort_by_end = [];
+var sorted_ticks = [];
+
 
 function Range(start, end) {
   // Everthing from here are in milliseconds.
   this.start = start;
   this.end = end;
 }
 
 
+function Tick(tick) {
+  this.tick = tick;
+}
+
+
 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 (event == kExecutionEvent) {
-    if (start < xrange_start) xrange_start = start;
-    if (end > xrange_end) xrange_end = end;
-  }
+  var range = new Range(start, end);
+  event.ranges.push(range);
+  sort_by_start.push(range);
+  sort_by_end.push(range);
 }
 
 
 function ProcessCodeCreateEvent(type, kind, address, size, name) {
   var code_entry = new CodeMap.CodeEntry(size, name);
   code_entry.kind = kind;
   code_map.addCode(address, code_entry);
 }
 
 
@@ skipping 25 matching lines @@
   for (name in CodeKinds) {
     if (CodeKinds[name].kinds.indexOf(kind) >= 0) {
       return CodeKinds[name];
     }
   }
 }
 
 
 function ProcessTickEvent(pc, sp, timer, unused_x, unused_y, vmstate, stack) {
   timer /= 1000;
-  var tick = new Range(timer - kTickHalfDuration, timer + kTickHalfDuration);
+  var tick = new Tick(timer);
 
+  var entered = false;
   var entry = code_map.findEntry(pc);
   if (entry) {
     FindCodeKind(entry.kind).in_execution.push(tick);
+    entered = true;
   }
 
   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);
+      entered = true;
+    }
+  }
+
+  if (entered) sorted_ticks.push(tick);
+}
+
+
+function ProcessDistortion(distortion_in_picoseconds) {
+  distortion_per_entry = distortion_in_picoseconds / 1000000;
+}
+
+
+function ProcessPlotRange(start, end) {
+  xrange_start_override = start;
+  xrange_end_override = end;
+}
+
+
+function Undistort() {
+  // Undistort timers wrt instrumentation overhead.
+  sort_by_start.sort(function(a, b) { return b.start - a.start; });
+  sort_by_end.sort(function(a, b) { return b.end - a.end; });
+  sorted_ticks.sort(function(a, b) { return b.tick - a.tick; });
+  var distortion = 0;
+
+  var next_start = sort_by_start.pop();
+  var next_end = sort_by_end.pop();
+  var next_tick = sorted_ticks.pop();
+
+  function UndistortTicksUntil(tick) {
+    while (next_tick) {
+      if (next_tick.tick > tick) return;
+      next_tick.tick -= distortion;
+      next_tick = sorted_ticks.pop();
+    }
+  }
+
+  while (true) {
+    var next_start_start = next_start ? next_start.start : Infinity;
+    var next_end_end = next_end ? next_end.end : Infinity;
+    if (!next_start && !next_end) {
+      UndistortTicksUntil(Infinity);
+      break;
+    }
+    if (next_start_start <= next_end_end) {
+      UndistortTicksUntil(next_start_start);
+      // Undistort the start time stamp.
+      next_start.start -= distortion;
+      next_start = sort_by_start.pop();
+    } else {
+      // Undistort the end time stamp.  We completely attribute the overhead
+      // to the point when we stop and log the timer, so we increase the
+      // distortion only here.
+      UndistortTicksUntil(next_end_end);
+      distortion += distortion_per_entry;
+      next_end.end -= distortion;
+      next_end = sort_by_end.pop();
+    }
+  }
+
+  sort_by_start = undefined;
+  sort_by_end = undefined;
+  sorted_ticks = undefined;
+
+  // Make sure that start <= end applies for every range.
+  for (name in TimerEvents) {
+    var ranges = TimerEvents[name].ranges;
+    for (var j = 0; j < ranges.length; j++) {
+      if (ranges[j].end < ranges[j].start) ranges[j].end = ranges[j].start;
     }
   }
 }
 
 
 function CollectData() {
   // Collect data from log.
   var logreader = new LogReader(
     { 'timer-event' :   { parsers: [null, parseInt, parseInt],
                           processor: ProcessTimerEvent },
       '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 },
       'tick':           { parsers: [parseInt, parseInt, parseInt,
                                     null, null, parseInt, 'var-args'],
                           processor: ProcessTickEvent },
+      'distortion':     { parsers: [parseInt],
+                          processor: ProcessDistortion },
+      'plot-range':     { parsers: [parseInt, parseInt],
+                          processor: ProcessPlotRange },
     });
 
   var line;
   while (line = readline()) {
     logreader.processLogLine(line);
   }
 
+  Undistort();
+
+  // Figure out plot range.
+  var execution_ranges = kExecutionEvent.ranges;
+  for (var i = 0; i < execution_ranges.length; i++) {
+    if (execution_ranges[i].start < xrange_start) {
+      xrange_start = execution_ranges[i].start;
+    }
+    if (execution_ranges[i].end > xrange_end) {
+      xrange_end = execution_ranges[i].end;
+    }
+  }
+
   // 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);
 
   // Knock out time not spent in javascript execution.  Note that this also
@@ skipping 20 matching lines @@
 function DrawBar(row, color, start, end, width) {
   obj_index++;
   command = "set object " + obj_index + " rect";
   command += " from " + start + ", " + (row - width);
   command += " to " + end + ", " + (row + width);
   command += " fc rgb \"" + color + "\"";
   print(command);
 }
 
 
+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 > 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.
+    if (merge_end < merge_start) continue;  // Not an actual 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;
@@ skipping 69 matching lines @@
     } else {
       throw new Error("this should not happen!");
     }
   }
 
   return result;
 }
 
 
 function GnuplotOutput() {
-  xrange_start = kOverrideRangeStart ? kOverrideRangeStart : xrange_start;
-  xrange_end = kOverrideRangeEnd ? kOverrideRangeEnd : xrange_end;
+  xrange_start = (xrange_start_override || xrange_start_override == 0)
+                     ? xrange_start_override : xrange_start;
+  xrange_end = (xrange_end_override || xrange_end_override == 0)
+                   ? xrange_end_override : xrange_end;
   print("set terminal pngcairo size " + kResX + "," + kResY +
         " enhanced font 'Helvetica,10'");
   print("set yrange [0:" + (num_timer_event + 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");
@@ skipping 19 matching lines @@
               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(code_kind.in_execution);
+    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(code_kind.stack_frames[i]);
+      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 * (xrange_end - xrange_start) / kResX;
   var label_x = xrange_start;
@@ skipping 35 matching lines @@
   for (var i = 0; i < execution_pauses.length; i++) {
     var pause = execution_pauses[i];
     print(pause.end + " " + pause.duration());
   }
   print("e");
 }
 
 
 CollectData();
 GnuplotOutput();