OLD | NEW |
| (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", [-3]), | |
108 'reg.exp. ': new CodeKind("#0000FF", [-2]), | |
109 'runtime ': new CodeKind("#000000", [-1]), | |
110 'full code': new CodeKind("#DD0000", [0]), | |
111 'opt code ': new CodeKind("#00EE00", [1]), | |
112 'code stub': new CodeKind("#FF00FF", [2]), | |
113 'built-in ': new CodeKind("#AA00AA", [3]), | |
114 'inl.cache': new CodeKind("#4444AA", [4, 5, 6, 7, 8, 9, 10, 11, 12, 13]), | |
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 = -3; // 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(); | |
OLD | NEW |