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