Log deopts with --log-timer-events.

R=jkummerow@chromium.org
BUG=

Review URL: https://codereview.chromium.org/17599007

git-svn-id: http://v8.googlecode.com/svn/branches/bleeding_edge@15462 ce2b1a6d-e550-0410-aec6-3dcde31c8c00

src/deoptimizer.cc

@@ -714,6 +714,10 @@ void Deoptimizer::DoComputeOutputFrames() {
 
   // Print some helpful diagnostic information.
   int64_t start = OS::Ticks();
+  if (FLAG_log_timer_events &&
+      compiled_code_->kind() == Code::OPTIMIZED_FUNCTION) {
+    LOG(isolate(), CodeDeoptEvent(compiled_code_));
+  }
   if (trace_) {
     PrintF("[deoptimizing (DEOPT %s): begin 0x%08" V8PRIxPTR " ",
            MessageFor(bailout_type_),

src/log.cc

@@ -637,6 +637,16 @@ void Logger::SharedLibraryEvent(const wchar_t* library_path,
 }
 
 
+void Logger::CodeDeoptEvent(Code* code) {
+  if (!log_->IsEnabled()) return;
+  ASSERT(FLAG_log_internal_timer_events);
+  LogMessageBuilder msg(this);
+  int since_epoch = static_cast<int>(OS::Ticks() - epoch_);
+  msg.Append("code-deopt,%ld,%d\n", since_epoch, code->CodeSize());
+  msg.WriteToLogFile();
+}
+
+
 void Logger::TimerEvent(StartEnd se, const char* name) {
   if (!log_->IsEnabled()) return;
   ASSERT(FLAG_log_internal_timer_events);

src/log.h

@@ -293,6 +293,8 @@ class Logger {
   // ==== Events logged by --log-timer-events. ====
   enum StartEnd { START, END };
 
+  void CodeDeoptEvent(Code* code);
+
   void TimerEvent(StartEnd se, const char* name);
 
   static void EnterExternal(Isolate* isolate);

tools/profviz/composer.js

@@ -41,7 +41,9 @@ function PlotScriptComposer(kResX, kResY) {
   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.
@@ -52,6 +54,9 @@ function PlotScriptComposer(kResX, kResY) {
   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");
@@ -72,9 +77,13 @@ function PlotScriptComposer(kResX, kResY) {
   }
 
   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; }
@@ -83,9 +92,6 @@ function PlotScriptComposer(kResX, kResY) {
     this.tick = tick;
   }
 
-  // Init values.
-  var num_timer_event = kY1Offset + 0.5;
-
   var TimerEvents = {
       'V8.Execute':
         new TimerEvent("execution", "#000000", false, 0),
@@ -127,6 +133,7 @@ function PlotScriptComposer(kResX, kResY) {
 
   var code_map = new CodeMap();
   var execution_pauses = [];
+  var deopts = [];
   var event_stack = [];
   var last_time_stamp = [];
   for (var i = 0; i < kNumThreads; i++) {
@@ -312,6 +319,10 @@ function PlotScriptComposer(kResX, kResY) {
       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.
@@ -352,6 +363,8 @@ function PlotScriptComposer(kResX, kResY) {
                             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 }
@@ -423,18 +436,27 @@ function PlotScriptComposer(kResX, kResY) {
     output("set style rect fs solid 1 noborder");
     output("set style line 1 lt 1 lw 1 lc rgb \"#000000\"");
     output("set border 15 lw 0.2");  // Draw thin border box.
+    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) {
@@ -447,6 +469,17 @@ function PlotScriptComposer(kResX, kResY) {
       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) {
@@ -459,6 +492,8 @@ function PlotScriptComposer(kResX, kResY) {
     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.