From 924cc893848e11db45eb1a3661fac05c5933c994 Mon Sep 17 00:00:00 2001 From: Nikolaos Papaspyrou Date: Tue, 8 Mar 2022 18:05:58 +0100 Subject: [PATCH] heap: Migrate full GC cycle UMA metrics Report full GC statistics to the Recorder API. These will be used by Blink to populate UMA histograms. Existing UMA reporting in V8 remains as is for now and will be removed in a followup. With this CL, most full GC statistics are reported as part of V8.GC.Cycle.*.Full.*. Also V8.GCMarkCompactReason is migrated to V8.GC.Cycle.Reason.Full. This CL goes together with: https://chromium-review.googlesource.com/c/chromium/src/+/3353448 Bug: chromium:1154636 Change-Id: I199be75e75144a59e5f56a6872268d0ecad3a885 Reviewed-on: https://chromium-review.googlesource.com/c/v8/v8/+/3356195 Reviewed-by: Michael Lippautz Reviewed-by: Omer Katz Commit-Queue: Nikolaos Papaspyrou Cr-Commit-Position: refs/heads/main@{#79408} --- include/v8-metrics.h | 1 + src/heap/gc-tracer.cc | 116 +++++++++++++++++++++++++++++++++++------- src/heap/gc-tracer.h | 9 ++-- src/heap/sweeper.cc | 3 +- 4 files changed, 105 insertions(+), 24 deletions(-) diff --git a/include/v8-metrics.h b/include/v8-metrics.h index 1238f833f2..01bc538e22 100644 --- a/include/v8-metrics.h +++ b/include/v8-metrics.h @@ -35,6 +35,7 @@ struct GarbageCollectionSizes { }; struct GarbageCollectionFullCycle { + int reason = -1; GarbageCollectionPhases total; GarbageCollectionPhases total_cpp; GarbageCollectionPhases main_thread; diff --git a/src/heap/gc-tracer.cc b/src/heap/gc-tracer.cc index 4c76d5733f..a926a8d4f0 100644 --- a/src/heap/gc-tracer.cc +++ b/src/heap/gc-tracer.cc @@ -479,7 +479,7 @@ void GCTracer::UpdateStatistics(GarbageCollector collector) { } RecordMutatorUtilization(current_.end_time, duration + current_.incremental_marking_duration); - RecordGCSumCounters(duration); + RecordGCSumCounters(); ResetIncrementalMarkingCounters(); combined_mark_compact_speed_cache_ = 0.0; FetchBackgroundMarkCompactCounters(); @@ -1363,20 +1363,23 @@ void GCTracer::RecordGCPhasesHistograms(RecordGCPhasesInfo::Mode mode) { } } -void GCTracer::RecordGCSumCounters(double atomic_pause_duration) { +void GCTracer::RecordGCSumCounters() { base::MutexGuard guard(&background_counter_mutex_); - const double overall_duration = + const double atomic_pause_duration = current_.scopes[Scope::MARK_COMPACTOR]; + const double incremental_marking = current_.incremental_marking_scopes[Scope::MC_INCREMENTAL_LAYOUT_CHANGE] .duration + current_.incremental_marking_scopes[Scope::MC_INCREMENTAL_START] .duration + - current_.incremental_marking_scopes[Scope::MC_INCREMENTAL_SWEEPING] - .duration + incremental_marking_duration_ + current_.incremental_marking_scopes[Scope::MC_INCREMENTAL_FINALIZE] - .duration + - atomic_pause_duration; + .duration; + const double incremental_sweeping = + current_.incremental_marking_scopes[Scope::MC_INCREMENTAL_SWEEPING] + .duration; + const double overall_duration = + atomic_pause_duration + incremental_marking + incremental_sweeping; const double background_duration = background_counter_[Scope::MC_BACKGROUND_EVACUATE_COPY] .total_duration_ms + @@ -1384,16 +1387,9 @@ void GCTracer::RecordGCSumCounters(double atomic_pause_duration) { .total_duration_ms + background_counter_[Scope::MC_BACKGROUND_MARKING].total_duration_ms + background_counter_[Scope::MC_BACKGROUND_SWEEPING].total_duration_ms; - - const double marking_duration = - current_.incremental_marking_scopes[Scope::MC_INCREMENTAL_LAYOUT_CHANGE] - .duration + - current_.incremental_marking_scopes[Scope::MC_INCREMENTAL_START] - .duration + - incremental_marking_duration_ + - current_.incremental_marking_scopes[Scope::MC_INCREMENTAL_FINALIZE] - .duration + - current_.scopes[Scope::MC_MARK]; + const double atomic_marking_duration = + current_.scopes[Scope::MC_PROLOGUE] + current_.scopes[Scope::MC_MARK]; + const double marking_duration = atomic_marking_duration + incremental_marking; const double marking_background_duration = background_counter_[Scope::MC_BACKGROUND_MARKING].total_duration_ms; @@ -1494,7 +1490,11 @@ void GCTracer::ReportFullCycleToRecorder() { FlushBatchedIncrementalEvents(incremental_mark_batched_events_, heap_->isolate()); } + v8::metrics::GarbageCollectionFullCycle event; + event.reason = static_cast(current_.gc_reason); + + // Managed C++ heap statistics: if (cpp_heap) { cpp_heap->GetMetricRecorder()->FlushBatchedIncrementalEvents(); const base::Optional @@ -1522,7 +1522,87 @@ void GCTracer::ReportFullCycleToRecorder() { event.main_thread_efficiency_cpp_in_bytes_per_us = cppgc_event.main_thread_efficiency_in_bytes_per_us; } - // TODO(chromium:1154636): Populate v8 metrics. + + // Unified heap statistics: + const double atomic_pause_duration = current_.scopes[Scope::MARK_COMPACTOR]; + const double incremental_marking = + current_.incremental_marking_scopes[Scope::MC_INCREMENTAL_LAYOUT_CHANGE] + .duration + + current_.incremental_marking_scopes[Scope::MC_INCREMENTAL_START] + .duration + + current_.incremental_marking_duration + + current_.incremental_marking_scopes[Scope::MC_INCREMENTAL_FINALIZE] + .duration; + const double incremental_sweeping = + current_.incremental_marking_scopes[Scope::MC_INCREMENTAL_SWEEPING] + .duration; + const double overall_duration = + atomic_pause_duration + incremental_marking + incremental_sweeping; + const double marking_background_duration = + current_.scopes[Scope::MC_BACKGROUND_MARKING]; + const double sweeping_background_duration = + current_.scopes[Scope::MC_BACKGROUND_SWEEPING]; + const double compact_background_duration = + current_.scopes[Scope::MC_BACKGROUND_EVACUATE_COPY] + + current_.scopes[Scope::MC_BACKGROUND_EVACUATE_UPDATE_POINTERS]; + const double background_duration = marking_background_duration + + sweeping_background_duration + + compact_background_duration; + const double atomic_marking_duration = + current_.scopes[Scope::MC_PROLOGUE] + current_.scopes[Scope::MC_MARK]; + const double marking_duration = atomic_marking_duration + incremental_marking; + const double weak_duration = current_.scopes[Scope::MC_CLEAR]; + const double compact_duration = current_.scopes[Scope::MC_EVACUATE] + + current_.scopes[Scope::MC_FINISH] + + current_.scopes[Scope::MC_EPILOGUE]; + const double atomic_sweeping_duration = current_.scopes[Scope::MC_SWEEP]; + const double sweeping_duration = + atomic_sweeping_duration + incremental_sweeping; + + event.main_thread_atomic.total_wall_clock_duration_in_us = + static_cast(atomic_pause_duration * + base::Time::kMicrosecondsPerMillisecond); + event.main_thread.total_wall_clock_duration_in_us = static_cast( + overall_duration * base::Time::kMicrosecondsPerMillisecond); + event.total.total_wall_clock_duration_in_us = + static_cast((overall_duration + background_duration) * + base::Time::kMicrosecondsPerMillisecond); + event.main_thread_atomic.mark_wall_clock_duration_in_us = + static_cast(atomic_marking_duration * + base::Time::kMicrosecondsPerMillisecond); + event.main_thread.mark_wall_clock_duration_in_us = static_cast( + marking_duration * base::Time::kMicrosecondsPerMillisecond); + event.total.mark_wall_clock_duration_in_us = + static_cast((marking_duration + marking_background_duration) * + base::Time::kMicrosecondsPerMillisecond); + event.main_thread_atomic.weak_wall_clock_duration_in_us = + event.main_thread.weak_wall_clock_duration_in_us = + event.total.weak_wall_clock_duration_in_us = static_cast( + weak_duration * base::Time::kMicrosecondsPerMillisecond); + event.main_thread_atomic.compact_wall_clock_duration_in_us = + event.main_thread.compact_wall_clock_duration_in_us = + static_cast(compact_duration * + base::Time::kMicrosecondsPerMillisecond); + event.total.compact_wall_clock_duration_in_us = + static_cast((compact_duration + compact_background_duration) * + base::Time::kMicrosecondsPerMillisecond); + event.main_thread_atomic.sweep_wall_clock_duration_in_us = + static_cast(atomic_sweeping_duration * + base::Time::kMicrosecondsPerMillisecond); + event.main_thread.sweep_wall_clock_duration_in_us = static_cast( + sweeping_duration * base::Time::kMicrosecondsPerMillisecond); + event.total.sweep_wall_clock_duration_in_us = + static_cast((sweeping_duration + sweeping_background_duration) * + base::Time::kMicrosecondsPerMillisecond); + + // TODO(chromium:1154636): Populate the following: + // - event.main_thread_incremental + // - event.objects + // - event.memory + // - event.collection_rate_in_percent + // - event.efficiency_in_bytes_per_us + // - event.main_thread_efficiency_in_bytes_per_us + recorder->AddMainThreadEvent(event, GetContextId(heap_->isolate())); } diff --git a/src/heap/gc-tracer.h b/src/heap/gc-tracer.h index 34dce367e0..7727623d0a 100644 --- a/src/heap/gc-tracer.h +++ b/src/heap/gc-tracer.h @@ -440,7 +440,6 @@ class V8_EXPORT_PRIVATE GCTracer { FRIEND_TEST(GCTracerTest, IncrementalScope); FRIEND_TEST(GCTracerTest, IncrementalMarkingSpeed); FRIEND_TEST(GCTracerTest, MutatorUtilization); - FRIEND_TEST(GCTracerTest, RecordGCSumHistograms); FRIEND_TEST(GCTracerTest, RecordMarkCompactHistograms); FRIEND_TEST(GCTracerTest, RecordScavengerHistograms); @@ -461,10 +460,10 @@ class V8_EXPORT_PRIVATE GCTracer { void RecordMutatorUtilization(double mark_compactor_end_time, double mark_compactor_duration); - // Overall time spent in mark compact within a given GC cycle. Exact - // accounting of events within a GC is not necessary which is why the - // recording takes place at the end of the atomic pause. - void RecordGCSumCounters(double atomic_pause_duration); + // Update counters for an entire full GC cycle. Exact accounting of events + // within a GC is not necessary which is why the recording takes place at the + // end of the atomic pause. + void RecordGCSumCounters(); double MonotonicallyIncreasingTimeInMs(); diff --git a/src/heap/sweeper.cc b/src/heap/sweeper.cc index 7f0e109464..0bd5639d92 100644 --- a/src/heap/sweeper.cc +++ b/src/heap/sweeper.cc @@ -136,7 +136,6 @@ class Sweeper::IncrementalSweeperTask final : public CancelableTask { void RunInternal() final { VMState state(isolate_); TRACE_EVENT_CALL_STATS_SCOPED(isolate_, "v8", "V8.Task"); - sweeper_->incremental_sweeper_pending_ = false; if (sweeper_->sweeping_in_progress()) { @@ -441,6 +440,8 @@ bool Sweeper::ConcurrentSweepSpace(AllocationSpace identity, } bool Sweeper::IncrementalSweepSpace(AllocationSpace identity) { + TRACE_GC_EPOCH(heap_->tracer(), GCTracer::Scope::MC_INCREMENTAL_SWEEPING, + ThreadKind::kMain); if (Page* page = GetSweepingPageSafe(identity)) { ParallelSweepPage(page, identity); }