Take instrumentation overhead into account when plotting.

R=jkummerow@chromium.org
BUG=

Review URL: https://chromiumcodereview.appspot.com/11348298

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

src/counters.cc

@@ -77,7 +77,7 @@ void* Histogram::CreateHistogram() const {
 
 // Start the timer.
 void HistogramTimer::Start() {
-  if (histogram_.Enabled() || FLAG_log_timer_events) {
+  if (histogram_.Enabled() || FLAG_log_internal_timer_events) {
     stop_time_ = 0;
     start_time_ = OS::Ticks();
   }
@@ -91,7 +91,7 @@ void HistogramTimer::Stop() {
     int milliseconds = static_cast<int>(stop_time_ - start_time_) / 1000;
     histogram_.AddSample(milliseconds);
   }
-  if (FLAG_log_timer_events) {
+  if (FLAG_log_internal_timer_events) {
     LOG(Isolate::Current(),
         TimerEvent(histogram_.name_, start_time_, OS::Ticks()));
   }

src/flag-definitions.h

@@ -664,7 +664,10 @@ DEFINE_string(logfile, "v8.log", "Specify the name of the log file.")
 DEFINE_bool(ll_prof, false, "Enable low-level linux profiler.")
 DEFINE_string(gc_fake_mmap, "/tmp/__v8_gc__",
               "Specify the name of the file for fake gc mmap used in ll_prof")
-DEFINE_bool(log_timer_events, false, "Log histogram timer events.")
+DEFINE_bool(log_internal_timer_events, false, "Time internal events.")
+DEFINE_bool(log_timer_events, false,
+            "Time events including external callbacks.")
+DEFINE_implication(log_timer_events, log_internal_timer_events)
 
 //
 // Disassembler only flags

src/log-utils.cc

@@ -67,7 +67,7 @@ void Log::Initialize() {
     FLAG_log_suspect = true;
     FLAG_log_handles = true;
     FLAG_log_regexp = true;
-    FLAG_log_timer_events = true;
+    FLAG_log_internal_timer_events = true;
   }
 
   // --prof implies --log-code.
@@ -82,7 +82,7 @@ void Log::Initialize() {
   bool open_log_file = FLAG_log || FLAG_log_runtime || FLAG_log_api
       || FLAG_log_code || FLAG_log_gc || FLAG_log_handles || FLAG_log_suspect
       || FLAG_log_regexp || FLAG_log_state_changes || FLAG_ll_prof
-      || FLAG_log_timer_events;
+      || FLAG_log_internal_timer_events;
 
   // If we're logging anything, we need to open the log file.
   if (open_log_file) {

src/log.cc

@@ -707,7 +707,7 @@ void Logger::SharedLibraryEvent(const wchar_t* library_path,
 
 void Logger::TimerEvent(const char* name, int64_t start, int64_t end) {
   if (!log_->IsEnabled()) return;
-  ASSERT(FLAG_log_timer_events);
+  ASSERT(FLAG_log_internal_timer_events);
   LogMessageBuilder msg(this);
   int since_epoch = static_cast<int>(start - epoch_);
   int pause_time = static_cast<int>(end - start);
@@ -1379,8 +1379,7 @@ void Logger::TickEvent(TickSample* sample, bool overflow) {
   msg.AppendAddress(sample->pc);
   msg.Append(',');
   msg.AppendAddress(sample->sp);
-  msg.Append(",%ld",
-      FLAG_log_timer_events ? static_cast<int>(OS::Ticks() - epoch_) : 0);
+  msg.Append(",%ld", static_cast<int>(OS::Ticks() - epoch_));
   if (sample->has_external_callback) {
     msg.Append(",1,");
     msg.AppendAddress(sample->external_callback);
@@ -1789,7 +1788,7 @@ bool Logger::SetUp() {
   bool start_logging = FLAG_log || FLAG_log_runtime || FLAG_log_api
     || FLAG_log_code || FLAG_log_gc || FLAG_log_handles || FLAG_log_suspect
     || FLAG_log_regexp || FLAG_log_state_changes || FLAG_ll_prof
-    || FLAG_log_timer_events;
+    || FLAG_log_internal_timer_events;
 
   if (start_logging) {
     logging_nesting_ = 1;
@@ -1807,7 +1806,7 @@ bool Logger::SetUp() {
     }
   }
 
-  if (FLAG_log_timer_events) epoch_ = OS::Ticks();
+  if (FLAG_log_internal_timer_events || FLAG_prof) epoch_ = OS::Ticks();
 
   return true;
 }

src/log.h

@@ -287,11 +287,11 @@ class Logger {
    public:
     TimerEventScope(Isolate* isolate, const char* name)
         : isolate_(isolate), name_(name), start_(0) {
-      if (FLAG_log_timer_events) start_ = OS::Ticks();
+      if (FLAG_log_internal_timer_events) start_ = OS::Ticks();
     }
 
     ~TimerEventScope() {
-      if (FLAG_log_timer_events) LogTimerEvent();
+      if (FLAG_log_internal_timer_events) LogTimerEvent();
     }
 
     void LogTimerEvent();

tools/plot-timer-events

@@ -32,9 +32,40 @@ if [ ! -x "$d8_exec" ]; then
   exit 1
 fi
 
-# nm spits out 'no symbols found' messages to stderr.
-cat $log_file | $d8_exec $tools_path/csvparser.js \
+if [ -n "$DISTORTION" ]; then
+  distortion=$DISTORTION
+else
+  # Try to find out how much the instrumentation overhead is.
+  calibration_log=calibration.log
+  calibration_script="for (var i = 0; i < 1000000; i++) print();"
+
+  $d8_exec --nocrankshaft --prof --logfile $calibration_log \
+       --log-timer-events -e "$calibration_script" > /dev/null
+  t_1=`grep "V8.Execute" $calibration_log  | tail -n1 | awk -F, '{print $4}'`
+  n_1=`grep "timer-event" $calibration_log  | wc -l`
+
+  $d8_exec --nocrankshaft --prof --logfile $calibration_log \
+       --log-internal-timer-events -e "$calibration_script" > /dev/null
+  t_2=`grep "V8.Execute" $calibration_log  | tail -n1 | awk -F, '{print $4}'`
+  n_2=`grep "timer-event" $calibration_log  | wc -l`
+
+  rm $calibration_log
+
+  # Overhead in picoseconds.
+  distortion=`echo "1000*($t_1 - $t_2)/($n_1 - $n_2)" | bc`
+fi
+
+if [ -n "$PLOT_RANGE" ]; then
+  plot_range=$PLOT_RANGE
+else
+  plot_range=auto,auto
+fi
+
+echo "DISTORTION=$distortion"
+echo "PLOT_RANGE=$plot_range"
+
+echo -e "plot-range,$plot_range\ndistortion,$distortion" | cat - $log_file |
+    $d8_exec $tools_path/csvparser.js \
     $tools_path/splaytree.js $tools_path/codemap.js \
     $tools_path/logreader.js $tools_path/plot-timer-events.js \
     2>/dev/null | gnuplot > timer-events.png
-

tools/plot-timer-events.js

@@ -43,9 +43,6 @@ var kNumPauseLabels = 7;
 var kTickHalfDuration = 0.5;  // Milliseconds
 var kCodeKindLabelPadding = 100;
 
-var kOverrideRangeStart = undefined;
-var kOverrideRangeEnd = undefined;
-
 var num_timer_event = kY1Offset + 0.5;
 
 
@@ -103,6 +100,14 @@ 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.
@@ -111,6 +116,11 @@ function Range(start, end) {
 }
 
 
+function Tick(tick) {
+  this.tick = tick;
+}
+
+
 Range.prototype.duration = function() { return this.end - this.start; }
 
 
@@ -120,11 +130,10 @@ function ProcessTimerEvent(name, start, length) {
   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);
 }
 
 
@@ -170,11 +179,13 @@ function FindCodeKind(kind) {
 
 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++) {
@@ -182,6 +193,76 @@ function ProcessTickEvent(pc, sp, timer, unused_x, unused_y, vmstate, stack) {
     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);
+      next_end.end -= distortion;
+      distortion += distortion_per_entry;
+      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;
     }
   }
 }
@@ -203,6 +284,10 @@ function CollectData() {
       '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;
@@ -210,6 +295,19 @@ function CollectData() {
     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];
@@ -250,6 +348,16 @@ function DrawBar(row, color, start, end, width) {
 }
 
 
+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 = [];
@@ -268,6 +376,7 @@ function MergeRanges(ranges) {
       }
     }
     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;
@@ -357,8 +466,10 @@ function ExcludeRanges(include, exclude) {
 
 
 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) + "]");
@@ -398,7 +509,7 @@ function GnuplotOutput() {
     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);
@@ -407,7 +518,7 @@ function GnuplotOutput() {
     // 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);