Chromium Code Reviews
chromiumcodereview-hr@appspot.gserviceaccount.com (chromiumcodereview-hr) | Please choose your nickname with Settings | Help | Chromium Project | Gerrit Changes | Sign out
(411)

Side by Side Diff: tools/plot-timer-events.js

Issue 17592002: Add v8.log visualizer page. (Closed) Base URL: https://v8.googlecode.com/svn/branches/bleeding_edge
Patch Set: small changes Created 7 years, 6 months ago
Use n/p to move between diff chunks; N/P to move between comments. Draft comments are only viewable by you.
Jump to:
View unified diff | Download patch | Annotate | Revision Log
« no previous file with comments | « tools/plot-timer-events ('k') | tools/presubmit.py » ('j') | no next file with comments »
Toggle Intra-line Diffs ('i') | Expand Comments ('e') | Collapse Comments ('c') | Show Comments Hide Comments ('s')
OLDNEW
(Empty)
1 // Copyright 2012 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
28 var kV8BinarySuffixes = ["/d8", "/libv8.so"];
29 var kStackFrames = 8;
30
31 var kTimerEventWidth = 0.33;
32 var kExecutionFrameWidth = 0.2;
33 var kStackFrameWidth = 0.1;
34 var kGapWidth = 0.05;
35
36 var kY1Offset = 10;
37
38 var kResX = 1600;
39 var kResY = 600;
40 var kPauseLabelPadding = 5;
41 var kNumPauseLabels = 7;
42 var kTickHalfDuration = 0.5; // Milliseconds
43 var kCodeKindLabelPadding = 100;
44 var kMinRangeLength = 0.0005; // Milliseconds
45
46 var num_timer_event = kY1Offset + 0.5;
47
48 var kNumThreads = 2;
49 var kExecutionThreadId = 0;
50
51 function assert(something, message) {
52 if (!something) {
53 print(new Error(message).stack);
54 }
55 }
56
57 function TimerEvent(color, pause, thread_id) {
58 assert(thread_id >= 0 && thread_id < kNumThreads, "invalid thread id");
59 this.color = color;
60 this.pause = pause;
61 this.ranges = [];
62 this.thread_id = thread_id;
63 this.index = ++num_timer_event;
64 }
65
66
67 var TimerEvents = {
68 'V8.Execute': new TimerEvent("#000000", false, 0),
69 'V8.External': new TimerEvent("#3399FF", false, 0),
70 'V8.CompileFullCode': new TimerEvent("#CC0000", true, 0),
71 'V8.RecompileSynchronous': new TimerEvent("#CC0044", true, 0),
72 'V8.RecompileParallel': new TimerEvent("#CC4499", false, 1),
73 'V8.CompileEval': new TimerEvent("#CC4400", true, 0),
74 'V8.Parse': new TimerEvent("#00CC00", true, 0),
75 'V8.PreParse': new TimerEvent("#44CC00", true, 0),
76 'V8.ParseLazy': new TimerEvent("#00CC44", true, 0),
77 'V8.GCScavenger': new TimerEvent("#0044CC", true, 0),
78 'V8.GCCompactor': new TimerEvent("#4444CC", true, 0),
79 'V8.GCContext': new TimerEvent("#4400CC", true, 0),
80 }
81
82
83 Array.prototype.top = function() {
84 if (this.length == 0) return undefined;
85 return this[this.length - 1];
86 }
87
88 var event_stack = [];
89 var last_time_stamp = [];
90
91 for (var i = 0; i < kNumThreads; i++) {
92 event_stack[i] = [];
93 last_time_stamp[i] = -1;
94 }
95
96
97 function CodeKind(color, kinds) {
98 this.color = color;
99 this.in_execution = [];
100 this.stack_frames = [];
101 for (var i = 0; i < kStackFrames; i++) this.stack_frames.push([]);
102 this.kinds = kinds;
103 }
104
105
106 var CodeKinds = {
107 'external ': new CodeKind("#3399FF", [-2]),
108 'runtime ': new CodeKind("#000000", [-1]),
109 'full code': new CodeKind("#DD0000", [0]),
110 'opt code ': new CodeKind("#00EE00", [1]),
111 'code stub': new CodeKind("#FF00FF", [2]),
112 'built-in ': new CodeKind("#AA00AA", [3]),
113 'inl.cache': new CodeKind("#4444AA", [4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14]),
114 'reg.exp. ': new CodeKind("#0000FF", [15]),
115 }
116
117
118 var xrange_start;
119 var xrange_end;
120 var obj_index = 0;
121 var execution_pauses = [];
122 var code_map = new CodeMap();
123
124 var xrange_start_override = undefined;
125 var xrange_end_override = undefined;
126 var distortion_per_entry = 0.005; // Milliseconds
127 var pause_tolerance = 0.005; // Milliseconds.
128
129 var distortion = 0;
130
131
132 function Range(start, end) {
133 // Everthing from here are in milliseconds.
134 this.start = start;
135 this.end = end;
136 }
137
138
139 function Tick(tick) {
140 this.tick = tick;
141 }
142
143
144 Range.prototype.duration = function() { return this.end - this.start; }
145
146
147 function ProcessTimerEventStart(name, start) {
148 // Find out the thread id.
149 var new_event = TimerEvents[name];
150 if (new_event === undefined) return;
151 var thread_id = new_event.thread_id;
152
153 start = Math.max(last_time_stamp[thread_id] + kMinRangeLength, start);
154
155 // Last event on this thread is done with the start of this event.
156 var last_event = event_stack[thread_id].top();
157 if (last_event !== undefined) {
158 var new_range = new Range(last_time_stamp[thread_id], start);
159 last_event.ranges.push(new_range);
160 }
161 event_stack[thread_id].push(new_event);
162 last_time_stamp[thread_id] = start;
163 }
164
165
166 function ProcessTimerEventEnd(name, end) {
167 // Find out about the thread_id.
168 var finished_event = TimerEvents[name];
169 var thread_id = finished_event.thread_id;
170 assert(finished_event === event_stack[thread_id].pop(),
171 "inconsistent event stack");
172
173 end = Math.max(last_time_stamp[thread_id] + kMinRangeLength, end);
174
175 var new_range = new Range(last_time_stamp[thread_id], end);
176 finished_event.ranges.push(new_range);
177 last_time_stamp[thread_id] = end;
178 }
179
180
181 function ProcessCodeCreateEvent(type, kind, address, size, name) {
182 var code_entry = new CodeMap.CodeEntry(size, name);
183 code_entry.kind = kind;
184 code_map.addCode(address, code_entry);
185 }
186
187
188 function ProcessCodeMoveEvent(from, to) {
189 code_map.moveCode(from, to);
190 }
191
192
193 function ProcessCodeDeleteEvent(address) {
194 code_map.deleteCode(address);
195 }
196
197
198 function ProcessSharedLibrary(name, start, end) {
199 var code_entry = new CodeMap.CodeEntry(end - start, name);
200 code_entry.kind = -2; // External code kind.
201 for (var i = 0; i < kV8BinarySuffixes.length; i++) {
202 var suffix = kV8BinarySuffixes[i];
203 if (name.indexOf(suffix, name.length - suffix.length) >= 0) {
204 code_entry.kind = -1; // V8 runtime code kind.
205 break;
206 }
207 }
208 code_map.addLibrary(start, code_entry);
209 }
210
211
212 function FindCodeKind(kind) {
213 for (name in CodeKinds) {
214 if (CodeKinds[name].kinds.indexOf(kind) >= 0) {
215 return CodeKinds[name];
216 }
217 }
218 }
219
220
221 function ProcessTickEvent(pc, sp, timer, unused_x, unused_y, vmstate, stack) {
222 var tick = new Tick(timer);
223
224 var entry = code_map.findEntry(pc);
225 if (entry) FindCodeKind(entry.kind).in_execution.push(tick);
226
227 for (var i = 0; i < kStackFrames; i++) {
228 if (!stack[i]) break;
229 var entry = code_map.findEntry(stack[i]);
230 if (entry) FindCodeKind(entry.kind).stack_frames[i].push(tick);
231 }
232 }
233
234
235 function FindPlotRange() {
236 var start_found = (xrange_start_override || xrange_start_override == 0);
237 var end_found = (xrange_end_override || xrange_end_override == 0);
238 xrange_start = start_found ? xrange_start_override : Infinity;
239 xrange_end = end_found ? xrange_end_override : -Infinity;
240
241 if (start_found && end_found) return;
242
243 for (name in TimerEvents) {
244 var ranges = TimerEvents[name].ranges;
245 for (var i = 0; i < ranges.length; i++) {
246 if (ranges[i].start < xrange_start && !start_found) {
247 xrange_start = ranges[i].start;
248 }
249 if (ranges[i].end > xrange_end && !end_found) {
250 xrange_end = ranges[i].end;
251 }
252 }
253 }
254
255 for (codekind in CodeKinds) {
256 var ticks = CodeKinds[codekind].in_execution;
257 for (var i = 0; i < ticks.length; i++) {
258 if (ticks[i].tick < xrange_start && !start_found) {
259 xrange_start = ticks[i].tick;
260 }
261 if (ticks[i].tick > xrange_end && !end_found) {
262 xrange_end = ticks[i].tick;
263 }
264 }
265 }
266
267 // Set pause tolerance to something appropriate for the plot resolution
268 // to make it easier for gnuplot.
269 pause_tolerance = (xrange_end - xrange_start) / kResX / 10;
270 }
271
272
273 function parseTimeStamp(timestamp) {
274 distortion += distortion_per_entry;
275 return parseInt(timestamp) / 1000 - distortion;
276 }
277
278
279 function ParseArguments(args) {
280 var processor = new ArgumentsProcessor(args);
281 do {
282 if (!processor.parse()) break;
283 var result = processor.result();
284 var distortion = parseInt(result.distortion);
285 if (isNaN(distortion)) break;
286 // Convert picoseconds to milliseconds.
287 distortion_per_entry = distortion / 1000000;
288 var rangelimits = result.range.split(",");
289 var range_start = parseInt(rangelimits[0]);
290 var range_end = parseInt(rangelimits[1]);
291 xrange_start_override = isNaN(range_start) ? undefined : range_start;
292 xrange_end_override = isNaN(range_end) ? undefined : range_end;
293 return;
294 } while (false);
295 processor.printUsageAndExit();
296 }
297
298
299 function CollectData() {
300 // Collect data from log.
301 var logreader = new LogReader(
302 { 'timer-event-start': { parsers: [null, parseTimeStamp],
303 processor: ProcessTimerEventStart },
304 'timer-event-end': { parsers: [null, parseTimeStamp],
305 processor: ProcessTimerEventEnd },
306 'shared-library': { parsers: [null, parseInt, parseInt],
307 processor: ProcessSharedLibrary },
308 'code-creation': { parsers: [null, parseInt, parseInt, parseInt, null],
309 processor: ProcessCodeCreateEvent },
310 'code-move': { parsers: [parseInt, parseInt],
311 processor: ProcessCodeMoveEvent },
312 'code-delete': { parsers: [parseInt],
313 processor: ProcessCodeDeleteEvent },
314 'tick': { parsers: [parseInt, parseInt, parseTimeStamp,
315 null, null, parseInt, 'var-args'],
316 processor: ProcessTickEvent }
317 });
318
319 var line;
320 while (line = readline()) {
321 logreader.processLogLine(line);
322 }
323
324 // Collect execution pauses.
325 for (name in TimerEvents) {
326 var event = TimerEvents[name];
327 if (!event.pause) continue;
328 var ranges = event.ranges;
329 for (var j = 0; j < ranges.length; j++) execution_pauses.push(ranges[j]);
330 }
331 execution_pauses = MergeRanges(execution_pauses);
332 }
333
334
335 function DrawBar(row, color, start, end, width) {
336 obj_index++;
337 command = "set object " + obj_index + " rect";
338 command += " from " + start + ", " + (row - width);
339 command += " to " + end + ", " + (row + width);
340 command += " fc rgb \"" + color + "\"";
341 print(command);
342 }
343
344
345 function TicksToRanges(ticks) {
346 var ranges = [];
347 for (var i = 0; i < ticks.length; i++) {
348 var tick = ticks[i].tick;
349 ranges.push(new Range(tick - kTickHalfDuration, tick + kTickHalfDuration));
350 }
351 return ranges;
352 }
353
354
355 function MergeRanges(ranges) {
356 ranges.sort(function(a, b) { return a.start - b.start; });
357 var result = [];
358 var j = 0;
359 for (var i = 0; i < ranges.length; i = j) {
360 var merge_start = ranges[i].start;
361 if (merge_start > xrange_end) break; // Out of plot range.
362 var merge_end = ranges[i].end;
363 for (j = i + 1; j < ranges.length; j++) {
364 var next_range = ranges[j];
365 // Don't merge ranges if there is no overlap (including merge tolerance).
366 if (next_range.start > merge_end + pause_tolerance) break;
367 // Merge ranges.
368 if (next_range.end > merge_end) { // Extend range end.
369 merge_end = next_range.end;
370 }
371 }
372 if (merge_end < xrange_start) continue; // Out of plot range.
373 if (merge_end < merge_start) continue; // Not an actual range.
374 result.push(new Range(merge_start, merge_end));
375 }
376 return result;
377 }
378
379
380 function RestrictRangesTo(ranges, start, end) {
381 var result = [];
382 for (var i = 0; i < ranges.length; i++) {
383 if (ranges[i].start <= end && ranges[i].end >= start) {
384 result.push(new Range(Math.max(ranges[i].start, start),
385 Math.min(ranges[i].end, end)));
386 }
387 }
388 return result;
389 }
390
391
392 function GnuplotOutput() {
393 print("set terminal pngcairo size " + kResX + "," + kResY +
394 " enhanced font 'Helvetica,10'");
395 print("set yrange [0:" + (num_timer_event + 1) + "]");
396 print("set xlabel \"execution time in ms\"");
397 print("set xrange [" + xrange_start + ":" + xrange_end + "]");
398 print("set style fill pattern 2 bo 1");
399 print("set style rect fs solid 1 noborder");
400 print("set style line 1 lt 1 lw 1 lc rgb \"#000000\"");
401 print("set xtics out nomirror");
402 print("unset key");
403
404 var percentages = {};
405 var total = 0;
406 for (var name in TimerEvents) {
407 var event = TimerEvents[name];
408 var ranges = RestrictRangesTo(event.ranges, xrange_start, xrange_end);
409 ranges = MergeRanges(ranges);
410 var sum =
411 ranges.map(function(range) { return range.duration(); })
412 .reduce(function(a, b) { return a + b; }, 0);
413 percentages[name] = (sum / (xrange_end - xrange_start) * 100).toFixed(1);
414 }
415
416 // Name Y-axis.
417 var ytics = [];
418 for (name in TimerEvents) {
419 var index = TimerEvents[name].index;
420 ytics.push('"' + name + ' (' + percentages[name] + '%%)" ' + index);
421 }
422 ytics.push('"code kind being executed"' + ' ' + (kY1Offset - 1));
423 ytics.push('"top ' + kStackFrames + ' js stack frames"' + ' ' +
424 (kY1Offset - 2));
425 ytics.push('"pause times" 0');
426 print("set ytics out nomirror (" + ytics.join(', ') + ")");
427
428 // Plot timeline.
429 for (var name in TimerEvents) {
430 var event = TimerEvents[name];
431 var ranges = MergeRanges(event.ranges);
432 for (var i = 0; i < ranges.length; i++) {
433 DrawBar(event.index, event.color,
434 ranges[i].start, ranges[i].end,
435 kTimerEventWidth);
436 }
437 }
438
439 // Plot code kind gathered from ticks.
440 for (var name in CodeKinds) {
441 var code_kind = CodeKinds[name];
442 var offset = kY1Offset - 1;
443 // Top most frame.
444 var row = MergeRanges(TicksToRanges(code_kind.in_execution));
445 for (var j = 0; j < row.length; j++) {
446 DrawBar(offset, code_kind.color,
447 row[j].start, row[j].end, kExecutionFrameWidth);
448 }
449 offset = offset - 2 * kExecutionFrameWidth - kGapWidth;
450 // Javascript frames.
451 for (var i = 0; i < kStackFrames; i++) {
452 offset = offset - 2 * kStackFrameWidth - kGapWidth;
453 row = MergeRanges(TicksToRanges(code_kind.stack_frames[i]));
454 for (var j = 0; j < row.length; j++) {
455 DrawBar(offset, code_kind.color,
456 row[j].start, row[j].end, kStackFrameWidth);
457 }
458 }
459 }
460
461 // Add labels as legend for code kind colors.
462 var padding = kCodeKindLabelPadding * (xrange_end - xrange_start) / kResX;
463 var label_x = xrange_start;
464 var label_y = kY1Offset;
465 for (var name in CodeKinds) {
466 label_x += padding;
467 print("set label \"" + name + "\" at " + label_x + "," + label_y +
468 " textcolor rgb \"" + CodeKinds[name].color + "\"" +
469 " font \"Helvetica,9'\"");
470 }
471
472 if (execution_pauses.length == 0) {
473 // Force plot and return without plotting execution pause impulses.
474 print("plot 1/0");
475 return;
476 }
477
478 // Label the longest pauses.
479 execution_pauses.sort(
480 function(a, b) { return b.duration() - a.duration(); });
481
482 var max_pause_time = execution_pauses[0].duration();
483 padding = kPauseLabelPadding * (xrange_end - xrange_start) / kResX;
484 var y_scale = kY1Offset / max_pause_time / 2;
485 for (var i = 0; i < execution_pauses.length && i < kNumPauseLabels; i++) {
486 var pause = execution_pauses[i];
487 var label_content = (pause.duration() | 0) + " ms";
488 var label_x = pause.end + padding;
489 var label_y = Math.max(1, (pause.duration() * y_scale));
490 print("set label \"" + label_content + "\" at " +
491 label_x + "," + label_y + " font \"Helvetica,7'\"");
492 }
493
494 // Scale second Y-axis appropriately.
495 var y2range = max_pause_time * num_timer_event / kY1Offset * 2;
496 print("set y2range [0:" + y2range + "]");
497 // Plot graph with impulses as data set.
498 print("plot '-' using 1:2 axes x1y2 with impulses ls 1");
499 for (var i = 0; i < execution_pauses.length; i++) {
500 var pause = execution_pauses[i];
501 print(pause.end + " " + pause.duration());
502 }
503 print("e");
504 }
505
506
507 ParseArguments(arguments);
508 CollectData();
509 FindPlotRange();
510 GnuplotOutput();
OLDNEW
« no previous file with comments | « tools/plot-timer-events ('k') | tools/presubmit.py » ('j') | no next file with comments »

Powered by Google App Engine
This is Rietveld 408576698