• 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.ParseMicroSeconds':
110        new TimerEvent("parse", "#00CC00",  true, 0),
111      'V8.PreParseMicroSeconds':
112        new TimerEvent("preparse", "#44CC00",  true, 0),
113      'V8.ParseLazyMicroSeconds':
114        new TimerEvent("lazy parse", "#00CC44",  true, 0),
115      'V8.GCScavenger':
116        new TimerEvent("gc scavenge", "#0044CC",  true, 0),
117      'V8.GCCompactor':
118        new TimerEvent("gc compaction", "#4444CC",  true, 0),
119      'V8.GCContext':
120        new TimerEvent("gc context", "#4400CC",  true, 0),
121  };
122
123  var CodeKinds = {
124      'external ': new CodeKind("#3399FF", [-2]),
125      'runtime  ': new CodeKind("#000000", [-1]),
126      'full code': new CodeKind("#DD0000", [0]),
127      'opt code ': new CodeKind("#00EE00", [1]),
128      'code stub': new CodeKind("#FF00FF", [2]),
129      'built-in ': new CodeKind("#AA00AA", [3]),
130      'inl.cache': new CodeKind("#4444AA",
131                                [4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14]),
132      'reg.exp. ': new CodeKind("#0000FF", [15]),
133  };
134
135  var code_map = new CodeMap();
136  var execution_pauses = [];
137  var deopts = [];
138  var gettime = [];
139  var event_stack = [];
140  var last_time_stamp = [];
141  for (var i = 0; i < kNumThreads; i++) {
142    event_stack[i] = [];
143    last_time_stamp[i] = -1;
144  }
145
146  var range_start = undefined;
147  var range_end = undefined;
148  var obj_index = 0;
149  var pause_tolerance = 0.005;  // Milliseconds.
150  var distortion = 0;
151
152  // Utility functions.
153  function assert(something, message) {
154    if (!something) {
155      var error = new Error(message);
156      error_output(error.stack);
157    }
158  }
159
160  function FindCodeKind(kind) {
161    for (name in CodeKinds) {
162      if (CodeKinds[name].kinds.indexOf(kind) >= 0) {
163        return CodeKinds[name];
164      }
165    }
166  }
167
168  function TicksToRanges(ticks) {
169    var ranges = [];
170    for (var i = 0; i < ticks.length; i++) {
171      var tick = ticks[i].tick;
172      ranges.push(
173          new Range(tick - kTickHalfDuration, tick + kTickHalfDuration));
174    }
175    return ranges;
176  }
177
178  function MergeRanges(ranges) {
179    ranges.sort(function(a, b) { return a.start - b.start; });
180    var result = [];
181    var j = 0;
182    for (var i = 0; i < ranges.length; i = j) {
183      var merge_start = ranges[i].start;
184      if (merge_start > range_end) break;  // Out of plot range.
185      var merge_end = ranges[i].end;
186      for (j = i + 1; j < ranges.length; j++) {
187        var next_range = ranges[j];
188        // Don't merge ranges if there is no overlap (incl. merge tolerance).
189        if (next_range.start > merge_end + pause_tolerance) break;
190        // Merge ranges.
191        if (next_range.end > merge_end) {  // Extend range end.
192          merge_end = next_range.end;
193        }
194      }
195      if (merge_end < range_start) continue;  // Out of plot range.
196      if (merge_end < merge_start) continue;  // Not an actual range.
197      result.push(new Range(merge_start, merge_end));
198    }
199    return result;
200  }
201
202  function RestrictRangesTo(ranges, start, end) {
203    var result = [];
204    for (var i = 0; i < ranges.length; i++) {
205      if (ranges[i].start <= end && ranges[i].end >= start) {
206        result.push(new Range(Math.max(ranges[i].start, start),
207                              Math.min(ranges[i].end, end)));
208      }
209    }
210    return result;
211  }
212
213  // Public methods.
214  this.collectData = function(input, distortion_per_entry) {
215
216    var last_timestamp = 0;
217
218    // Parse functions.
219    var parseTimeStamp = function(timestamp) {
220      int_timestamp = parseInt(timestamp);
221      assert(int_timestamp >= last_timestamp, "Inconsistent timestamps.");
222      last_timestamp = int_timestamp;
223      distortion += distortion_per_entry;
224      return int_timestamp / 1000 - distortion;
225    }
226
227    var processTimerEventStart = function(name, start) {
228      // Find out the thread id.
229      var new_event = TimerEvents[name];
230      if (new_event === undefined) return;
231      var thread_id = new_event.thread_id;
232
233      start = Math.max(last_time_stamp[thread_id] + kMinRangeLength, start);
234
235      // Last event on this thread is done with the start of this event.
236      var last_event = event_stack[thread_id].top();
237      if (last_event !== undefined) {
238        var new_range = new Range(last_time_stamp[thread_id], start);
239        last_event.ranges.push(new_range);
240      }
241      event_stack[thread_id].push(new_event);
242      last_time_stamp[thread_id] = start;
243    };
244
245    var processTimerEventEnd = function(name, end) {
246      // Find out about the thread_id.
247      var finished_event = TimerEvents[name];
248      var thread_id = finished_event.thread_id;
249      assert(finished_event === event_stack[thread_id].pop(),
250             "inconsistent event stack");
251
252      end = Math.max(last_time_stamp[thread_id] + kMinRangeLength, end);
253
254      var new_range = new Range(last_time_stamp[thread_id], end);
255      finished_event.ranges.push(new_range);
256      last_time_stamp[thread_id] = end;
257    };
258
259    var processCodeCreateEvent = function(type, kind, address, size, name) {
260      var code_entry = new CodeMap.CodeEntry(size, name);
261      code_entry.kind = kind;
262      code_map.addCode(address, code_entry);
263    };
264
265    var processCodeMoveEvent = function(from, to) {
266      code_map.moveCode(from, to);
267    };
268
269    var processCodeDeleteEvent = function(address) {
270      code_map.deleteCode(address);
271    };
272
273    var processCodeDeoptEvent = function(time, size) {
274      deopts.push(new Deopt(time, size));
275    }
276
277    var processCurrentTimeEvent = function(time) {
278      gettime.push(time);
279    }
280
281    var processSharedLibrary = function(name, start, end) {
282      var code_entry = new CodeMap.CodeEntry(end - start, name);
283      code_entry.kind = -3;  // External code kind.
284      for (var i = 0; i < kV8BinarySuffixes.length; i++) {
285        var suffix = kV8BinarySuffixes[i];
286        if (name.indexOf(suffix, name.length - suffix.length) >= 0) {
287          code_entry.kind = -1;  // V8 runtime code kind.
288          break;
289        }
290      }
291      code_map.addLibrary(start, code_entry);
292    };
293
294    var processTickEvent = function(
295        pc, timer, unused_x, unused_y, vmstate, stack) {
296      var tick = new Tick(timer);
297
298      var entry = code_map.findEntry(pc);
299      if (entry) FindCodeKind(entry.kind).in_execution.push(tick);
300
301      for (var i = 0; i < kStackFrames; i++) {
302        if (!stack[i]) break;
303        var entry = code_map.findEntry(stack[i]);
304        if (entry) FindCodeKind(entry.kind).stack_frames[i].push(tick);
305      }
306    };
307    // Collect data from log.
308    var logreader = new LogReader(
309      { 'timer-event-start': { parsers: [null, parseTimeStamp],
310                               processor: processTimerEventStart },
311        'timer-event-end':   { parsers: [null, parseTimeStamp],
312                               processor: processTimerEventEnd },
313        'shared-library': { parsers: [null, parseInt, parseInt],
314                            processor: processSharedLibrary },
315        'code-creation':  { parsers: [null, parseInt, parseInt, parseInt, null],
316                            processor: processCodeCreateEvent },
317        'code-move':      { parsers: [parseInt, parseInt],
318                            processor: processCodeMoveEvent },
319        'code-delete':    { parsers: [parseInt],
320                            processor: processCodeDeleteEvent },
321        'code-deopt':     { parsers: [parseTimeStamp, parseInt],
322                            processor: processCodeDeoptEvent },
323        'current-time':   { parsers: [parseTimeStamp],
324                            processor: processCurrentTimeEvent },
325        'tick':           { parsers: [parseInt, parseTimeStamp,
326                                      null, null, parseInt, 'var-args'],
327                            processor: processTickEvent }
328      });
329
330    var line;
331    while (line = input()) {
332      for (var s of line.split("\n")) logreader.processLogLine(s);
333    }
334
335    // Collect execution pauses.
336    for (name in TimerEvents) {
337      var event = TimerEvents[name];
338      if (!event.pause) continue;
339      var ranges = event.ranges;
340      for (var j = 0; j < ranges.length; j++) execution_pauses.push(ranges[j]);
341    }
342    execution_pauses = MergeRanges(execution_pauses);
343  };
344
345
346  this.findPlotRange = function(
347    range_start_override, range_end_override, result_callback) {
348    var start_found = (range_start_override || range_start_override == 0);
349    var end_found = (range_end_override || range_end_override == 0);
350    range_start = start_found ? range_start_override : Infinity;
351    range_end = end_found ? range_end_override : -Infinity;
352
353    if (!start_found || !end_found) {
354      for (name in TimerEvents) {
355        var ranges = TimerEvents[name].ranges;
356        for (var i = 0; i < ranges.length; i++) {
357          if (ranges[i].start < range_start && !start_found) {
358            range_start = ranges[i].start;
359          }
360          if (ranges[i].end > range_end && !end_found) {
361            range_end = ranges[i].end;
362          }
363        }
364      }
365
366      for (codekind in CodeKinds) {
367        var ticks = CodeKinds[codekind].in_execution;
368        for (var i = 0; i < ticks.length; i++) {
369          if (ticks[i].tick < range_start && !start_found) {
370            range_start = ticks[i].tick;
371          }
372          if (ticks[i].tick > range_end && !end_found) {
373            range_end = ticks[i].tick;
374          }
375        }
376      }
377    }
378    // Set pause tolerance to something appropriate for the plot resolution
379    // to make it easier for gnuplot.
380    pause_tolerance = (range_end - range_start) / kResX / 10;
381
382    if (typeof result_callback === 'function') {
383      result_callback(range_start, range_end);
384    }
385  };
386
387
388  this.assembleOutput = function(output) {
389    output("set yrange [0:" + (num_timer_event + 1) + "]");
390    output("set xlabel \"execution time in ms\"");
391    output("set xrange [" + range_start + ":" + range_end + "]");
392    output("set style fill pattern 2 bo 1");
393    output("set style rect fs solid 1 noborder");
394    output("set style line 1 lt 1 lw 1 lc rgb \"#000000\"");
395    output("set border 15 lw 0.2");  // Draw thin border box.
396    output("set style line 2 lt 1 lw 1 lc rgb \"#9944CC\"");
397    output("set xtics out nomirror");
398    output("unset key");
399
400    function DrawBarBase(color, start, end, top, bottom, transparency) {
401      obj_index++;
402      command = "set object " + obj_index + " rect";
403      command += " from " + start + ", " + top;
404      command += " to " + end + ", " + bottom;
405      command += " fc rgb \"" + color + "\"";
406      if (transparency) {
407        command += " fs transparent solid " + transparency;
408      }
409      output(command);
410    }
411
412    function DrawBar(row, color, start, end, width) {
413      DrawBarBase(color, start, end, row + width, row - width);
414    }
415
416    function DrawHalfBar(row, color, start, end, width) {
417      DrawBarBase(color, start, end, row, row - width);
418    }
419
420    var percentages = {};
421    var total = 0;
422    for (var name in TimerEvents) {
423      var event = TimerEvents[name];
424      var ranges = RestrictRangesTo(event.ranges, range_start, range_end);
425      var sum =
426        ranges.map(function(range) { return range.duration(); })
427            .reduce(function(a, b) { return a + b; }, 0);
428      percentages[name] = (sum / (range_end - range_start) * 100).toFixed(1);
429    }
430
431    // Plot deopts.
432    deopts.sort(function(a, b) { return b.size - a.size; });
433    var max_deopt_size = deopts.length > 0 ? deopts[0].size : Infinity;
434
435    for (var i = 0; i < deopts.length; i++) {
436      var deopt = deopts[i];
437      DrawHalfBar(kDeoptRow, "#9944CC", deopt.time,
438                  deopt.time + 10 * pause_tolerance,
439                  deopt.size / max_deopt_size * kMaxDeoptLength);
440    }
441
442    // Plot current time polls.
443    if (gettime.length > 1) {
444      var start = gettime[0];
445      var end = gettime.pop();
446      DrawBarBase("#0000BB", start, end, kGetTimeHeight, 0, 0.2);
447    }
448
449    // Name Y-axis.
450    var ytics = [];
451    for (name in TimerEvents) {
452      var index = TimerEvents[name].index;
453      var label = TimerEvents[name].label;
454      ytics.push('"' + label + ' (' + percentages[name] + '%%)" ' + index);
455    }
456    ytics.push('"code kind color coding" ' + kY1Offset);
457    ytics.push('"code kind in execution" ' + (kY1Offset - 1));
458    ytics.push('"top ' + kStackFrames + ' js stack frames"' + ' ' +
459               (kY1Offset - 2));
460    ytics.push('"pause times" 0');
461    ytics.push('"max deopt size: ' + (max_deopt_size / 1024).toFixed(1) +
462               ' kB" ' + kDeoptRow);
463    output("set ytics out nomirror (" + ytics.join(', ') + ")");
464
465    // Plot timeline.
466    for (var name in TimerEvents) {
467      var event = TimerEvents[name];
468      var ranges = MergeRanges(event.ranges);
469      for (var i = 0; i < ranges.length; i++) {
470        DrawBar(event.index, event.color,
471                ranges[i].start, ranges[i].end,
472                kTimerEventWidth);
473      }
474    }
475
476    // Plot code kind gathered from ticks.
477    for (var name in CodeKinds) {
478      var code_kind = CodeKinds[name];
479      var offset = kY1Offset - 1;
480      // Top most frame.
481      var row = MergeRanges(TicksToRanges(code_kind.in_execution));
482      for (var j = 0; j < row.length; j++) {
483        DrawBar(offset, code_kind.color,
484                row[j].start, row[j].end, kExecutionFrameWidth);
485      }
486      offset = offset - 2 * kExecutionFrameWidth - kGapWidth;
487      // Javascript frames.
488      for (var i = 0; i < kStackFrames; i++) {
489        offset = offset - 2 * kStackFrameWidth - kGapWidth;
490        row = MergeRanges(TicksToRanges(code_kind.stack_frames[i]));
491        for (var j = 0; j < row.length; j++) {
492          DrawBar(offset, code_kind.color,
493                  row[j].start, row[j].end, kStackFrameWidth);
494        }
495      }
496    }
497
498    // Add labels as legend for code kind colors.
499    var padding = kCodeKindLabelPadding * (range_end - range_start) / kResX;
500    var label_x = range_start;
501    var label_y = kY1Offset;
502    for (var name in CodeKinds) {
503      label_x += padding;
504      output("set label \"" + name + "\" at " + label_x + "," + label_y +
505             " textcolor rgb \"" + CodeKinds[name].color + "\"" +
506             " font \"Helvetica,9'\"");
507      obj_index++;
508    }
509
510    if (execution_pauses.length == 0) {
511      // Force plot and return without plotting execution pause impulses.
512      output("plot 1/0");
513      return;
514    }
515
516    // Label the longest pauses.
517    execution_pauses =
518        RestrictRangesTo(execution_pauses, range_start, range_end);
519    execution_pauses.sort(
520        function(a, b) { return b.duration() - a.duration(); });
521
522    var max_pause_time = execution_pauses.length > 0
523        ? execution_pauses[0].duration() : 0;
524    padding = kPauseLabelPadding * (range_end - range_start) / kResX;
525    var y_scale = kY1Offset / max_pause_time / 2;
526    for (var i = 0; i < execution_pauses.length && i < kNumPauseLabels; i++) {
527      var pause = execution_pauses[i];
528      var label_content = (pause.duration() | 0) + " ms";
529      var label_x = pause.end + padding;
530      var label_y = Math.max(1, (pause.duration() * y_scale));
531      output("set label \"" + label_content + "\" at " +
532             label_x + "," + label_y + " font \"Helvetica,7'\"");
533      obj_index++;
534    }
535
536    // Scale second Y-axis appropriately.
537    var y2range = max_pause_time * num_timer_event / kY1Offset * 2;
538    output("set y2range [0:" + y2range + "]");
539    // Plot graph with impulses as data set.
540    output("plot '-' using 1:2 axes x1y2 with impulses ls 1");
541    for (var i = 0; i < execution_pauses.length; i++) {
542      var pause = execution_pauses[i];
543      output(pause.end + " " + pause.duration());
544      obj_index++;
545    }
546    output("e");
547    return obj_index;
548  };
549}
550