From 72732e510926335f7dc16ccaddd6968aea7f4545 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Dominik=20Inf=C3=BChr?= Date: Thu, 26 Nov 2020 13:04:03 +0100 Subject: [PATCH] [heap] Use base::TimeTicks for measuring time in GCTracer MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Avoid virtual call on the fast path when invoking Heap::MonotonicallyIncreasingTimeInMs by using base::TimeTicks directly. With --predictable we need to fall back to Heap::MonotonicallyIncreasingTimeInMs though. Convert base::TimeTicks to milliseconds as double, since this was the format GCTracer was using internally. Change-Id: I25ab6f1a77ffc8a317782b5754521c39ccb46e48 Reviewed-on: https://chromium-review.googlesource.com/c/v8/v8/+/2562240 Reviewed-by: Ulan Degenbaev Commit-Queue: Dominik Inführ Cr-Commit-Position: refs/heads/master@{#71440} --- src/heap/gc-tracer.cc | 30 +++++++++++++++++++----------- src/heap/gc-tracer.h | 3 +++ 2 files changed, 22 insertions(+), 11 deletions(-) diff --git a/src/heap/gc-tracer.cc b/src/heap/gc-tracer.cc index 1d96d0f14b..7ddf80f5fe 100644 --- a/src/heap/gc-tracer.cc +++ b/src/heap/gc-tracer.cc @@ -48,17 +48,26 @@ RuntimeCallCounterId GCTracer::RCSCounterFromBackgroundScope( static_cast(id)); } +double GCTracer::MonotonicallyIncreasingTimeInMs() { + if (V8_UNLIKELY(FLAG_predictable)) { + return heap_->MonotonicallyIncreasingTimeInMs(); + } else { + return base::TimeTicks::Now().ToInternalValue() / + static_cast(base::Time::kMicrosecondsPerMillisecond); + } +} + GCTracer::Scope::Scope(GCTracer* tracer, ScopeId scope) : tracer_(tracer), scope_(scope) { - start_time_ = tracer_->heap_->MonotonicallyIncreasingTimeInMs(); + start_time_ = tracer_->MonotonicallyIncreasingTimeInMs(); if (V8_LIKELY(!TracingFlags::is_runtime_stats_enabled())) return; runtime_stats_ = tracer_->heap_->isolate()->counters()->runtime_call_stats(); runtime_stats_->Enter(&timer_, GCTracer::RCSCounterFromScope(scope)); } GCTracer::Scope::~Scope() { - tracer_->AddScopeSample( - scope_, tracer_->heap_->MonotonicallyIncreasingTimeInMs() - start_time_); + double delta = tracer_->MonotonicallyIncreasingTimeInMs() - start_time_; + tracer_->AddScopeSample(scope_, delta); if (V8_LIKELY(runtime_stats_ == nullptr)) return; runtime_stats_->Leave(&timer_); } @@ -66,16 +75,15 @@ GCTracer::Scope::~Scope() { GCTracer::BackgroundScope::BackgroundScope(GCTracer* tracer, ScopeId scope, RuntimeCallStats* runtime_stats) : tracer_(tracer), scope_(scope), runtime_stats_(runtime_stats) { - start_time_ = tracer_->heap_->MonotonicallyIncreasingTimeInMs(); + start_time_ = tracer_->MonotonicallyIncreasingTimeInMs(); if (V8_LIKELY(!TracingFlags::is_runtime_stats_enabled())) return; runtime_stats_->Enter(&timer_, GCTracer::RCSCounterFromBackgroundScope(scope)); } GCTracer::BackgroundScope::~BackgroundScope() { - double duration_ms = - tracer_->heap_->MonotonicallyIncreasingTimeInMs() - start_time_; - tracer_->AddBackgroundScopeSample(scope_, duration_ms); + double delta = tracer_->MonotonicallyIncreasingTimeInMs() - start_time_; + tracer_->AddBackgroundScopeSample(scope_, delta); if (V8_LIKELY(runtime_stats_ == nullptr)) return; runtime_stats_->Leave(&timer_); } @@ -175,7 +183,7 @@ GCTracer::GCTracer(Heap* heap) // We assume that MC_INCREMENTAL is the first scope so that we can properly // map it to RuntimeCallStats. STATIC_ASSERT(0 == Scope::MC_INCREMENTAL); - current_.end_time = heap_->MonotonicallyIncreasingTimeInMs(); + current_.end_time = MonotonicallyIncreasingTimeInMs(); for (int i = 0; i < BackgroundScope::NUMBER_OF_SCOPES; i++) { background_counter_[i].total_duration_ms = 0; } @@ -183,7 +191,7 @@ GCTracer::GCTracer(Heap* heap) void GCTracer::ResetForTesting() { current_ = Event(Event::START, GarbageCollectionReason::kTesting, nullptr); - current_.end_time = heap_->MonotonicallyIncreasingTimeInMs(); + current_.end_time = MonotonicallyIncreasingTimeInMs(); previous_ = current_; ResetIncrementalMarkingCounters(); allocation_time_ms_ = 0.0; @@ -248,7 +256,7 @@ void GCTracer::Start(GarbageCollector collector, } current_.reduce_memory = heap_->ShouldReduceMemory(); - current_.start_time = heap_->MonotonicallyIncreasingTimeInMs(); + current_.start_time = MonotonicallyIncreasingTimeInMs(); current_.start_object_size = 0; current_.start_memory_size = 0; current_.start_holes_size = 0; @@ -322,7 +330,7 @@ void GCTracer::Stop(GarbageCollector collector) { (current_.type == Event::MARK_COMPACTOR || current_.type == Event::INCREMENTAL_MARK_COMPACTOR))); - current_.end_time = heap_->MonotonicallyIncreasingTimeInMs(); + current_.end_time = MonotonicallyIncreasingTimeInMs(); AddAllocation(current_.end_time); diff --git a/src/heap/gc-tracer.h b/src/heap/gc-tracer.h index 47722f7875..4baa738bbd 100644 --- a/src/heap/gc-tracer.h +++ b/src/heap/gc-tracer.h @@ -7,6 +7,7 @@ #include "src/base/compiler-specific.h" #include "src/base/platform/platform.h" +#include "src/base/platform/time.h" #include "src/base/ring-buffer.h" #include "src/common/globals.h" #include "src/heap/heap.h" @@ -405,6 +406,8 @@ class V8_EXPORT_PRIVATE GCTracer { // recording takes place at the end of the atomic pause. void RecordGCSumCounters(double atomic_pause_duration); + double MonotonicallyIncreasingTimeInMs(); + // Print one detailed trace line in name=value format. // TODO(ernstm): Move to Heap. void PrintNVP() const;