From 048b86d697ef1721f23991aa8f6a7b8e70d0c697 Mon Sep 17 00:00:00 2001 From: "yangguo@chromium.org" Date: Mon, 28 Jan 2013 13:55:40 +0000 Subject: [PATCH] Log event start and event end separately when using --log-timer-events. R=haraken@chromium.org BUG= Review URL: https://chromiumcodereview.appspot.com/12040075 git-svn-id: http://v8.googlecode.com/svn/branches/bleeding_edge@13529 ce2b1a6d-e550-0410-aec6-3dcde31c8c00 --- src/counters.cc | 8 +- src/log.cc | 35 ++---- src/log.h | 16 +-- src/vm-state-inl.h | 9 +- tools/plot-timer-events | 17 ++- tools/plot-timer-events.js | 296 +++++++++++++++------------------------------ 6 files changed, 135 insertions(+), 246 deletions(-) diff --git a/src/counters.cc b/src/counters.cc index 6d453d6..7c8265e 100644 --- a/src/counters.cc +++ b/src/counters.cc @@ -77,10 +77,13 @@ void* Histogram::CreateHistogram() const { // Start the timer. void HistogramTimer::Start() { - if (histogram_.Enabled() || FLAG_log_internal_timer_events) { + if (histogram_.Enabled()) { stop_time_ = 0; start_time_ = OS::Ticks(); } + if (FLAG_log_internal_timer_events) { + LOG(Isolate::Current(), TimerEvent(Logger::START, histogram_.name_)); + } } // Stop the timer and record the results. @@ -92,8 +95,7 @@ void HistogramTimer::Stop() { histogram_.AddSample(milliseconds); } if (FLAG_log_internal_timer_events) { - LOG(Isolate::Current(), - TimerEvent(histogram_.name_, start_time_, OS::Ticks())); + LOG(Isolate::Current(), TimerEvent(Logger::END, histogram_.name_)); } } diff --git a/src/log.cc b/src/log.cc index efbb8f7..4a53db4 100644 --- a/src/log.cc +++ b/src/log.cc @@ -633,46 +633,30 @@ void Logger::SharedLibraryEvent(const wchar_t* library_path, } -void Logger::TimerEvent(const char* name, int64_t start, int64_t end) { +void Logger::TimerEvent(StartEnd se, const char* name) { if (!log_->IsEnabled()) return; ASSERT(FLAG_log_internal_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); + int since_epoch = static_cast(OS::Ticks() - epoch_); + const char* format = (se == START) ? "timer-event-start,\"%s\",%ld\n" + : "timer-event-end,\"%s\",%ld\n"; + msg.Append(format, name, since_epoch); msg.WriteToLogFile(); } -void Logger::ExternalSwitch(StateTag old_tag, StateTag new_tag) { - if (old_tag != EXTERNAL && new_tag == EXTERNAL) { - enter_external_ = OS::Ticks(); - } - if (old_tag == EXTERNAL && new_tag != EXTERNAL && enter_external_ != 0) { - TimerEvent("V8.External", enter_external_, OS::Ticks()); - enter_external_ = 0; - } -} - - void Logger::EnterExternal() { - LOGGER->enter_external_ = OS::Ticks(); + LOG(ISOLATE, TimerEvent(START, TimerEventScope::v8_external)); } void Logger::LeaveExternal() { - if (enter_external_ == 0) return; - Logger* logger = LOGGER; - logger->TimerEvent("V8.External", enter_external_, OS::Ticks()); - logger->enter_external_ = 0; + LOG(ISOLATE, TimerEvent(END, TimerEventScope::v8_external)); } -int64_t Logger::enter_external_ = 0; - - -void Logger::TimerEventScope::LogTimerEvent() { - LOG(isolate_, TimerEvent(name_, start_, OS::Ticks())); +void Logger::TimerEventScope::LogTimerEvent(StartEnd se) { + LOG(isolate_, TimerEvent(se, name_)); } @@ -683,6 +667,7 @@ const char* Logger::TimerEventScope::v8_recompile_parallel = const char* Logger::TimerEventScope::v8_compile_full_code = "V8.CompileFullCode"; const char* Logger::TimerEventScope::v8_execute = "V8.Execute"; +const char* Logger::TimerEventScope::v8_external = "V8.External"; void Logger::LogRegExpSource(Handle regexp) { diff --git a/src/log.h b/src/log.h index b5b6817..093906c 100644 --- a/src/log.h +++ b/src/log.h @@ -273,8 +273,9 @@ class Logger { uintptr_t end); // ==== Events logged by --log-timer-events. ==== - void TimerEvent(const char* name, int64_t start, int64_t end); - void ExternalSwitch(StateTag old_tag, StateTag new_tag); + enum StartEnd { START, END }; + + void TimerEvent(StartEnd se, const char* name); static void EnterExternal(); static void LeaveExternal(); @@ -282,25 +283,25 @@ class Logger { class TimerEventScope { public: TimerEventScope(Isolate* isolate, const char* name) - : isolate_(isolate), name_(name), start_(0) { - if (FLAG_log_internal_timer_events) start_ = OS::Ticks(); + : isolate_(isolate), name_(name) { + if (FLAG_log_internal_timer_events) LogTimerEvent(START); } ~TimerEventScope() { - if (FLAG_log_internal_timer_events) LogTimerEvent(); + if (FLAG_log_internal_timer_events) LogTimerEvent(END); } - void LogTimerEvent(); + void LogTimerEvent(StartEnd se); static const char* v8_recompile_synchronous; static const char* v8_recompile_parallel; static const char* v8_compile_full_code; static const char* v8_execute; + static const char* v8_external; private: Isolate* isolate_; const char* name_; - int64_t start_; }; // ==== Events logged by --log-regexp ==== @@ -473,7 +474,6 @@ class Logger { Address prev_code_; int64_t epoch_; - static int64_t enter_external_; friend class CpuProfiler; }; diff --git a/src/vm-state-inl.h b/src/vm-state-inl.h index bc48160..fae68eb 100644 --- a/src/vm-state-inl.h +++ b/src/vm-state-inl.h @@ -67,8 +67,8 @@ VMState::VMState(Isolate* isolate, StateTag tag) LOG(isolate, UncheckedStringEvent("From", StateToString(previous_tag_))); } - if (FLAG_log_timer_events) { - LOG(isolate, ExternalSwitch(previous_tag_, tag)); + if (FLAG_log_timer_events && previous_tag_ != EXTERNAL && tag == EXTERNAL) { + LOG(isolate_, EnterExternal()); } isolate_->SetCurrentVMState(tag); @@ -84,8 +84,9 @@ VMState::~VMState() { UncheckedStringEvent("To", StateToString(previous_tag_))); } - if (FLAG_log_timer_events) { - LOG(isolate_, ExternalSwitch(isolate_->current_vm_state(), previous_tag_)); + if (FLAG_log_timer_events && + previous_tag_ != EXTERNAL && isolate_->current_vm_state() == EXTERNAL) { + LOG(isolate_, LeaveExternal()); } isolate_->SetCurrentVMState(previous_tag_); diff --git a/tools/plot-timer-events b/tools/plot-timer-events index 581e0ae..0f85699 100755 --- a/tools/plot-timer-events +++ b/tools/plot-timer-events @@ -41,18 +41,25 @@ else $d8_exec --nocrankshaft --prof --logfile $calibration_log \ --log-timer-events -e "$calibration_script" > /dev/null - t_1=`grep "V8.Execute" $calibration_log | tail -n1 | awk -F, '{print $4}'` - n_1=`grep "timer-event" $calibration_log | wc -l` + t_1_start=`grep "timer-event-start,\"V8.Execute\"" $calibration_log \ + | tail -n1 | awk -F, '{print $3}'` + t_1_end=`grep "timer-event-end,\"V8.Execute\"" $calibration_log \ + | tail -n1 | awk -F, '{print $3}'` + n_1=`grep "timer-event\|tick" $calibration_log | wc -l` $d8_exec --nocrankshaft --prof --logfile $calibration_log \ --log-internal-timer-events -e "$calibration_script" > /dev/null - t_2=`grep "V8.Execute" $calibration_log | tail -n1 | awk -F, '{print $4}'` - n_2=`grep "timer-event" $calibration_log | wc -l` + t_2_start=`grep "timer-event-start,\"V8.Execute\"" $calibration_log \ + | tail -n1 | awk -F, '{print $3}'` + t_2_end=`grep "timer-event-end,\"V8.Execute\"" $calibration_log \ + | tail -n1 | awk -F, '{print $3}'` + n_2=`grep "timer-event\|tick" $calibration_log | wc -l` rm $calibration_log # Overhead in picoseconds. - distortion=`echo "1000*($t_1 - $t_2)/($n_1 - $n_2)" | bc` + distortion=`echo "1000*(($t_1_end - $t_1_start) - ($t_2_end - $t_2_start)) \ + / ($n_1 - $n_2)" | bc` fi if [ -n "$PLOT_RANGE" ]; then diff --git a/tools/plot-timer-events.js b/tools/plot-timer-events.js index 44ff326..4ea0740 100644 --- a/tools/plot-timer-events.js +++ b/tools/plot-timer-events.js @@ -33,7 +33,6 @@ var kExecutionFrameWidth = 0.2; var kStackFrameWidth = 0.1; var kGapWidth = 0.05; -var kPauseTolerance = 0.1; // Milliseconds. var kY1Offset = 10; var kResX = 1600; @@ -42,35 +41,57 @@ var kPauseLabelPadding = 5; var kNumPauseLabels = 7; var kTickHalfDuration = 0.5; // Milliseconds var kCodeKindLabelPadding = 100; +var kMinRangeLength = 0.0005; // Milliseconds var num_timer_event = kY1Offset + 0.5; +var kNumThreads = 2; +var kExecutionThreadId = 0; -function TimerEvent(color, pause, no_execution) { +function assert(something, message) { + if (!something) { + print(new Error(message).stack); + } +} + +function TimerEvent(color, pause, thread_id) { + assert(thread_id >= 0 && thread_id < kNumThreads, "invalid thread id"); this.color = color; this.pause = pause; this.ranges = []; - this.no_execution = no_execution; + this.thread_id = thread_id; this.index = ++num_timer_event; } var TimerEvents = { - 'V8.Execute': new TimerEvent("#000000", false, false), - 'V8.External': new TimerEvent("#3399FF", false, true), - 'V8.CompileFullCode': new TimerEvent("#CC0000", true, true), - 'V8.RecompileSynchronous': new TimerEvent("#CC0044", true, true), - 'V8.RecompileParallel': new TimerEvent("#CC4499", false, false), - 'V8.CompileEval': new TimerEvent("#CC4400", true, true), - 'V8.Parse': new TimerEvent("#00CC00", true, true), - 'V8.PreParse': new TimerEvent("#44CC00", true, true), - 'V8.ParseLazy': new TimerEvent("#00CC44", true, true), - 'V8.GCScavenger': new TimerEvent("#0044CC", true, true), - 'V8.GCCompactor': new TimerEvent("#4444CC", true, true), - 'V8.GCContext': new TimerEvent("#4400CC", true, true), + 'V8.Execute': new TimerEvent("#000000", false, 0), + 'V8.External': new TimerEvent("#3399FF", false, 0), + 'V8.CompileFullCode': new TimerEvent("#CC0000", true, 0), + 'V8.RecompileSynchronous': new TimerEvent("#CC0044", true, 0), + 'V8.RecompileParallel': new TimerEvent("#CC4499", false, 1), + 'V8.CompileEval': new TimerEvent("#CC4400", true, 0), + 'V8.Parse': new TimerEvent("#00CC00", true, 0), + 'V8.PreParse': new TimerEvent("#44CC00", true, 0), + 'V8.ParseLazy': new TimerEvent("#00CC44", true, 0), + 'V8.GCScavenger': new TimerEvent("#0044CC", true, 0), + 'V8.GCCompactor': new TimerEvent("#4444CC", true, 0), + 'V8.GCContext': new TimerEvent("#4400CC", true, 0), } -var kExecutionEvent = TimerEvents['V8.Execute']; + +Array.prototype.top = function() { + if (this.length == 0) return undefined; + return this[this.length - 1]; +} + +var event_stack = []; +var last_time_stamp = []; + +for (var i = 0; i < kNumThreads; i++) { + event_stack[i] = []; + last_time_stamp[i] = -1; +} function CodeKind(color, kinds) { @@ -103,10 +124,9 @@ var code_map = new CodeMap(); var xrange_start_override = undefined; var xrange_end_override = undefined; var distortion_per_entry = 0.005; // Milliseconds +var pause_tolerance = 0.005; // Milliseconds. -var sort_by_start = []; -var sort_by_end = []; -var sorted_ticks = []; +var distortion = 0; function Range(start, end) { @@ -124,16 +144,37 @@ function Tick(tick) { 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; - var range = new Range(start, end); - event.ranges.push(range); - sort_by_start.push(range); - sort_by_end.push(range); +function ProcessTimerEventStart(name, start) { + // Find out the thread id. + var new_event = TimerEvents[name]; + if (new_event === undefined) return; + var thread_id = new_event.thread_id; + + start = Math.max(last_time_stamp[thread_id] + kMinRangeLength, start); + + // Last event on this thread is done with the start of this event. + var last_event = event_stack[thread_id].top(); + if (last_event !== undefined) { + var new_range = new Range(last_time_stamp[thread_id], start); + last_event.ranges.push(new_range); + } + event_stack[thread_id].push(new_event); + last_time_stamp[thread_id] = start; +} + + +function ProcessTimerEventEnd(name, end) { + // Find out about the thread_id. + var finished_event = TimerEvents[name]; + var thread_id = finished_event.thread_id; + assert(finished_event === event_stack[thread_id].pop(), + "inconsistent event stack"); + + end = Math.max(last_time_stamp[thread_id] + kMinRangeLength, end); + + var new_range = new Range(last_time_stamp[thread_id], end); + finished_event.ranges.push(new_range); + last_time_stamp[thread_id] = end; } @@ -178,26 +219,16 @@ function FindCodeKind(kind) { function ProcessTickEvent(pc, sp, timer, unused_x, unused_y, vmstate, stack) { - timer /= 1000; var tick = new Tick(timer); - var entered = false; var entry = code_map.findEntry(pc); - if (entry) { - FindCodeKind(entry.kind).in_execution.push(tick); - entered = true; - } + if (entry) FindCodeKind(entry.kind).in_execution.push(tick); for (var i = 0; i < kStackFrames; i++) { if (!stack[i]) break; var entry = code_map.findEntry(stack[i]); - if (entry) { - FindCodeKind(entry.kind).stack_frames[i].push(tick); - entered = true; - } + if (entry) FindCodeKind(entry.kind).stack_frames[i].push(tick); } - - if (entered) sorted_ticks.push(tick); } @@ -212,62 +243,6 @@ function ProcessPlotRange(start, end) { } -function Undistort() { - // Undistort timers wrt instrumentation overhead. - sort_by_start.sort(function(a, b) { return b.start - a.start; }); - sort_by_end.sort(function(a, b) { return b.end - a.end; }); - sorted_ticks.sort(function(a, b) { return b.tick - a.tick; }); - var distortion = 0; - - var next_start = sort_by_start.pop(); - var next_end = sort_by_end.pop(); - var next_tick = sorted_ticks.pop(); - - function UndistortTicksUntil(tick) { - while (next_tick) { - if (next_tick.tick > tick) return; - next_tick.tick -= distortion; - next_tick = sorted_ticks.pop(); - } - } - - while (true) { - var next_start_start = next_start ? next_start.start : Infinity; - var next_end_end = next_end ? next_end.end : Infinity; - if (!next_start && !next_end) { - UndistortTicksUntil(Infinity); - break; - } - if (next_start_start <= next_end_end) { - UndistortTicksUntil(next_start_start); - // Undistort the start time stamp. - next_start.start -= distortion; - next_start = sort_by_start.pop(); - } else { - // Undistort the end time stamp. We completely attribute the overhead - // to the point when we stop and log the timer, so we increase the - // distortion only here. - UndistortTicksUntil(next_end_end); - next_end.end -= distortion; - distortion += distortion_per_entry; - next_end = sort_by_end.pop(); - } - } - - sort_by_start = undefined; - sort_by_end = undefined; - sorted_ticks = undefined; - - // Make sure that start <= end applies for every range. - for (name in TimerEvents) { - var ranges = TimerEvents[name].ranges; - for (var j = 0; j < ranges.length; j++) { - if (ranges[j].end < ranges[j].start) ranges[j].end = ranges[j].start; - } - } -} - - function FindPlotRange() { var start_found = (xrange_start_override || xrange_start_override == 0); var end_found = (xrange_end_override || xrange_end_override == 0); @@ -299,14 +274,26 @@ function FindPlotRange() { } } } + + // Set pause tolerance to something appropriate for the plot resolution + // to make it easier for gnuplot. + pause_tolerance = (xrange_end - xrange_start) / kResX / 10; +} + + +function parseTimeStamp(timestamp) { + distortion += distortion_per_entry; + return parseInt(timestamp) / 1000 - distortion; } function CollectData() { // Collect data from log. var logreader = new LogReader( - { 'timer-event' : { parsers: [null, parseInt, parseInt], - processor: ProcessTimerEvent }, + { 'timer-event-start': { parsers: [null, parseTimeStamp], + processor: ProcessTimerEventStart }, + 'timer-event-end': { parsers: [null, parseTimeStamp], + processor: ProcessTimerEventEnd }, 'shared-library': { parsers: [null, parseInt, parseInt], processor: ProcessSharedLibrary }, 'code-creation': { parsers: [null, parseInt, parseInt, parseInt, null], @@ -315,7 +302,7 @@ function CollectData() { processor: ProcessCodeMoveEvent }, 'code-delete': { parsers: [parseInt], processor: ProcessCodeDeleteEvent }, - 'tick': { parsers: [parseInt, parseInt, parseInt, + 'tick': { parsers: [parseInt, parseInt, parseTimeStamp, null, null, parseInt, 'var-args'], processor: ProcessTickEvent }, 'distortion': { parsers: [parseInt], @@ -329,8 +316,6 @@ function CollectData() { logreader.processLogLine(line); } - Undistort(); - // Collect execution pauses. for (name in TimerEvents) { var event = TimerEvents[name]; @@ -339,25 +324,6 @@ function CollectData() { for (var j = 0; j < ranges.length; j++) execution_pauses.push(ranges[j]); } execution_pauses = MergeRanges(execution_pauses); - - // Knock out time not spent in javascript execution. Note that this also - // includes time spent external code, which do not contribute to execution - // pauses. - var exclude_ranges = []; - for (name in TimerEvents) { - var event = TimerEvents[name]; - if (!event.no_execution) continue; - var ranges = event.ranges; - // Add ranges of this event to the pause list. - for (var j = 0; j < ranges.length; j++) { - exclude_ranges.push(ranges[j]); - } - } - - kExecutionEvent.ranges = MergeRanges(kExecutionEvent.ranges); - exclude_ranges = MergeRanges(exclude_ranges); - kExecutionEvent.ranges = ExcludeRanges(kExecutionEvent.ranges, - exclude_ranges); } @@ -392,7 +358,7 @@ function MergeRanges(ranges) { 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; + if (next_range.start > merge_end + pause_tolerance) break; // Merge ranges. if (next_range.end > merge_end) { // Extend range end. merge_end = next_range.end; @@ -406,84 +372,14 @@ function MergeRanges(ranges) { } -function ExcludeRanges(include, exclude) { - // We assume that both input lists are sorted and merged with MergeRanges. +function RestrictRangesTo(ranges, start, end) { 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; + for (var i = 0; i < ranges.length; i++) { + if (ranges[i].start <= end && ranges[i].end >= start) { + result.push(new Range(Math.max(ranges[i].start, start), + Math.min(ranges[i].end, end))); } - 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; } @@ -506,10 +402,8 @@ function GnuplotOutput() { var total = 0; for (var name in TimerEvents) { var event = TimerEvents[name]; - var ranges = MergeRanges(event.ranges); - var exclude_ranges = [new Range(-Infinity, xrange_start), - new Range(xrange_end, Infinity)]; - ranges = ExcludeRanges(ranges, exclude_ranges); + var ranges = RestrictRangesTo(event.ranges, xrange_start, xrange_end); + ranges = MergeRanges(ranges); var sum = ranges.map(function(range) { return range.duration(); }) .reduce(function(a, b) { return a + b; }, 0); -- 2.7.4