Log deopts with --log-timer-events.

tools/profviz/composer.js

 // Copyright 2013 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 23 matching lines @@
 function PlotScriptComposer(kResX, kResY) {
   // Constants.
   var kV8BinarySuffixes = ["/d8", "/libv8.so"];
   var kStackFrames = 8;             // Stack frames to display in the plot.
 
   var kTimerEventWidth = 0.33;      // Width of each timeline.
   var kExecutionFrameWidth = 0.2;   // Width of the top stack frame line.
   var kStackFrameWidth = 0.1;       // Width of the lower stack frame lines.
   var kGapWidth = 0.05;             // Gap between stack frame lines.
 
-  var kY1Offset = 10;               // Offset for stack frame vs. event lines.
+  var kY1Offset = 11;               // Offset for stack frame vs. event lines.
+  var kDeoptRow = 7;                // Row displaying deopts.
+  var kMaxDeoptLength = 4;          // Draw size of the largest deopt.
   var kPauseLabelPadding = 5;       // Padding for pause time labels.
   var kNumPauseLabels = 7;          // Number of biggest pauses to label.
   var kCodeKindLabelPadding = 100;  // Padding for code kind labels.
 
   var kTickHalfDuration = 0.5;      // Duration of half a tick in ms.
   var kMinRangeLength = 0.0005;     // Minimum length for an event in ms.
 
   var kNumThreads = 2;              // Number of threads.
   var kExecutionThreadId = 0;       // ID of main thread.
 
+  // Init values.
+  var num_timer_event = kY1Offset + 0.5;
+
   // Data structures.
   function TimerEvent(label, color, pause, thread_id) {
     assert(thread_id >= 0 && thread_id < kNumThreads, "invalid thread id");
     this.label = label;
     this.color = color;
     this.pause = pause;
     this.ranges = [];
     this.thread_id = thread_id;
     this.index = ++num_timer_event;
   }
 
   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;
   }
 
   function Range(start, end) {
-    // Everthing here are in milliseconds.
-    this.start = start;
-    this.end = end;
+    this.start = start;  // In milliseconds.
+    this.end = end;      // In milliseconds.
+  }
+
+  function Deopt(time, size) {
+    this.time = time;  // In milliseconds.
+    this.size = size;  // In bytes.
   }
 
   Range.prototype.duration = function() { return this.end - this.start; }
 
   function Tick(tick) {
     this.tick = tick;
   }
 
-  // Init values.
-  var num_timer_event = kY1Offset + 0.5;
-
   var TimerEvents = {
       'V8.Execute':
         new TimerEvent("execution", "#000000", false, 0),
       'V8.External':
         new TimerEvent("external", "#3399FF", false, 0),
       'V8.CompileFullCode':
         new TimerEvent("compile unopt", "#CC0000",  true, 0),
       'V8.RecompileSynchronous':
         new TimerEvent("recompile sync", "#CC0044",  true, 0),
       'V8.RecompileParallel':
@@ skipping 21 matching lines @@
       '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, 14]),
       'reg.exp. ': new CodeKind("#0000FF", [15]),
   };
 
   var code_map = new CodeMap();
   var execution_pauses = [];
+  var deopts = [];
   var event_stack = [];
   var last_time_stamp = [];
   for (var i = 0; i < kNumThreads; i++) {
     event_stack[i] = [];
     last_time_stamp[i] = -1;
   }
 
   var range_start = undefined;
   var range_end = undefined;
   var obj_index = 0;
@@ skipping 165 matching lines @@
     };
 
     var processCodeMoveEvent = function(from, to) {
       code_map.moveCode(from, to);
     };
 
     var processCodeDeleteEvent = function(address) {
       code_map.deleteCode(address);
     };
 
+    var processCodeDeoptEvent = function(time, size) {
+      deopts.push(new Deopt(time, size));
+    }
+
     var processSharedLibrary = function(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;
         }
       }
@@ skipping 20 matching lines @@
         'timer-event-end':   { parsers: [null, parseTimeStamp],
                                processor: processTimerEventEnd },
         '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 },
+        'code-deopt':     { parsers: [parseTimeStamp, parseInt],
+                            processor: processCodeDeoptEvent },
         'tick':           { parsers: [parseInt, parseInt, parseTimeStamp,
                                       null, null, parseInt, 'var-args'],
                             processor: processTickEvent }
       });
 
     var line;
     while (line = input()) {
       logreader.processLogLine(line);
     }
 
@@ skipping 50 matching lines @@
   };
 
 
   this.assembleOutput = function(output) {
     output("set yrange [0:" + (num_timer_event + 1) + "]");
     output("set xlabel \"execution time in ms\"");
     output("set xrange [" + range_start + ":" + range_end + "]");
     output("set style fill pattern 2 bo 1");
     output("set style rect fs solid 1 noborder");
     output("set style line 1 lt 1 lw 1 lc rgb \"#000000\"");
+    output("set style line 2 lt 1 lw 1 lc rgb \"#9944CC\"");
     output("set xtics out nomirror");
     output("unset key");
 
-    function DrawBar(row, color, start, end, width) {
+    function DrawBarBase(color, start, end, top, bottom) {
       obj_index++;
       command = "set object " + obj_index + " rect";
-      command += " from " + start + ", " + (row - width);
-      command += " to " + end + ", " + (row + width);
+      command += " from " + start + ", " + top;
+      command += " to " + end + ", " + bottom;
       command += " fc rgb \"" + color + "\"";
       output(command);
     }
 
+    function DrawBar(row, color, start, end, width) {
+      DrawBarBase(color, start, end, row + width, row - width);
+    }
+
+    function DrawHalfBar(row, color, start, end, width) {
+      DrawBarBase(color, start, end, row, row - width);
+    }
+
     var percentages = {};
     var total = 0;
     for (var name in TimerEvents) {
       var event = TimerEvents[name];
       var ranges = RestrictRangesTo(event.ranges, range_start, range_end);
       ranges = MergeRanges(ranges);
       var sum =
         ranges.map(function(range) { return range.duration(); })
             .reduce(function(a, b) { return a + b; }, 0);
       percentages[name] = (sum / (range_end - range_start) * 100).toFixed(1);
     }
 
+    // Plot deopts.
+    deopts.sort(function(a, b) { return b.size - a.size; });
+    var max_deopt_size = deopts.length > 0 ? deopts[0].size : Infinity;
+
+    for (var i = 0; i < deopts.length; i++) {
+      var deopt = deopts[i];
+      DrawHalfBar(kDeoptRow, "#9944CC", deopt.time,
+                  deopt.time + 10 * pause_tolerance,
+                  deopt.size / max_deopt_size * kMaxDeoptLength);
+    }
+
     // Name Y-axis.
     var ytics = [];
     for (name in TimerEvents) {
       var index = TimerEvents[name].index;
       var label = TimerEvents[name].label;
       ytics.push('"' + label + ' (' + percentages[name] + '%%)" ' + index);
     }
     ytics.push('"code kind color coding" ' + kY1Offset);
     ytics.push('"code kind in execution" ' + (kY1Offset - 1));
     ytics.push('"top ' + kStackFrames + ' js stack frames"' + ' ' +
                (kY1Offset - 2));
     ytics.push('"pause times" 0');
+    ytics.push('"max deopt size: ' + (max_deopt_size / 1024).toFixed(1) +
+               ' kB" ' + kDeoptRow);
     output("set ytics out nomirror (" + ytics.join(', ') + ")");
 
     // Plot timeline.
     for (var name in TimerEvents) {
       var event = TimerEvents[name];
       var ranges = MergeRanges(event.ranges);
       for (var i = 0; i < ranges.length; i++) {
         DrawBar(event.index, event.color,
                 ranges[i].start, ranges[i].end,
                 kTimerEventWidth);
@@ skipping 64 matching lines @@
     output("plot '-' using 1:2 axes x1y2 with impulses ls 1");
     for (var i = 0; i < execution_pauses.length; i++) {
       var pause = execution_pauses[i];
       output(pause.end + " " + pause.duration());
       obj_index++;
     }
     output("e");
     return obj_index;
   };
 }