Include more information in --prof log.

tools/plot-timer-events.js

Index: tools/plot-timer-events.js
diff --git a/tools/plot-timer-events.js b/tools/plot-timer-events.js
index 8ef0b8e4add72d24a04b1e6b06e22931b5cc71f4..d5e3a3f6d2b4b71801c510796cf9d4245dbcb98c 100644
--- a/tools/plot-timer-events.js
+++ b/tools/plot-timer-events.js
@@ -25,50 +25,83 @@
 // (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 kV8BinarySuffixes = ["/d8", "/libv8.so"];
+var kStackFrames = 16;

[Jakob Kummerow, 2012/11/28 09:18:47]

As discussed offline, a smaller number is probably enough here (4 maybe?).

 
-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 kTimerEventWidth = 0.33;
+var kExecutionFrameWidth = 0.2;
+var kStackFrameWidth = 0.1;
+var kGapWidth = 0.05;
+
+var kPauseTolerance = 0.1;  // Milliseconds.
+var kY1Offset = 12;
 
-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 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;
+}
+
+
+var TimerEvents = {
+  'V8.Execute':              new TimerEvent("#000000", false, false),
+  'V8.External':             new TimerEvent("#3399FF", false,  true),
+  'V8.CompileFullCode':      new TimerEvent("#CC0000",  true,  true),
+  'V8.RecompileSynchronous': new TimerEvent("#CC0044",  true,  true),
+  'V8.RecompileParallel':    new TimerEvent("#CC4499", false, false),
+  'V8.CompileEval':          new TimerEvent("#CC4400",  true,  true),
+  'V8.Parse':                new TimerEvent("#00CC00",  true,  true),
+  'V8.PreParse':             new TimerEvent("#44CC00",  true,  true),
+  'V8.ParseLazy':            new TimerEvent("#00CC44",  true,  true),
+  'V8.GCScavenger':          new TimerEvent("#0044CC",  true,  true),
+  'V8.GCCompactor':          new TimerEvent("#4444CC",  true,  true),
+  'V8.GCContext':            new TimerEvent("#4400CC",  true,  true),
+}
+
+var kExecutionEvent = TimerEvents['V8.Execute'];
+
+
+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;
+}
+
+
+var CodeKinds = {
+  'external ': new CodeKind("#3399FF", [-3]),
+  'reg.exp. ': new CodeKind("#0000FF", [-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]),
+}
+
+
 var xrange_start = Infinity;
 var xrange_end = 0;
 var obj_index = 0;
 var execution_pauses = [];
+var code_map = new CodeMap();
 
 
 function Range(start, end) {
@@ -88,19 +121,89 @@ function ProcessTimerEvent(name, start, length) {
   length /= 1000;
   var end = start + length;
   event.ranges.push(new Range(start, end));
-  if (name == kExecutionName) {
+  if (event == kExecutionEvent) {
     if (start < xrange_start) xrange_start = start;
     if (end > xrange_end) xrange_end = end;
   }
 }
 
 
+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);
+}
+
+
+function ProcessCodeMoveEvent(from, to) {
+  code_map.moveCode(from, to);
+}
+
+
+function ProcessCodeDeleteEvent(address) {
+  code_map.deleteCode(address);
+}
+
+
+function ProcessSharedLibrary(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);
+}
+
+
+function FindCodeKind(kind) {
+  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 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);
+    }
+  }
+}
+
+
 function CollectData() {
   // Collect data from log.
   var logreader = new LogReader(
-    { 'timer-event' : { parsers: [null, parseInt, parseInt],
-                        processor: ProcessTimerEvent
-                      } });
+    { '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 },
+    });
 
   var line;
   while (line = readline()) {
@@ -112,25 +215,42 @@ function CollectData() {
     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
+  // includes time spent external code, which do not contribute to execution
+  // pauses.
+  var exclude_ranges = [];
+  for (name in TimerEvents) {
+    var event = TimerEvents[name];
+    if (!event.no_execution) 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]);
+      exclude_ranges.push(ranges[j]);
     }
   }
+  
+  kExecutionEvent.ranges = MergeRanges(kExecutionEvent.ranges);
+  exclude_ranges = MergeRanges(exclude_ranges);
+  kExecutionEvent.ranges = ExcludeRanges(kExecutionEvent.ranges,
+                                         exclude_ranges);
 }
 
 
-function drawBar(row, color, start, end) {
+function DrawBar(row, color, start, end, width) {
   obj_index++;
   command = "set object " + obj_index + " rect";
-  command += " from " + start + ", " + (row - kBarWidth + kY1Offset);
-  command += " to " + end + ", " + (row + kBarWidth + kY1Offset);
+  command += " from " + start + ", " + (row - width);
+  command += " to " + end + ", " + (row + width);
   command += " fc rgb \"" + color + "\"";
   print(command);
 }
 
 
-function MergeRanges(ranges, merge_tolerance) {
+function MergeRanges(ranges) {
   ranges.sort(function(a, b) { return a.start - b.start; });
   var result = [];
   var j = 0;
@@ -141,7 +261,7 @@ function MergeRanges(ranges, merge_tolerance) {
     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;
+      if (next_range.start > merge_end + kPauseTolerance) break;
       // Merge ranges.
       if (next_range.end > merge_end) {  // Extend range end.
         merge_end = next_range.end;
@@ -239,10 +359,9 @@ function ExcludeRanges(include, exclude) {
 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 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");
@@ -255,35 +374,57 @@ function GnuplotOutput() {
   var ytics = [];
   for (name in TimerEvents) {
     var index = TimerEvents[name].index;
-    ytics.push('"' + name + '"' + ' ' + (index + kY1Offset));
+    ytics.push('"' + name + '"' + ' ' + index);
   }
+  ytics.push('"code kind being executed"' + ' ' + (kY1Offset - 1));
+  ytics.push('"top ' + kStackFrames + ' js stack frames"' + ' ' +
+             (kY1Offset - 2));
+  ytics.push('"pause times" 0');
   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;
+    var ranges = MergeRanges(event.ranges);
     for (var i = 0; i < ranges.length; i++) {
-      drawBar(event.index, event.color, ranges[i].start, ranges[i].end);
+      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(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]);
+      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;
+  var label_y = kY1Offset;
+  for (var name in CodeKinds) {
+    label_x += padding;
+    print("set label \"" + name + "\" at " + label_x + "," + label_y +
+          "textcolor rgb \"" + CodeKinds[name].color + "\" " +
+          "font \"Helvetica,9'\"");
+  }
 
   if (execution_pauses.length == 0) {
     // Force plot and return without plotting execution pause impulses.
@@ -291,21 +432,13 @@ function GnuplotOutput() {
     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;
+  padding = kPauseLabelPadding * (xrange_end - xrange_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";
@@ -316,8 +449,8 @@ function GnuplotOutput() {
   }
 
   // Scale second Y-axis appropriately.
-  print("set y2range [0:" + (max_pause_time * kY2Factor) + "]");
-
+  var y2range = max_pause_time * num_timer_event / kY1Offset * 2;
+  print("set y2range [0:" + y2range + "]");
   // 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++) {