Commit 92d9a56a authored by lpy's avatar lpy Committed by Commit bot

[Tracing] Fix inaccurate timer calculation in runtime statistics.

Previously we reset runtime counters and dump them when we enter, exit top level
trace events respectively. However, there is gap between two top level trace
events and runtime counters may be activated, resetting the counters makes the
accumulated time inaccurate, and we may end up with negative time due to the
nature of how we accumulate time.

This patch fixes this problem by only resetting counters when there's no
counters active, and before dump counters, we traverse current active counters
to calculate their time, and then restart their timer.

BUG=chromium:658145

Review-Url: https://codereview.chromium.org/2457523002
Cr-Commit-Position: refs/heads/master@{#40653}
parent 404e2154
...@@ -316,6 +316,9 @@ void RuntimeCallStats::CorrectCurrentCounterId(RuntimeCallStats* stats, ...@@ -316,6 +316,9 @@ void RuntimeCallStats::CorrectCurrentCounterId(RuntimeCallStats* stats,
void RuntimeCallStats::Print(std::ostream& os) { void RuntimeCallStats::Print(std::ostream& os) {
RuntimeCallStatEntries entries; RuntimeCallStatEntries entries;
if (current_timer_ != NULL) {
current_timer_->Elapsed();
}
#define PRINT_COUNTER(name) entries.Add(&this->name); #define PRINT_COUNTER(name) entries.Add(&this->name);
FOR_EACH_MANUAL_COUNTER(PRINT_COUNTER) FOR_EACH_MANUAL_COUNTER(PRINT_COUNTER)
...@@ -368,6 +371,9 @@ void RuntimeCallStats::Reset() { ...@@ -368,6 +371,9 @@ void RuntimeCallStats::Reset() {
} }
void RuntimeCallStats::Dump(v8::tracing::TracedValue* value) { void RuntimeCallStats::Dump(v8::tracing::TracedValue* value) {
if (current_timer_ != NULL) {
current_timer_->Elapsed();
}
#define DUMP_COUNTER(name) \ #define DUMP_COUNTER(name) \
if (this->name.count > 0) this->name.Dump(value); if (this->name.count > 0) this->name.Dump(value);
FOR_EACH_MANUAL_COUNTER(DUMP_COUNTER) FOR_EACH_MANUAL_COUNTER(DUMP_COUNTER)
......
...@@ -521,6 +521,16 @@ class RuntimeCallTimer { ...@@ -521,6 +521,16 @@ class RuntimeCallTimer {
return parent_; return parent_;
} }
inline void Elapsed() {
base::TimeDelta delta = timer_.Elapsed();
counter_->time += delta;
if (parent_ != nullptr) {
parent_->counter_->time -= delta;
parent_->Elapsed();
}
timer_.Restart();
}
RuntimeCallCounter* counter_ = nullptr; RuntimeCallCounter* counter_ = nullptr;
RuntimeCallTimer* parent_ = nullptr; RuntimeCallTimer* parent_ = nullptr;
base::ElapsedTimer timer_; base::ElapsedTimer timer_;
......
...@@ -49,7 +49,7 @@ void CallStatsScopedTracer::Initialize(v8::internal::Isolate* isolate, ...@@ -49,7 +49,7 @@ void CallStatsScopedTracer::Initialize(v8::internal::Isolate* isolate,
p_data_ = &data_; p_data_ = &data_;
RuntimeCallStats* table = isolate->counters()->runtime_call_stats(); RuntimeCallStats* table = isolate->counters()->runtime_call_stats();
has_parent_scope_ = table->InUse(); has_parent_scope_ = table->InUse();
if (!has_parent_scope_) table->Reset(); if (!has_parent_scope_ && table->current_timer() == NULL) table->Reset();
v8::internal::tracing::AddTraceEvent( v8::internal::tracing::AddTraceEvent(
TRACE_EVENT_PHASE_BEGIN, category_group_enabled, name, TRACE_EVENT_PHASE_BEGIN, category_group_enabled, name,
v8::internal::tracing::kGlobalScope, v8::internal::tracing::kNoId, v8::internal::tracing::kGlobalScope, v8::internal::tracing::kNoId,
......
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment