From 72db2287c3cfe22b7ec82c471d345de85e7a57a2 Mon Sep 17 00:00:00 2001 From: "yangguo@chromium.org" Date: Thu, 22 Nov 2012 13:04:11 +0000 Subject: [PATCH] Add parallel recompilation time to histogram and plot execution pause times. BUG= Review URL: https://chromiumcodereview.appspot.com/11412125 git-svn-id: http://v8.googlecode.com/svn/branches/bleeding_edge@13036 ce2b1a6d-e550-0410-aec6-3dcde31c8c00 --- src/api.cc | 2 + src/compiler.cc | 16 +- src/counters.cc | 8 +- src/flag-definitions.h | 1 + src/heap.cc | 14 +- src/log-utils.cc | 3 +- src/log.cc | 27 +++- src/log.h | 27 ++++ src/optimizing-compiler-thread.cc | 2 + src/profile-generator-inl.h | 2 +- src/v8-counters.h | 1 - src/v8globals.h | 2 +- src/vm-state-inl.h | 4 +- tools/plot-timer-events | 39 +++++ tools/plot-timer-events.js | 332 ++++++++++++++++++++++++++++++++++++++ tools/tickprocessor.js | 2 +- 16 files changed, 463 insertions(+), 19 deletions(-) create mode 100755 tools/plot-timer-events create mode 100644 tools/plot-timer-events.js diff --git a/src/api.cc b/src/api.cc index ae5a8bd..ca38dd9 100644 --- a/src/api.cc +++ b/src/api.cc @@ -1681,6 +1681,8 @@ Local Script::Run() { ON_BAILOUT(isolate, "v8::Script::Run()", return Local()); LOG_API(isolate, "Script::Run"); ENTER_V8(isolate); + i::Logger::TimerEventScope timer_scope( + isolate->logger(), i::Logger::TimerEventScope::v8_execute); i::Object* raw_result = NULL; { i::HandleScope scope(isolate); diff --git a/src/compiler.cc b/src/compiler.cc index 1ff92f1..0c6e1a9 100644 --- a/src/compiler.cc +++ b/src/compiler.cc @@ -396,7 +396,10 @@ static bool GenerateCode(CompilationInfo* info) { bool is_optimizing = V8::UseCrankshaft() && !info->IsCompilingForDebugging() && info->IsOptimizing(); + Logger* logger = info->isolate()->logger(); if (is_optimizing) { + Logger::TimerEventScope timer( + logger, Logger::TimerEventScope::v8_recompile_synchronous); return MakeCrankshaftCode(info); } else { if (info->IsOptimizing()) { @@ -404,6 +407,8 @@ static bool GenerateCode(CompilationInfo* info) { // BASE or NONOPT. info->DisableOptimization(); } + Logger::TimerEventScope timer( + logger, Logger::TimerEventScope::v8_compile_full_code); return FullCodeGenerator::MakeCode(info); } } @@ -852,6 +857,11 @@ void Compiler::RecompileParallel(Handle closure) { ASSERT(closure->IsMarkedForParallelRecompilation()); Isolate* isolate = closure->GetIsolate(); + // Here we prepare compile data for the parallel recompilation thread, but + // this still happens synchronously and interrupts execution. + Logger::TimerEventScope timer( + isolate->logger(), Logger::TimerEventScope::v8_recompile_synchronous); + if (!isolate->optimizing_compiler_thread()->IsQueueAvailable()) { if (FLAG_trace_parallel_recompilation) { PrintF(" ** Compilation queue, will retry opting on next run.\n"); @@ -860,7 +870,7 @@ void Compiler::RecompileParallel(Handle closure) { } SmartPointer info(new CompilationInfoWithZone(closure)); - VMState state(isolate, PARALLEL_COMPILER_PROLOGUE); + VMState state(isolate, PARALLEL_COMPILER); PostponeInterruptsScope postpone(isolate); Handle shared = info->shared_info(); @@ -908,6 +918,10 @@ void Compiler::RecompileParallel(Handle closure) { void Compiler::InstallOptimizedCode(OptimizingCompiler* optimizing_compiler) { SmartPointer info(optimizing_compiler->info()); + Isolate* isolate = info->isolate(); + VMState state(isolate, PARALLEL_COMPILER); + Logger::TimerEventScope timer( + isolate->logger(), Logger::TimerEventScope::v8_recompile_synchronous); // If crankshaft succeeded, install the optimized code else install // the unoptimized code. OptimizingCompiler::Status status = optimizing_compiler->last_status(); diff --git a/src/counters.cc b/src/counters.cc index 811c0aa..db8a123 100644 --- a/src/counters.cc +++ b/src/counters.cc @@ -77,7 +77,7 @@ void* Histogram::CreateHistogram() const { // Start the timer. void HistogramTimer::Start() { - if (histogram_.Enabled()) { + if (histogram_.Enabled() || FLAG_log_timer_events) { stop_time_ = 0; start_time_ = OS::Ticks(); } @@ -87,11 +87,15 @@ void HistogramTimer::Start() { void HistogramTimer::Stop() { if (histogram_.Enabled()) { stop_time_ = OS::Ticks(); - // Compute the delta between start and stop, in milliseconds. int milliseconds = static_cast(stop_time_ - start_time_) / 1000; histogram_.AddSample(milliseconds); } + if (FLAG_log_timer_events) { + stop_time_ = OS::Ticks(); + Isolate::Current()->logger()->TimerEvent( + histogram_.name_, start_time_, stop_time_); + } } } } // namespace v8::internal diff --git a/src/flag-definitions.h b/src/flag-definitions.h index 0b1e615..4a08eff 100644 --- a/src/flag-definitions.h +++ b/src/flag-definitions.h @@ -667,6 +667,7 @@ DEFINE_string(logfile, "v8.log", "Specify the name of the log file.") DEFINE_bool(ll_prof, false, "Enable low-level linux profiler.") DEFINE_string(gc_fake_mmap, "/tmp/__v8_gc__", "Specify the name of the file for fake gc mmap used in ll_prof") +DEFINE_bool(log_timer_events, false, "Log histogram timer events.") // // Disassembler only flags diff --git a/src/heap.cc b/src/heap.cc index 75a73a1..48aacec 100644 --- a/src/heap.cc +++ b/src/heap.cc @@ -644,13 +644,13 @@ bool Heap::CollectGarbage(AllocationSpace space, // Tell the tracer which collector we've selected. tracer.set_collector(collector); - HistogramTimer* rate = (collector == SCAVENGER) - ? isolate_->counters()->gc_scavenger() - : isolate_->counters()->gc_compactor(); - rate->Start(); - next_gc_likely_to_collect_more = - PerformGarbageCollection(collector, &tracer); - rate->Stop(); + { + HistogramTimerScope histogram_timer_scope( + (collector == SCAVENGER) ? isolate_->counters()->gc_scavenger() + : isolate_->counters()->gc_compactor()); + next_gc_likely_to_collect_more = + PerformGarbageCollection(collector, &tracer); + } ASSERT(collector == SCAVENGER || incremental_marking()->IsStopped()); diff --git a/src/log-utils.cc b/src/log-utils.cc index 930b4ba..7ae96db 100644 --- a/src/log-utils.cc +++ b/src/log-utils.cc @@ -80,7 +80,8 @@ void Log::Initialize() { bool open_log_file = FLAG_log || FLAG_log_runtime || FLAG_log_api || FLAG_log_code || FLAG_log_gc || FLAG_log_handles || FLAG_log_suspect - || FLAG_log_regexp || FLAG_log_state_changes || FLAG_ll_prof; + || FLAG_log_regexp || FLAG_log_state_changes || FLAG_ll_prof + || FLAG_log_timer_events; // If we're logging anything, we need to open the log file. if (open_log_file) { diff --git a/src/log.cc b/src/log.cc index b049ffe..92b8054 100644 --- a/src/log.cc +++ b/src/log.cc @@ -531,7 +531,8 @@ Logger::Logger() prev_sp_(NULL), prev_function_(NULL), prev_to_(NULL), - prev_code_(NULL) { + prev_code_(NULL), + epoch_(0) { } @@ -704,6 +705,25 @@ void Logger::SharedLibraryEvent(const wchar_t* library_path, } +void Logger::TimerEvent(const char* name, int64_t start, int64_t end) { + ASSERT(FLAG_log_timer_events); + LogMessageBuilder msg(this); + int since_epoch = static_cast(start - epoch_); + int pause_time = static_cast(end - start); + msg.Append("timer-event,\"%s\",%ld,%ld\n", name, since_epoch, pause_time); + msg.WriteToLogFile(); +} + + +const char* Logger::TimerEventScope::v8_recompile_synchronous = + "V8.RecompileSynchronous"; +const char* Logger::TimerEventScope::v8_recompile_parallel = + "V8.RecompileParallel"; +const char* Logger::TimerEventScope::v8_compile_full_code = + "V8.CompileFullCode"; +const char* Logger::TimerEventScope::v8_execute = "V8.Execute"; + + void Logger::LogRegExpSource(Handle regexp) { // Prints "/" + re.source + "/" + // (re.global?"g":"") + (re.ignorecase?"i":"") + (re.multiline?"m":"") @@ -1727,7 +1747,8 @@ bool Logger::SetUp() { bool start_logging = FLAG_log || FLAG_log_runtime || FLAG_log_api || FLAG_log_code || FLAG_log_gc || FLAG_log_handles || FLAG_log_suspect - || FLAG_log_regexp || FLAG_log_state_changes || FLAG_ll_prof; + || FLAG_log_regexp || FLAG_log_state_changes || FLAG_ll_prof + || FLAG_log_timer_events; if (start_logging) { logging_nesting_ = 1; @@ -1745,6 +1766,8 @@ bool Logger::SetUp() { } } + if (FLAG_log_timer_events) epoch_ = OS::Ticks(); + return true; } diff --git a/src/log.h b/src/log.h index 33f359a..a1ebd79 100644 --- a/src/log.h +++ b/src/log.h @@ -274,6 +274,31 @@ class Logger { void SharedLibraryEvent(const wchar_t* library_path, uintptr_t start, uintptr_t end); + void TimerEvent(const char* name, int64_t start, int64_t end); + + class TimerEventScope { + public: + TimerEventScope(Logger* logger, const char* name) + : logger_(logger), name_(name), start_(0) { + if (FLAG_log_timer_events) start_ = OS::Ticks(); + } + + ~TimerEventScope() { + if (FLAG_log_timer_events) { + logger_->TimerEvent(name_, start_, OS::Ticks()); + } + } + + static const char* v8_recompile_synchronous; + static const char* v8_recompile_parallel; + static const char* v8_compile_full_code; + static const char* v8_execute; + + private: + Logger* logger_; + const char* name_; + int64_t start_; + }; // ==== Events logged by --log-regexp ==== // Regexp compilation and execution events. @@ -449,6 +474,8 @@ class Logger { // Logger::FunctionCreateEvent(...) Address prev_code_; + int64_t epoch_; + friend class CpuProfiler; }; diff --git a/src/optimizing-compiler-thread.cc b/src/optimizing-compiler-thread.cc index 48ee12c..d93f671 100644 --- a/src/optimizing-compiler-thread.cc +++ b/src/optimizing-compiler-thread.cc @@ -48,6 +48,8 @@ void OptimizingCompilerThread::Run() { while (true) { input_queue_semaphore_->Wait(); + Logger::TimerEventScope timer( + isolate_->logger(), Logger::TimerEventScope::v8_recompile_parallel); if (Acquire_Load(&stop_thread_)) { stop_semaphore_->Signal(); if (FLAG_trace_parallel_recompilation) { diff --git a/src/profile-generator-inl.h b/src/profile-generator-inl.h index 02e146f..e4f32a7 100644 --- a/src/profile-generator-inl.h +++ b/src/profile-generator-inl.h @@ -84,7 +84,7 @@ CodeEntry* ProfileGenerator::EntryForVMState(StateTag tag) { return gc_entry_; case JS: case COMPILER: - case PARALLEL_COMPILER_PROLOGUE: + case PARALLEL_COMPILER: // DOM events handlers are reported as OTHER / EXTERNAL entries. // To avoid confusing people, let's put all these entries into // one bucket. diff --git a/src/v8-counters.h b/src/v8-counters.h index fad3454..ef43179 100644 --- a/src/v8-counters.h +++ b/src/v8-counters.h @@ -50,7 +50,6 @@ namespace internal { HT(compile_eval, V8.CompileEval) \ HT(compile_lazy, V8.CompileLazy) - #define HISTOGRAM_PERCENTAGE_LIST(HP) \ HP(external_fragmentation_total, \ V8.MemoryExternalFragmentationTotal) \ diff --git a/src/v8globals.h b/src/v8globals.h index 0e71a93..ef857d1 100644 --- a/src/v8globals.h +++ b/src/v8globals.h @@ -355,7 +355,7 @@ struct AccessorDescriptor { V(JS) \ V(GC) \ V(COMPILER) \ - V(PARALLEL_COMPILER_PROLOGUE) \ + V(PARALLEL_COMPILER) \ V(OTHER) \ V(EXTERNAL) diff --git a/src/vm-state-inl.h b/src/vm-state-inl.h index 384940d..97febd0 100644 --- a/src/vm-state-inl.h +++ b/src/vm-state-inl.h @@ -47,8 +47,8 @@ inline const char* StateToString(StateTag state) { return "GC"; case COMPILER: return "COMPILER"; - case PARALLEL_COMPILER_PROLOGUE: - return "PARALLEL_COMPILER_PROLOGUE"; + case PARALLEL_COMPILER: + return "PARALLEL_COMPILER"; case OTHER: return "OTHER"; case EXTERNAL: diff --git a/tools/plot-timer-events b/tools/plot-timer-events new file mode 100755 index 0000000..1db2c31 --- /dev/null +++ b/tools/plot-timer-events @@ -0,0 +1,39 @@ +#!/bin/sh + +# find the name of the log file to process, it must not start with a dash. +log_file="v8.log" +for arg in "$@" +do + if ! expr "X${arg}" : "^X-" > /dev/null; then + log_file=${arg} + fi +done + +tools_path=`cd $(dirname "$0");pwd` +if [ ! "$D8_PATH" ]; then + d8_public=`which d8` + if [ -x "$d8_public" ]; then D8_PATH=$(dirname "$d8_public"); fi +fi +[ -n "$D8_PATH" ] || D8_PATH=$tools_path/.. +d8_exec=$D8_PATH/d8 + +if [ ! -x "$d8_exec" ]; then + D8_PATH=`pwd`/out/native + d8_exec=$D8_PATH/d8 +fi + +if [ ! -x "$d8_exec" ]; then + d8_exec=`grep -m 1 -o '".*/d8"' $log_file | sed 's/"//g'` +fi + +if [ ! -x "$d8_exec" ]; then + echo "d8 shell not found in $D8_PATH" + echo "To build, execute 'make native' from the V8 directory" + exit 1 +fi + +# nm spits out 'no symbols found' messages to stderr. +cat $log_file | $d8_exec $tools_path/csvparser.js \ + $tools_path/logreader.js $tools_path/plot-timer-events.js \ + 2>/dev/null | gnuplot > timer-events.png + diff --git a/tools/plot-timer-events.js b/tools/plot-timer-events.js new file mode 100644 index 0000000..8ef0b8e --- /dev/null +++ b/tools/plot-timer-events.js @@ -0,0 +1,332 @@ +// Copyright 2012 the V8 project authors. All rights reserved. +// Redistribution and use in source and binary forms, with or without +// modification, are permitted provided that the following conditions are +// met: +// +// * Redistributions of source code must retain the above copyright +// notice, this list of conditions and the following disclaimer. +// * Redistributions in binary form must reproduce the above +// copyright notice, this list of conditions and the following +// disclaimer in the documentation and/or other materials provided +// with the distribution. +// * Neither the name of Google Inc. nor the names of its +// contributors may be used to endorse or promote products derived +// from this software without specific prior written permission. +// +// THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS +// "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT +// LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR +// A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT +// OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, +// SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT +// LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, +// DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY +// THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT +// (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE +// OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE. + +var kExecutionName = 'V8.Execute'; + +var TimerEvents = { + 'V8.Execute': + { ranges: [], color: "#444444", pause: false, index: 1 }, + 'V8.CompileFullCode': + { ranges: [], color: "#CC0000", pause: true, index: 2 }, + 'V8.RecompileSynchronous': + { ranges: [], color: "#CC0044", pause: true, index: 3 }, + 'V8.RecompileParallel': + { ranges: [], color: "#CC4499", pause: false, index: 4 }, + 'V8.CompileEval': + { ranges: [], color: "#CC4400", pause: true, index: 5 }, + 'V8.Parse': + { ranges: [], color: "#00CC00", pause: true, index: 6 }, + 'V8.PreParse': + { ranges: [], color: "#44CC00", pause: true, index: 7 }, + 'V8.ParseLazy': + { ranges: [], color: "#00CC44", pause: true, index: 8 }, + 'V8.GCScavenger': + { ranges: [], color: "#0044CC", pause: true, index: 9 }, + 'V8.GCCompactor': + { ranges: [], color: "#4444CC", pause: true, index: 10 }, + 'V8.GCContext': + { ranges: [], color: "#4400CC", pause: true, index: 11 }, +} + +var kNumRows = 11; +var kBarWidth = 0.33; +var kPauseTolerance = 0.05; // Milliseconds. +var kY1Offset = 3; +var kY2Factor = 5; +var kResX = 1600; +var kResY = 400; +var kLabelPadding = 5; +var kNumPauseLabels = 7; + +var kOverrideRangeStart = undefined; +var kOverrideRangeEnd = undefined; + +var xrange_start = Infinity; +var xrange_end = 0; +var obj_index = 0; +var execution_pauses = []; + + +function Range(start, end) { + // Everthing from here are in milliseconds. + this.start = start; + this.end = end; +} + + +Range.prototype.duration = function() { return this.end - this.start; } + + +function ProcessTimerEvent(name, start, length) { + var event = TimerEvents[name]; + if (event === undefined) return; + start /= 1000; // Convert to milliseconds. + length /= 1000; + var end = start + length; + event.ranges.push(new Range(start, end)); + if (name == kExecutionName) { + if (start < xrange_start) xrange_start = start; + if (end > xrange_end) xrange_end = end; + } +} + + +function CollectData() { + // Collect data from log. + var logreader = new LogReader( + { 'timer-event' : { parsers: [null, parseInt, parseInt], + processor: ProcessTimerEvent + } }); + + var line; + while (line = readline()) { + logreader.processLogLine(line); + } + + // Collect execution pauses. + for (name in TimerEvents) { + var event = TimerEvents[name]; + if (!event.pause) continue; + var ranges = event.ranges; + // Add ranges of this event to the pause list. + for (var j = 0; j < ranges.length; j++) { + execution_pauses.push(ranges[j]); + } + } +} + + +function drawBar(row, color, start, end) { + obj_index++; + command = "set object " + obj_index + " rect"; + command += " from " + start + ", " + (row - kBarWidth + kY1Offset); + command += " to " + end + ", " + (row + kBarWidth + kY1Offset); + command += " fc rgb \"" + color + "\""; + print(command); +} + + +function MergeRanges(ranges, merge_tolerance) { + ranges.sort(function(a, b) { return a.start - b.start; }); + var result = []; + var j = 0; + for (var i = 0; i < ranges.length; i = j) { + var merge_start = ranges[i].start; + if (merge_start > xrange_end) break; // Out of plot range. + var merge_end = ranges[i].end; + for (j = i + 1; j < ranges.length; j++) { + var next_range = ranges[j]; + // Don't merge ranges if there is no overlap (including merge tolerance). + if (next_range.start >= merge_end + kPauseTolerance) break; + // Merge ranges. + if (next_range.end > merge_end) { // Extend range end. + merge_end = next_range.end; + } + } + if (merge_end < xrange_start) continue; // Out of plot range. + result.push(new Range(merge_start, merge_end)); + } + return result; +} + + +function ExcludeRanges(include, exclude) { + // We assume that both input lists are sorted and merged with MergeRanges. + var result = []; + var exclude_index = 0; + var include_index = 0; + var include_start, include_end, exclude_start, exclude_end; + + function NextInclude() { + if (include_index >= include.length) return false; + include_start = include[include_index].start; + include_end = include[include_index].end; + include_index++; + return true; + } + + function NextExclude() { + if (exclude_index >= exclude.length) { + // No more exclude, finish by repeating case (2). + exclude_start = Infinity; + exclude_end = Infinity; + return false; + } + exclude_start = exclude[exclude_index].start; + exclude_end = exclude[exclude_index].end; + exclude_index++; + return true; + } + + if (!NextInclude() || !NextExclude()) return include; + + while (true) { + if (exclude_end <= include_start) { + // (1) Exclude and include do not overlap. + // Include ##### + // Exclude ## + NextExclude(); + } else if (include_end <= exclude_start) { + // (2) Exclude and include do not overlap. + // Include ##### + // Exclude ### + result.push(new Range(include_start, include_end)); + if (!NextInclude()) break; + } else if (exclude_start <= include_start && + exclude_end < include_end && + include_start < exclude_end) { + // (3) Exclude overlaps with begin of include. + // Include ####### + // Exclude ##### + // Result #### + include_start = exclude_end; + NextExclude(); + } else if (include_start < exclude_start && + include_end <= exclude_end && + exclude_start < include_end) { + // (4) Exclude overlaps with end of include. + // Include ####### + // Exclude ##### + // Result #### + result.push(new Range(include_start, exclude_start)); + if (!NextInclude()) break; + } else if (exclude_start > include_start && exclude_end < include_end) { + // (5) Exclude splits include into two parts. + // Include ####### + // Exclude ## + // Result ## ### + result.push(new Range(include_start, exclude_start)); + include_start = exclude_end; + NextExclude(); + } else if (exclude_start <= include_start && exclude_end >= include_end) { + // (6) Exclude entirely covers include. + // Include ###### + // Exclude ######### + if (!NextInclude()) break; + } else { + throw new Error("this should not happen!"); + } + } + + return result; +} + + +function GnuplotOutput() { + xrange_start = kOverrideRangeStart ? kOverrideRangeStart : xrange_start; + xrange_end = kOverrideRangeEnd ? kOverrideRangeEnd : xrange_end; + + print("set terminal pngcairo size " + kResX + "," + kResY + + " enhanced font 'Helvetica,10'"); + print("set yrange [0:" + (kNumRows + kY1Offset + 1) + "]"); + print("set xlabel \"execution time in ms\""); + print("set xrange [" + xrange_start + ":" + xrange_end + "]"); + print("set style fill pattern 2 bo 1"); + print("set style rect fs solid 1 noborder"); + print("set style line 1 lt 1 lw 1 lc rgb \"#000000\""); + print("set xtics out nomirror"); + print("unset key"); + + // Name Y-axis. + var ytics = []; + for (name in TimerEvents) { + var index = TimerEvents[name].index; + ytics.push('"' + name + '"' + ' ' + (index + kY1Offset)); + } + print("set ytics out nomirror (" + ytics.join(', ') + ")"); + + // Smallest visible gap given our resolution. + // We remove superfluous objects to go easy on Gnuplot. + var tolerance = (xrange_end - xrange_start) / kResX / 2; + + // Sort, merge and remove invisible gaps for each time row. + for (var name in TimerEvents) { + var event = TimerEvents[name]; + event.ranges = MergeRanges(event.ranges, tolerance); + } + + // Knock out execution pauses. + var execution_event = TimerEvents[kExecutionName]; + var exclude_ranges = MergeRanges(execution_pauses, tolerance); + execution_event.ranges = ExcludeRanges(execution_event.ranges, + exclude_ranges); + execution_event.ranges = MergeRanges(execution_event.ranges, tolerance); + + // Plot timeline. + for (var name in TimerEvents) { + var event = TimerEvents[name]; + var ranges = event.ranges; + for (var i = 0; i < ranges.length; i++) { + drawBar(event.index, event.color, ranges[i].start, ranges[i].end); + } + } + + if (execution_pauses.length == 0) { + // Force plot and return without plotting execution pause impulses. + print("plot 1/0"); + return; + } + + // Plot execution pauses as impulses. This may be better resolved + // due to possibly smaller merge tolerance. + if (tolerance > kPauseTolerance) { + execution_pauses = MergeRanges(execution_pauses, kPauseTolerance); + } else { + execution_pauses = exclude_ranges; + } + + // Label the longest pauses. + execution_pauses.sort( + function(a, b) { return b.duration() - a.duration(); }); + + var max_pause_time = execution_pauses[0].duration(); + var padding = kLabelPadding * (xrange_end - xrange_start) / kResX; + var y_scale = kY1Offset / max_pause_time; + for (var i = 0; i < execution_pauses.length && i < kNumPauseLabels; i++) { + var pause = execution_pauses[i]; + var label_content = (pause.duration() | 0) + " ms"; + var label_x = pause.end + padding; + var label_y = Math.max(1, (pause.duration() * y_scale)); + print("set label \"" + label_content + "\" at " + + label_x + "," + label_y + " font \"Helvetica,7'\""); + } + + // Scale second Y-axis appropriately. + print("set y2range [0:" + (max_pause_time * kY2Factor) + "]"); + + // Plot graph with impulses as data set. + print("plot '-' using 1:2 axes x1y2 with impulses ls 1"); + for (var i = 0; i < execution_pauses.length; i++) { + var pause = execution_pauses[i]; + print(pause.end + " " + pause.duration()); + } + print("e"); +} + + +CollectData(); +GnuplotOutput(); diff --git a/tools/tickprocessor.js b/tools/tickprocessor.js index f6e315d..78f4cee 100644 --- a/tools/tickprocessor.js +++ b/tools/tickprocessor.js @@ -231,7 +231,7 @@ TickProcessor.VmStates = { JS: 0, GC: 1, COMPILER: 2, - PARALLEL_COMPILER_PROLOGUE: 3, + PARALLEL_COMPILER: 3, OTHER: 4, EXTERNAL: 5 }; -- 2.7.4