• Home
  • Line#
  • Scopes#
  • Navigate#
  • Raw
  • Download
1// Copyright 2013 the V8 project authors. All rights reserved.
2// Redistribution and use in source and binary forms, with or without
3// modification, are permitted provided that the following conditions are
4// met:
5//
6//     * Redistributions of source code must retain the above copyright
7//       notice, this list of conditions and the following disclaimer.
8//     * Redistributions in binary form must reproduce the above
9//       copyright notice, this list of conditions and the following
10//       disclaimer in the documentation and/or other materials provided
11//       with the distribution.
12//     * Neither the name of Google Inc. nor the names of its
13//       contributors may be used to endorse or promote products derived
14//       from this software without specific prior written permission.
15//
16// THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS
17// "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT
18// LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR
19// A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT
20// OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL,
21// SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT
22// LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE,
23// DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY
24// THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
25// (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE
26// OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
27
28Array.prototype.top = function() {
29  if (this.length == 0) return undefined;
30  return this[this.length - 1];
31}
32
33
34function PlotScriptComposer(kResX, kResY, error_output) {
35  // Constants.
36  var kV8BinarySuffixes = ["/d8", "/libv8.so"];
37  var kStackFrames = 8;             // Stack frames to display in the plot.
38
39  var kTimerEventWidth = 0.33;      // Width of each timeline.
40  var kExecutionFrameWidth = 0.2;   // Width of the top stack frame line.
41  var kStackFrameWidth = 0.1;       // Width of the lower stack frame lines.
42  var kGapWidth = 0.05;             // Gap between stack frame lines.
43
44  var kY1Offset = 11;               // Offset for stack frame vs. event lines.
45  var kDeoptRow = 7;                // Row displaying deopts.
46  var kGetTimeHeight = 0.5;         // Height of marker displaying timed part.
47  var kMaxDeoptLength = 4;          // Draw size of the largest deopt.
48  var kPauseLabelPadding = 5;       // Padding for pause time labels.
49  var kNumPauseLabels = 7;          // Number of biggest pauses to label.
50  var kCodeKindLabelPadding = 100;  // Padding for code kind labels.
51
52  var kTickHalfDuration = 0.5;      // Duration of half a tick in ms.
53  var kMinRangeLength = 0.0005;     // Minimum length for an event in ms.
54
55  var kNumThreads = 2;              // Number of threads.
56  var kExecutionThreadId = 0;       // ID of main thread.
57
58  // Init values.
59  var num_timer_event = kY1Offset + 0.5;
60
61  // Data structures.
62  function TimerEvent(label, color, pause, thread_id) {
63    assert(thread_id >= 0 && thread_id < kNumThreads, "invalid thread id");
64    this.label = label;
65    this.color = color;
66    this.pause = pause;
67    this.ranges = [];
68    this.thread_id = thread_id;
69    this.index = ++num_timer_event;
70  }
71
72  function CodeKind(color, kinds) {
73    this.color = color;
74    this.in_execution = [];
75    this.stack_frames = [];
76    for (var i = 0; i < kStackFrames; i++) this.stack_frames.push([]);
77    this.kinds = kinds;
78  }
79
80  function Range(start, end) {
81    this.start = start;  // In milliseconds.
82    this.end = end;      // In milliseconds.
83  }
84
85  function Deopt(time, size) {
86    this.time = time;  // In milliseconds.
87    this.size = size;  // In bytes.
88  }
89
90  Range.prototype.duration = function() { return this.end - this.start; }
91
92  function Tick(tick) {
93    this.tick = tick;
94  }
95
96  var TimerEvents = {
97      'V8.Execute':
98        new TimerEvent("execution", "#000000", false, 0),
99      'V8.External':
100        new TimerEvent("external", "#3399FF", false, 0),
101      'V8.CompileFullCode':
102        new TimerEvent("compile unopt", "#CC0000",  true, 0),
103      'V8.RecompileSynchronous':
104        new TimerEvent("recompile sync", "#CC0044",  true, 0),
105      'V8.RecompileConcurrent':
106        new TimerEvent("recompile async", "#CC4499", false, 1),
107      'V8.CompileEvalMicroSeconds':
108        new TimerEvent("compile eval", "#CC4400",  true, 0),
109      'V8.IcMiss':
110        new TimerEvent("ic miss", "#CC9900", false, 0),
111      'V8.ParseMicroSeconds':
112        new TimerEvent("parse", "#00CC00",  true, 0),
113      'V8.PreParseMicroSeconds':
114        new TimerEvent("preparse", "#44CC00",  true, 0),
115      'V8.ParseLazyMicroSeconds':
116        new TimerEvent("lazy parse", "#00CC44",  true, 0),
117      'V8.GCScavenger':
118        new TimerEvent("gc scavenge", "#0044CC",  true, 0),
119      'V8.GCCompactor':
120        new TimerEvent("gc compaction", "#4444CC",  true, 0),
121      'V8.GCContext':
122        new TimerEvent("gc context", "#4400CC",  true, 0),
123  };
124
125  var CodeKinds = {
126      'external ': new CodeKind("#3399FF", [-2]),
127      'runtime  ': new CodeKind("#000000", [-1]),
128      'full code': new CodeKind("#DD0000", [0]),
129      'opt code ': new CodeKind("#00EE00", [1]),
130      'code stub': new CodeKind("#FF00FF", [2]),
131      'built-in ': new CodeKind("#AA00AA", [3]),
132      'inl.cache': new CodeKind("#4444AA",
133                                [4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14]),
134      'reg.exp. ': new CodeKind("#0000FF", [15]),
135  };
136
137  var code_map = new CodeMap();
138  var execution_pauses = [];
139  var deopts = [];
140  var gettime = [];
141  var event_stack = [];
142  var last_time_stamp = [];
143  for (var i = 0; i < kNumThreads; i++) {
144    event_stack[i] = [];
145    last_time_stamp[i] = -1;
146  }
147
148  var range_start = undefined;
149  var range_end = undefined;
150  var obj_index = 0;
151  var pause_tolerance = 0.005;  // Milliseconds.
152  var distortion = 0;
153
154  // Utility functions.
155  function assert(something, message) {
156    if (!something) {
157      var error = new Error(message);
158      error_output(error.stack);
159    }
160  }
161
162  function FindCodeKind(kind) {
163    for (name in CodeKinds) {
164      if (CodeKinds[name].kinds.indexOf(kind) >= 0) {
165        return CodeKinds[name];
166      }
167    }
168  }
169
170  function TicksToRanges(ticks) {
171    var ranges = [];
172    for (var i = 0; i < ticks.length; i++) {
173      var tick = ticks[i].tick;
174      ranges.push(
175          new Range(tick - kTickHalfDuration, tick + kTickHalfDuration));
176    }
177    return ranges;
178  }
179
180  function MergeRanges(ranges) {
181    ranges.sort(function(a, b) { return a.start - b.start; });
182    var result = [];
183    var j = 0;
184    for (var i = 0; i < ranges.length; i = j) {
185      var merge_start = ranges[i].start;
186      if (merge_start > range_end) break;  // Out of plot range.
187      var merge_end = ranges[i].end;
188      for (j = i + 1; j < ranges.length; j++) {
189        var next_range = ranges[j];
190        // Don't merge ranges if there is no overlap (incl. merge tolerance).
191        if (next_range.start > merge_end + pause_tolerance) break;
192        // Merge ranges.
193        if (next_range.end > merge_end) {  // Extend range end.
194          merge_end = next_range.end;
195        }
196      }
197      if (merge_end < range_start) continue;  // Out of plot range.
198      if (merge_end < merge_start) continue;  // Not an actual range.
199      result.push(new Range(merge_start, merge_end));
200    }
201    return result;
202  }
203
204  function RestrictRangesTo(ranges, start, end) {
205    var result = [];
206    for (var i = 0; i < ranges.length; i++) {
207      if (ranges[i].start <= end && ranges[i].end >= start) {
208        result.push(new Range(Math.max(ranges[i].start, start),
209                              Math.min(ranges[i].end, end)));
210      }
211    }
212    return result;
213  }
214
215  // Public methods.
216  this.collectData = function(input, distortion_per_entry) {
217
218    var last_timestamp = 0;
219
220    // Parse functions.
221    var parseTimeStamp = function(timestamp) {
222      int_timestamp = parseInt(timestamp);
223      assert(int_timestamp >= last_timestamp, "Inconsistent timestamps.");
224      last_timestamp = int_timestamp;
225      distortion += distortion_per_entry;
226      return int_timestamp / 1000 - distortion;
227    }
228
229    var processTimerEventStart = function(name, start) {
230      // Find out the thread id.
231      var new_event = TimerEvents[name];
232      if (new_event === undefined) return;
233      var thread_id = new_event.thread_id;
234
235      start = Math.max(last_time_stamp[thread_id] + kMinRangeLength, start);
236
237      // Last event on this thread is done with the start of this event.
238      var last_event = event_stack[thread_id].top();
239      if (last_event !== undefined) {
240        var new_range = new Range(last_time_stamp[thread_id], start);
241        last_event.ranges.push(new_range);
242      }
243      event_stack[thread_id].push(new_event);
244      last_time_stamp[thread_id] = start;
245    };
246
247    var processTimerEventEnd = function(name, end) {
248      // Find out about the thread_id.
249      var finished_event = TimerEvents[name];
250      var thread_id = finished_event.thread_id;
251      assert(finished_event === event_stack[thread_id].pop(),
252             "inconsistent event stack");
253
254      end = Math.max(last_time_stamp[thread_id] + kMinRangeLength, end);
255
256      var new_range = new Range(last_time_stamp[thread_id], end);
257      finished_event.ranges.push(new_range);
258      last_time_stamp[thread_id] = end;
259    };
260
261    var processCodeCreateEvent = function(type, kind, address, size, name) {
262      var code_entry = new CodeMap.CodeEntry(size, name);
263      code_entry.kind = kind;
264      code_map.addCode(address, code_entry);
265    };
266
267    var processCodeMoveEvent = function(from, to) {
268      code_map.moveCode(from, to);
269    };
270
271    var processCodeDeleteEvent = function(address) {
272      code_map.deleteCode(address);
273    };
274
275    var processCodeDeoptEvent = function(time, size) {
276      deopts.push(new Deopt(time, size));
277    }
278
279    var processCurrentTimeEvent = function(time) {
280      gettime.push(time);
281    }
282
283    var processSharedLibrary = function(name, start, end) {
284      var code_entry = new CodeMap.CodeEntry(end - start, name);
285      code_entry.kind = -3;  // External code kind.
286      for (var i = 0; i < kV8BinarySuffixes.length; i++) {
287        var suffix = kV8BinarySuffixes[i];
288        if (name.indexOf(suffix, name.length - suffix.length) >= 0) {
289          code_entry.kind = -1;  // V8 runtime code kind.
290          break;
291        }
292      }
293      code_map.addLibrary(start, code_entry);
294    };
295
296    var processTickEvent = function(
297        pc, timer, unused_x, unused_y, vmstate, stack) {
298      var tick = new Tick(timer);
299
300      var entry = code_map.findEntry(pc);
301      if (entry) FindCodeKind(entry.kind).in_execution.push(tick);
302
303      for (var i = 0; i < kStackFrames; i++) {
304        if (!stack[i]) break;
305        var entry = code_map.findEntry(stack[i]);
306        if (entry) FindCodeKind(entry.kind).stack_frames[i].push(tick);
307      }
308    };
309    // Collect data from log.
310    var logreader = new LogReader(
311      { 'timer-event-start': { parsers: [null, parseTimeStamp],
312                               processor: processTimerEventStart },
313        'timer-event-end':   { parsers: [null, parseTimeStamp],
314                               processor: processTimerEventEnd },
315        'shared-library': { parsers: [null, parseInt, parseInt],
316                            processor: processSharedLibrary },
317        'code-creation':  { parsers: [null, parseInt, parseInt, parseInt, null],
318                            processor: processCodeCreateEvent },
319        'code-move':      { parsers: [parseInt, parseInt],
320                            processor: processCodeMoveEvent },
321        'code-delete':    { parsers: [parseInt],
322                            processor: processCodeDeleteEvent },
323        'code-deopt':     { parsers: [parseTimeStamp, parseInt],
324                            processor: processCodeDeoptEvent },
325        'current-time':   { parsers: [parseTimeStamp],
326                            processor: processCurrentTimeEvent },
327        'tick':           { parsers: [parseInt, parseTimeStamp,
328                                      null, null, parseInt, 'var-args'],
329                            processor: processTickEvent }
330      });
331
332    var line;
333    while (line = input()) {
334      for (var s of line.split("\n")) logreader.processLogLine(s);
335    }
336
337    // Collect execution pauses.
338    for (name in TimerEvents) {
339      var event = TimerEvents[name];
340      if (!event.pause) continue;
341      var ranges = event.ranges;
342      for (var j = 0; j < ranges.length; j++) execution_pauses.push(ranges[j]);
343    }
344    execution_pauses = MergeRanges(execution_pauses);
345  };
346
347
348  this.findPlotRange = function(
349    range_start_override, range_end_override, result_callback) {
350    var start_found = (range_start_override || range_start_override == 0);
351    var end_found = (range_end_override || range_end_override == 0);
352    range_start = start_found ? range_start_override : Infinity;
353    range_end = end_found ? range_end_override : -Infinity;
354
355    if (!start_found || !end_found) {
356      for (name in TimerEvents) {
357        var ranges = TimerEvents[name].ranges;
358        for (var i = 0; i < ranges.length; i++) {
359          if (ranges[i].start < range_start && !start_found) {
360            range_start = ranges[i].start;
361          }
362          if (ranges[i].end > range_end && !end_found) {
363            range_end = ranges[i].end;
364          }
365        }
366      }
367
368      for (codekind in CodeKinds) {
369        var ticks = CodeKinds[codekind].in_execution;
370        for (var i = 0; i < ticks.length; i++) {
371          if (ticks[i].tick < range_start && !start_found) {
372            range_start = ticks[i].tick;
373          }
374          if (ticks[i].tick > range_end && !end_found) {
375            range_end = ticks[i].tick;
376          }
377        }
378      }
379    }
380    // Set pause tolerance to something appropriate for the plot resolution
381    // to make it easier for gnuplot.
382    pause_tolerance = (range_end - range_start) / kResX / 10;
383
384    if (typeof result_callback === 'function') {
385      result_callback(range_start, range_end);
386    }
387  };
388
389
390  this.assembleOutput = function(output) {
391    output("set yrange [0:" + (num_timer_event + 1) + "]");
392    output("set xlabel \"execution time in ms\"");
393    output("set xrange [" + range_start + ":" + range_end + "]");
394    output("set style fill pattern 2 bo 1");
395    output("set style rect fs solid 1 noborder");
396    output("set style line 1 lt 1 lw 1 lc rgb \"#000000\"");
397    output("set border 15 lw 0.2");  // Draw thin border box.
398    output("set style line 2 lt 1 lw 1 lc rgb \"#9944CC\"");
399    output("set xtics out nomirror");
400    output("unset key");
401
402    function DrawBarBase(color, start, end, top, bottom, transparency) {
403      obj_index++;
404      command = "set object " + obj_index + " rect";
405      command += " from " + start + ", " + top;
406      command += " to " + end + ", " + bottom;
407      command += " fc rgb \"" + color + "\"";
408      if (transparency) {
409        command += " fs transparent solid " + transparency;
410      }
411      output(command);
412    }
413
414    function DrawBar(row, color, start, end, width) {
415      DrawBarBase(color, start, end, row + width, row - width);
416    }
417
418    function DrawHalfBar(row, color, start, end, width) {
419      DrawBarBase(color, start, end, row, row - width);
420    }
421
422    var percentages = {};
423    var total = 0;
424    for (var name in TimerEvents) {
425      var event = TimerEvents[name];
426      var ranges = RestrictRangesTo(event.ranges, range_start, range_end);
427      var sum =
428        ranges.map(function(range) { return range.duration(); })
429            .reduce(function(a, b) { return a + b; }, 0);
430      percentages[name] = (sum / (range_end - range_start) * 100).toFixed(1);
431    }
432
433    // Plot deopts.
434    deopts.sort(function(a, b) { return b.size - a.size; });
435    var max_deopt_size = deopts.length > 0 ? deopts[0].size : Infinity;
436
437    for (var i = 0; i < deopts.length; i++) {
438      var deopt = deopts[i];
439      DrawHalfBar(kDeoptRow, "#9944CC", deopt.time,
440                  deopt.time + 10 * pause_tolerance,
441                  deopt.size / max_deopt_size * kMaxDeoptLength);
442    }
443
444    // Plot current time polls.
445    if (gettime.length > 1) {
446      var start = gettime[0];
447      var end = gettime.pop();
448      DrawBarBase("#0000BB", start, end, kGetTimeHeight, 0, 0.2);
449    }
450
451    // Name Y-axis.
452    var ytics = [];
453    for (name in TimerEvents) {
454      var index = TimerEvents[name].index;
455      var label = TimerEvents[name].label;
456      ytics.push('"' + label + ' (' + percentages[name] + '%%)" ' + index);
457    }
458    ytics.push('"code kind color coding" ' + kY1Offset);
459    ytics.push('"code kind in execution" ' + (kY1Offset - 1));
460    ytics.push('"top ' + kStackFrames + ' js stack frames"' + ' ' +
461               (kY1Offset - 2));
462    ytics.push('"pause times" 0');
463    ytics.push('"max deopt size: ' + (max_deopt_size / 1024).toFixed(1) +
464               ' kB" ' + kDeoptRow);
465    output("set ytics out nomirror (" + ytics.join(', ') + ")");
466
467    // Plot timeline.
468    for (var name in TimerEvents) {
469      var event = TimerEvents[name];
470      var ranges = MergeRanges(event.ranges);
471      for (var i = 0; i < ranges.length; i++) {
472        DrawBar(event.index, event.color,
473                ranges[i].start, ranges[i].end,
474                kTimerEventWidth);
475      }
476    }
477
478    // Plot code kind gathered from ticks.
479    for (var name in CodeKinds) {
480      var code_kind = CodeKinds[name];
481      var offset = kY1Offset - 1;
482      // Top most frame.
483      var row = MergeRanges(TicksToRanges(code_kind.in_execution));
484      for (var j = 0; j < row.length; j++) {
485        DrawBar(offset, code_kind.color,
486                row[j].start, row[j].end, kExecutionFrameWidth);
487      }
488      offset = offset - 2 * kExecutionFrameWidth - kGapWidth;
489      // Javascript frames.
490      for (var i = 0; i < kStackFrames; i++) {
491        offset = offset - 2 * kStackFrameWidth - kGapWidth;
492        row = MergeRanges(TicksToRanges(code_kind.stack_frames[i]));
493        for (var j = 0; j < row.length; j++) {
494          DrawBar(offset, code_kind.color,
495                  row[j].start, row[j].end, kStackFrameWidth);
496        }
497      }
498    }
499
500    // Add labels as legend for code kind colors.
501    var padding = kCodeKindLabelPadding * (range_end - range_start) / kResX;
502    var label_x = range_start;
503    var label_y = kY1Offset;
504    for (var name in CodeKinds) {
505      label_x += padding;
506      output("set label \"" + name + "\" at " + label_x + "," + label_y +
507             " textcolor rgb \"" + CodeKinds[name].color + "\"" +
508             " font \"Helvetica,9'\"");
509      obj_index++;
510    }
511
512    if (execution_pauses.length == 0) {
513      // Force plot and return without plotting execution pause impulses.
514      output("plot 1/0");
515      return;
516    }
517
518    // Label the longest pauses.
519    execution_pauses =
520        RestrictRangesTo(execution_pauses, range_start, range_end);
521    execution_pauses.sort(
522        function(a, b) { return b.duration() - a.duration(); });
523
524    var max_pause_time = execution_pauses.length > 0
525        ? execution_pauses[0].duration() : 0;
526    padding = kPauseLabelPadding * (range_end - range_start) / kResX;
527    var y_scale = kY1Offset / max_pause_time / 2;
528    for (var i = 0; i < execution_pauses.length && i < kNumPauseLabels; i++) {
529      var pause = execution_pauses[i];
530      var label_content = (pause.duration() | 0) + " ms";
531      var label_x = pause.end + padding;
532      var label_y = Math.max(1, (pause.duration() * y_scale));
533      output("set label \"" + label_content + "\" at " +
534             label_x + "," + label_y + " font \"Helvetica,7'\"");
535      obj_index++;
536    }
537
538    // Scale second Y-axis appropriately.
539    var y2range = max_pause_time * num_timer_event / kY1Offset * 2;
540    output("set y2range [0:" + y2range + "]");
541    // Plot graph with impulses as data set.
542    output("plot '-' using 1:2 axes x1y2 with impulses ls 1");
543    for (var i = 0; i < execution_pauses.length; i++) {
544      var pause = execution_pauses[i];
545      output(pause.end + " " + pause.duration());
546      obj_index++;
547    }
548    output("e");
549    return obj_index;
550  };
551}
552