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