From c027397c9de15ea7033256dfa1978a37effd0f2e Mon Sep 17 00:00:00 2001 From: "hpayer@chromium.org" Date: Wed, 30 Jan 2013 10:51:13 +0000 Subject: [PATCH] Precisely measure duration of mark and sweep phases. Changed print_cumulative_gc_stat flag to only print GC statistics at end of program. BUG= Review URL: https://codereview.chromium.org/11595006 git-svn-id: http://v8.googlecode.com/svn/branches/bleeding_edge@13551 ce2b1a6d-e550-0410-aec6-3dcde31c8c00 --- src/heap.cc | 9 ++++++++- src/heap.h | 25 ++++++++++++++++++++++++- src/incremental-marking.cc | 23 ++++++++++++++++------- src/mark-compact.cc | 17 +++++++++++++++++ 4 files changed, 65 insertions(+), 9 deletions(-) diff --git a/src/heap.cc b/src/heap.cc index 14c44e88dc..1916b64426 100644 --- a/src/heap.cc +++ b/src/heap.cc @@ -145,6 +145,8 @@ Heap::Heap() min_in_mutator_(kMaxInt), alive_after_last_gc_(0), last_gc_end_timestamp_(0.0), + marking_time_(0.0), + sweeping_time_(0.0), store_buffer_(this), marking_(this), incremental_marking_(this), @@ -6338,7 +6340,7 @@ void Heap::TearDown() { #endif if (FLAG_print_cumulative_gc_stat) { - PrintF("\n\n"); + PrintF("\n"); PrintF("gc_count=%d ", gc_count_); PrintF("mark_sweep_count=%d ", ms_count_); PrintF("max_gc_pause=%d ", get_max_gc_pause()); @@ -6346,6 +6348,8 @@ void Heap::TearDown() { PrintF("min_in_mutator=%d ", get_min_in_mutator()); PrintF("max_alive_after_gc=%" V8_PTR_PREFIX "d ", get_max_alive_after_gc()); + PrintF("total_marking_time=%f ", marking_time()); + PrintF("total_sweeping_time=%f ", sweeping_time()); PrintF("\n\n"); } @@ -7036,6 +7040,9 @@ GCTracer::~GCTracer() { if (collector_ == SCAVENGER && FLAG_trace_gc_ignore_scavenger) return; + heap_->AddMarkingTime(scopes_[Scope::MC_MARK]); + + if (FLAG_print_cumulative_gc_stat && !FLAG_trace_gc) return; PrintPID("%8.0f ms: ", heap_->isolate()->time_millis_since_init()); if (!FLAG_trace_gc_nvp) { diff --git a/src/heap.h b/src/heap.h index 5db1c954c3..45698a1f9f 100644 --- a/src/heap.h +++ b/src/heap.h @@ -1596,6 +1596,24 @@ class Heap { // Returns minimal interval between two subsequent collections. int get_min_in_mutator() { return min_in_mutator_; } + // TODO(hpayer): remove, should be handled by GCTracer + void AddMarkingTime(double marking_time) { + marking_time_ += marking_time; + } + + double marking_time() const { + return marking_time_; + } + + // TODO(hpayer): remove, should be handled by GCTracer + void AddSweepingTime(double sweeping_time) { + sweeping_time_ += sweeping_time; + } + + double sweeping_time() const { + return sweeping_time_; + } + MarkCompactCollector* mark_compact_collector() { return &mark_compact_collector_; } @@ -2035,7 +2053,6 @@ class Heap { GCTracer* tracer_; - // Allocates a small number to string cache. MUST_USE_RESULT MaybeObject* AllocateInitialNumberStringCache(); // Creates and installs the full-sized number string cache. @@ -2173,6 +2190,12 @@ class Heap { double last_gc_end_timestamp_; + // Cumulative GC time spent in marking + double marking_time_; + + // Cumulative GC time spent in sweeping + double sweeping_time_; + MarkCompactCollector mark_compact_collector_; StoreBuffer store_buffer_; diff --git a/src/incremental-marking.cc b/src/incremental-marking.cc index ef7dbe05ff..97332c5174 100644 --- a/src/incremental-marking.cc +++ b/src/incremental-marking.cc @@ -754,18 +754,24 @@ void IncrementalMarking::ProcessMarkingDeque() { void IncrementalMarking::Hurry() { if (state() == MARKING) { double start = 0.0; - if (FLAG_trace_incremental_marking) { - PrintF("[IncrementalMarking] Hurry\n"); + if (FLAG_trace_incremental_marking || FLAG_print_cumulative_gc_stat) { start = OS::TimeCurrentMillis(); + if (FLAG_trace_incremental_marking) { + PrintF("[IncrementalMarking] Hurry\n"); + } } // TODO(gc) hurry can mark objects it encounters black as mutator // was stopped. ProcessMarkingDeque(); state_ = COMPLETE; - if (FLAG_trace_incremental_marking) { + if (FLAG_trace_incremental_marking || FLAG_print_cumulative_gc_stat) { double end = OS::TimeCurrentMillis(); - PrintF("[IncrementalMarking] Complete (hurry), spent %d ms.\n", - static_cast(end - start)); + double delta = end - start; + heap_->AddMarkingTime(delta); + if (FLAG_trace_incremental_marking) { + PrintF("[IncrementalMarking] Complete (hurry), spent %d ms.\n", + static_cast(delta)); + } } } @@ -889,7 +895,8 @@ void IncrementalMarking::Step(intptr_t allocated_bytes, double start = 0; - if (FLAG_trace_incremental_marking || FLAG_trace_gc) { + if (FLAG_trace_incremental_marking || FLAG_trace_gc || + FLAG_print_cumulative_gc_stat) { start = OS::TimeCurrentMillis(); } @@ -969,12 +976,14 @@ void IncrementalMarking::Step(intptr_t allocated_bytes, } } - if (FLAG_trace_incremental_marking || FLAG_trace_gc) { + if (FLAG_trace_incremental_marking || FLAG_trace_gc || + FLAG_print_cumulative_gc_stat) { double end = OS::TimeCurrentMillis(); double delta = (end - start); longest_step_ = Max(longest_step_, delta); steps_took_ += delta; steps_took_since_last_gc_ += delta; + heap_->AddMarkingTime(delta); } } diff --git a/src/mark-compact.cc b/src/mark-compact.cc index bfb4031f3e..e59494004f 100644 --- a/src/mark-compact.cc +++ b/src/mark-compact.cc @@ -2832,6 +2832,11 @@ static void SweepPrecisely(PagedSpace* space, space->identity() == CODE_SPACE); ASSERT((p->skip_list() == NULL) || (skip_list_mode == REBUILD_SKIP_LIST)); + double start_time = 0.0; + if (FLAG_print_cumulative_gc_stat) { + start_time = OS::TimeCurrentMillis(); + } + MarkBit::CellType* cells = p->markbits()->cells(); p->MarkSweptPrecisely(); @@ -2897,6 +2902,9 @@ static void SweepPrecisely(PagedSpace* space, space->Free(free_start, static_cast(p->area_end() - free_start)); } p->ResetLiveBytes(); + if (FLAG_print_cumulative_gc_stat) { + space->heap()->AddSweepingTime(OS::TimeCurrentMillis() - start_time); + } } @@ -3491,6 +3499,11 @@ static inline Address StartOfLiveObject(Address block_address, uint32_t cell) { // spaces will not contain the free space map. intptr_t MarkCompactCollector::SweepConservatively(PagedSpace* space, Page* p) { ASSERT(!p->IsEvacuationCandidate() && !p->WasSwept()); + double start_time = 0.0; + if (FLAG_print_cumulative_gc_stat) { + start_time = OS::TimeCurrentMillis(); + } + MarkBit::CellType* cells = p->markbits()->cells(); p->MarkSweptConservatively(); @@ -3577,6 +3590,10 @@ intptr_t MarkCompactCollector::SweepConservatively(PagedSpace* space, Page* p) { } p->ResetLiveBytes(); + + if (FLAG_print_cumulative_gc_stat) { + space->heap()->AddSweepingTime(OS::TimeCurrentMillis() - start_time); + } return freed_bytes; }