From: ernstm@chromium.org Date: Thu, 17 Jul 2014 07:50:55 +0000 (+0000) Subject: v8: GCTracer clean-up part 1. X-Git-Tag: upstream/4.7.83~8191 X-Git-Url: http://review.tizen.org/git/?a=commitdiff_plain;h=509faa85452398dcf07e2a0914592a59e21b3cf5;p=platform%2Fupstream%2Fv8.git v8: GCTracer clean-up part 1. - Split GCTracer::~GCTracer into printing functions and update of variables tracked on Heap. - Clean-up recording of time, object size and memory size at the beginning and end of GC. - Consistently use enum notation in ScopeId. - Disallow copy and assign for Scope and GCTracer. - Remove unused stats on GCTracer. R=hpayer@chromium.org BUG= Review URL: https://codereview.chromium.org/396893004 git-svn-id: https://v8.googlecode.com/svn/branches/bleeding_edge@22439 ce2b1a6d-e550-0410-aec6-3dcde31c8c00 --- diff --git a/src/heap-inl.h b/src/heap-inl.h index 844a375..3fd849c 100644 --- a/src/heap-inl.h +++ b/src/heap-inl.h @@ -804,11 +804,6 @@ void VerifySmisVisitor::VisitPointers(Object** start, Object** end) { } -double GCTracer::SizeOfHeapObjects() { - return (static_cast(heap_->SizeOfObjects())) / MB; -} - - } } // namespace v8::internal #endif // V8_HEAP_INL_H_ diff --git a/src/heap.cc b/src/heap.cc index 8ffa438..75a48f1 100644 --- a/src/heap.cc +++ b/src/heap.cc @@ -834,16 +834,10 @@ bool Heap::CollectGarbage(GarbageCollector collector, bool next_gc_likely_to_collect_more = false; - { GCTracer tracer(this, gc_reason, collector_reason); + { GCTracer tracer(this, collector, gc_reason, collector_reason); ASSERT(AllowHeapAllocation::IsAllowed()); DisallowHeapAllocation no_allocation_during_gc; GarbageCollectionPrologue(); - // The GC count was incremented in the prologue. Tell the tracer about - // it. - tracer.set_gc_count(gc_count_); - - // Tell the tracer which collector we've selected. - tracer.set_collector(collector); { HistogramTimerScope histogram_timer_scope( @@ -1205,7 +1199,6 @@ void Heap::MarkCompact(GCTracer* tracer) { mark_compact_collector_.Prepare(tracer); ms_count_++; - tracer->set_full_gc_count(ms_count_); MarkCompactPrologue(); @@ -5956,14 +5949,40 @@ static intptr_t CountTotalHolesSize(Heap* heap) { } +void Heap::UpdateGCStatistics(double start_time, + double end_time, + double spent_in_mutator, + double marking_time) { + double duration = end_time - start_time; + alive_after_last_gc_ = SizeOfObjects(); + bool first_gc = (last_gc_end_timestamp_ == 0); + last_gc_end_timestamp_ = end_time; + + if (FLAG_print_cumulative_gc_stat) { + total_gc_time_ms_ += duration; + max_gc_pause_ = Max(max_gc_pause_, duration); + max_alive_after_gc_ = Max(max_alive_after_gc_, alive_after_last_gc_); + if (!first_gc) + min_in_mutator_ = Min(min_in_mutator_, spent_in_mutator); + } else if (FLAG_trace_gc_verbose) { + total_gc_time_ms_ += duration; + } + + marking_time_ += marking_time; +} + + GCTracer::GCTracer(Heap* heap, + GarbageCollector collector, const char* gc_reason, const char* collector_reason) : start_time_(0.0), + end_time_(0.0), start_object_size_(0), + end_object_size_(0), start_memory_size_(0), - gc_count_(0), - full_gc_count_(0), + end_memory_size_(0), + collector_(collector), allocated_since_last_gc_(0), spent_in_mutator_(0), nodes_died_in_new_space_(0), @@ -5973,11 +5992,12 @@ GCTracer::GCTracer(Heap* heap, gc_reason_(gc_reason), collector_reason_(collector_reason) { if (!FLAG_trace_gc && !FLAG_print_cumulative_gc_stat) return; + start_time_ = base::OS::TimeCurrentMillis(); start_object_size_ = heap_->SizeOfObjects(); start_memory_size_ = heap_->isolate()->memory_allocator()->Size(); - for (int i = 0; i < Scope::kNumberOfScopes; i++) { + for (int i = 0; i < Scope::NUMBER_OF_SCOPES; i++) { scopes_[i] = 0; } @@ -6001,146 +6021,140 @@ GCTracer::GCTracer(Heap* heap, GCTracer::~GCTracer() { - // Printf ONE line iff flag is set. if (!FLAG_trace_gc && !FLAG_print_cumulative_gc_stat) return; - bool first_gc = (heap_->last_gc_end_timestamp_ == 0); + end_time_ = base::OS::TimeCurrentMillis(); + end_object_size_ = heap_->SizeOfObjects(); + end_memory_size_ = heap_->isolate()->memory_allocator()->Size(); - heap_->alive_after_last_gc_ = heap_->SizeOfObjects(); - heap_->last_gc_end_timestamp_ = base::OS::TimeCurrentMillis(); + heap_->UpdateGCStatistics(start_time_, + end_time_, + spent_in_mutator_, + scopes_[Scope::MC_MARK]); - double time = heap_->last_gc_end_timestamp_ - start_time_; + if (collector_ == SCAVENGER && FLAG_trace_gc_ignore_scavenger) return; - // Update cumulative GC statistics if required. - if (FLAG_print_cumulative_gc_stat) { - heap_->total_gc_time_ms_ += time; - heap_->max_gc_pause_ = Max(heap_->max_gc_pause_, time); - heap_->max_alive_after_gc_ = Max(heap_->max_alive_after_gc_, - heap_->alive_after_last_gc_); - if (!first_gc) { - heap_->min_in_mutator_ = Min(heap_->min_in_mutator_, - spent_in_mutator_); - } - } else if (FLAG_trace_gc_verbose) { - heap_->total_gc_time_ms_ += time; - } + if (FLAG_trace_gc) { + if (FLAG_trace_gc_nvp) + PrintNVP(); + else + Print(); - if (collector_ == SCAVENGER && FLAG_trace_gc_ignore_scavenger) return; + heap_->PrintShortHeapStatistics(); + } +} - heap_->AddMarkingTime(scopes_[Scope::MC_MARK]); - if (FLAG_print_cumulative_gc_stat && !FLAG_trace_gc) return; +void GCTracer::Print() const { PrintPID("%8.0f ms: ", heap_->isolate()->time_millis_since_init()); - if (!FLAG_trace_gc_nvp) { - int external_time = static_cast(scopes_[Scope::EXTERNAL]); - - double end_memory_size_mb = - static_cast(heap_->isolate()->memory_allocator()->Size()) / MB; - - PrintF("%s %.1f (%.1f) -> %.1f (%.1f) MB, ", - CollectorString(), - static_cast(start_object_size_) / MB, - static_cast(start_memory_size_) / MB, - SizeOfHeapObjects(), - end_memory_size_mb); - - if (external_time > 0) PrintF("%d / ", external_time); - PrintF("%.1f ms", time); - if (steps_count_ > 0) { - if (collector_ == SCAVENGER) { - PrintF(" (+ %.1f ms in %d steps since last GC)", - steps_took_since_last_gc_, - steps_count_since_last_gc_); - } else { - PrintF(" (+ %.1f ms in %d steps since start of marking, " - "biggest step %.1f ms)", - steps_took_, - steps_count_, - longest_step_); - } - } + PrintF("%s %.1f (%.1f) -> %.1f (%.1f) MB, ", + CollectorString(), + static_cast(start_object_size_) / MB, + static_cast(start_memory_size_) / MB, + static_cast(end_object_size_) / MB, + static_cast(end_memory_size_) / MB); - if (gc_reason_ != NULL) { - PrintF(" [%s]", gc_reason_); - } - - if (collector_reason_ != NULL) { - PrintF(" [%s]", collector_reason_); - } - - PrintF(".\n"); - } else { - PrintF("pause=%.1f ", time); - PrintF("mutator=%.1f ", spent_in_mutator_); - PrintF("gc="); - switch (collector_) { - case SCAVENGER: - PrintF("s"); - break; - case MARK_COMPACTOR: - PrintF("ms"); - break; - default: - UNREACHABLE(); - } - PrintF(" "); - - PrintF("external=%.1f ", scopes_[Scope::EXTERNAL]); - PrintF("mark=%.1f ", scopes_[Scope::MC_MARK]); - PrintF("sweep=%.2f ", scopes_[Scope::MC_SWEEP]); - PrintF("sweepns=%.2f ", scopes_[Scope::MC_SWEEP_NEWSPACE]); - PrintF("sweepos=%.2f ", scopes_[Scope::MC_SWEEP_OLDSPACE]); - PrintF("sweepcode=%.2f ", scopes_[Scope::MC_SWEEP_CODE]); - PrintF("sweepcell=%.2f ", scopes_[Scope::MC_SWEEP_CELL]); - PrintF("sweepmap=%.2f ", scopes_[Scope::MC_SWEEP_MAP]); - PrintF("evacuate=%.1f ", scopes_[Scope::MC_EVACUATE_PAGES]); - PrintF("new_new=%.1f ", scopes_[Scope::MC_UPDATE_NEW_TO_NEW_POINTERS]); - PrintF("root_new=%.1f ", scopes_[Scope::MC_UPDATE_ROOT_TO_NEW_POINTERS]); - PrintF("old_new=%.1f ", scopes_[Scope::MC_UPDATE_OLD_TO_NEW_POINTERS]); - PrintF("compaction_ptrs=%.1f ", - scopes_[Scope::MC_UPDATE_POINTERS_TO_EVACUATED]); - PrintF("intracompaction_ptrs=%.1f ", - scopes_[Scope::MC_UPDATE_POINTERS_BETWEEN_EVACUATED]); - PrintF("misc_compaction=%.1f ", scopes_[Scope::MC_UPDATE_MISC_POINTERS]); - PrintF("weakcollection_process=%.1f ", - scopes_[Scope::MC_WEAKCOLLECTION_PROCESS]); - PrintF("weakcollection_clear=%.1f ", - scopes_[Scope::MC_WEAKCOLLECTION_CLEAR]); - - PrintF("total_size_before=%" V8_PTR_PREFIX "d ", start_object_size_); - PrintF("total_size_after=%" V8_PTR_PREFIX "d ", heap_->SizeOfObjects()); - PrintF("holes_size_before=%" V8_PTR_PREFIX "d ", - in_free_list_or_wasted_before_gc_); - PrintF("holes_size_after=%" V8_PTR_PREFIX "d ", CountTotalHolesSize(heap_)); - - PrintF("allocated=%" V8_PTR_PREFIX "d ", allocated_since_last_gc_); - PrintF("promoted=%" V8_PTR_PREFIX "d ", heap_->promoted_objects_size_); - PrintF("semi_space_copied=%" V8_PTR_PREFIX "d ", - heap_->semi_space_copied_object_size_); - PrintF("nodes_died_in_new=%d ", nodes_died_in_new_space_); - PrintF("nodes_copied_in_new=%d ", nodes_copied_in_new_space_); - PrintF("nodes_promoted=%d ", nodes_promoted_); - PrintF("promotion_rate=%.1f%% ", heap_->promotion_rate_); - PrintF("semi_space_copy_rate=%.1f%% ", heap_->semi_space_copied_rate_); + int external_time = static_cast(scopes_[Scope::EXTERNAL]); + if (external_time > 0) PrintF("%d / ", external_time); + PrintF("%.1f ms", end_time_ - start_time_); + if (steps_count_ > 0) { if (collector_ == SCAVENGER) { - PrintF("stepscount=%d ", steps_count_since_last_gc_); - PrintF("stepstook=%.1f ", steps_took_since_last_gc_); + PrintF(" (+ %.1f ms in %d steps since last GC)", + steps_took_since_last_gc_, + steps_count_since_last_gc_); } else { - PrintF("stepscount=%d ", steps_count_); - PrintF("stepstook=%.1f ", steps_took_); - PrintF("longeststep=%.1f ", longest_step_); + PrintF(" (+ %.1f ms in %d steps since start of marking, " + "biggest step %.1f ms)", + steps_took_, + steps_count_, + longest_step_); } + } - PrintF("\n"); + if (gc_reason_ != NULL) { + PrintF(" [%s]", gc_reason_); + } + + if (collector_reason_ != NULL) { + PrintF(" [%s]", collector_reason_); + } + + PrintF(".\n"); +} + + +void GCTracer::PrintNVP() const { + PrintPID("%8.0f ms: ", heap_->isolate()->time_millis_since_init()); + + PrintF("pause=%.1f ", end_time_ - start_time_); + PrintF("mutator=%.1f ", spent_in_mutator_); + PrintF("gc="); + switch (collector_) { + case SCAVENGER: + PrintF("s"); + break; + case MARK_COMPACTOR: + PrintF("ms"); + break; + default: + UNREACHABLE(); + } + PrintF(" "); + + PrintF("external=%.1f ", scopes_[Scope::EXTERNAL]); + PrintF("mark=%.1f ", scopes_[Scope::MC_MARK]); + PrintF("sweep=%.2f ", scopes_[Scope::MC_SWEEP]); + PrintF("sweepns=%.2f ", scopes_[Scope::MC_SWEEP_NEWSPACE]); + PrintF("sweepos=%.2f ", scopes_[Scope::MC_SWEEP_OLDSPACE]); + PrintF("sweepcode=%.2f ", scopes_[Scope::MC_SWEEP_CODE]); + PrintF("sweepcell=%.2f ", scopes_[Scope::MC_SWEEP_CELL]); + PrintF("sweepmap=%.2f ", scopes_[Scope::MC_SWEEP_MAP]); + PrintF("evacuate=%.1f ", scopes_[Scope::MC_EVACUATE_PAGES]); + PrintF("new_new=%.1f ", scopes_[Scope::MC_UPDATE_NEW_TO_NEW_POINTERS]); + PrintF("root_new=%.1f ", scopes_[Scope::MC_UPDATE_ROOT_TO_NEW_POINTERS]); + PrintF("old_new=%.1f ", scopes_[Scope::MC_UPDATE_OLD_TO_NEW_POINTERS]); + PrintF("compaction_ptrs=%.1f ", + scopes_[Scope::MC_UPDATE_POINTERS_TO_EVACUATED]); + PrintF("intracompaction_ptrs=%.1f ", + scopes_[Scope::MC_UPDATE_POINTERS_BETWEEN_EVACUATED]); + PrintF("misc_compaction=%.1f ", scopes_[Scope::MC_UPDATE_MISC_POINTERS]); + PrintF("weakcollection_process=%.1f ", + scopes_[Scope::MC_WEAKCOLLECTION_PROCESS]); + PrintF("weakcollection_clear=%.1f ", + scopes_[Scope::MC_WEAKCOLLECTION_CLEAR]); + + PrintF("total_size_before=%" V8_PTR_PREFIX "d ", start_object_size_); + PrintF("total_size_after=%" V8_PTR_PREFIX "d ", end_object_size_); + PrintF("holes_size_before=%" V8_PTR_PREFIX "d ", + in_free_list_or_wasted_before_gc_); + PrintF("holes_size_after=%" V8_PTR_PREFIX "d ", CountTotalHolesSize(heap_)); + + PrintF("allocated=%" V8_PTR_PREFIX "d ", allocated_since_last_gc_); + PrintF("promoted=%" V8_PTR_PREFIX "d ", heap_->promoted_objects_size_); + PrintF("semi_space_copied=%" V8_PTR_PREFIX "d ", + heap_->semi_space_copied_object_size_); + PrintF("nodes_died_in_new=%d ", nodes_died_in_new_space_); + PrintF("nodes_copied_in_new=%d ", nodes_copied_in_new_space_); + PrintF("nodes_promoted=%d ", nodes_promoted_); + PrintF("promotion_rate=%.1f%% ", heap_->promotion_rate_); + PrintF("semi_space_copy_rate=%.1f%% ", heap_->semi_space_copied_rate_); + + if (collector_ == SCAVENGER) { + PrintF("stepscount=%d ", steps_count_since_last_gc_); + PrintF("stepstook=%.1f ", steps_took_since_last_gc_); + } else { + PrintF("stepscount=%d ", steps_count_); + PrintF("stepstook=%.1f ", steps_took_); + PrintF("longeststep=%.1f ", longest_step_); } - heap_->PrintShortHeapStatistics(); + PrintF("\n"); } -const char* GCTracer::CollectorString() { +const char* GCTracer::CollectorString() const { switch (collector_) { case SCAVENGER: return "Scavenge"; diff --git a/src/heap.h b/src/heap.h index a6a14f6..9eaa6ab 100644 --- a/src/heap.h +++ b/src/heap.h @@ -1236,6 +1236,12 @@ class Heap { } } + // Update GC statistics that are tracked on the Heap. + void UpdateGCStatistics(double start_time, + double end_time, + double spent_in_mutator, + double marking_time); + // Returns maximum GC pause. double get_max_gc_pause() { return max_gc_pause_; } @@ -2535,7 +2541,7 @@ class GCTracer BASE_EMBEDDED { MC_WEAKCOLLECTION_PROCESS, MC_WEAKCOLLECTION_CLEAR, MC_FLUSH_CODE, - kNumberOfScopes + NUMBER_OF_SCOPES }; Scope(GCTracer* tracer, ScopeId scope) @@ -2545,7 +2551,7 @@ class GCTracer BASE_EMBEDDED { } ~Scope() { - ASSERT(scope_ < kNumberOfScopes); // scope_ is unsigned. + ASSERT(scope_ < NUMBER_OF_SCOPES); // scope_ is unsigned. tracer_->scopes_[scope_] += base::OS::TimeCurrentMillis() - start_time_; } @@ -2553,22 +2559,16 @@ class GCTracer BASE_EMBEDDED { GCTracer* tracer_; ScopeId scope_; double start_time_; + + DISALLOW_COPY_AND_ASSIGN(Scope); }; explicit GCTracer(Heap* heap, + GarbageCollector collector, const char* gc_reason, const char* collector_reason); ~GCTracer(); - // Sets the collector. - void set_collector(GarbageCollector collector) { collector_ = collector; } - - // Sets the GC count. - void set_gc_count(unsigned int count) { gc_count_ = count; } - - // Sets the full GC count. - void set_full_gc_count(int count) { full_gc_count_ = count; } - void increment_nodes_died_in_new_space() { nodes_died_in_new_space_++; } @@ -2583,32 +2583,37 @@ class GCTracer BASE_EMBEDDED { private: // Returns a string matching the collector. - const char* CollectorString(); + const char* CollectorString() const; + + // Print one detailed trace line in name=value format. + void PrintNVP() const; - // Returns size of object in heap (in MB). - inline double SizeOfHeapObjects(); + // Print one trace line. + void Print() const; // Timestamp set in the constructor. double start_time_; + // Timestamp set in the destructor. + double end_time_; + // Size of objects in heap set in constructor. intptr_t start_object_size_; + // Size of objects in heap set in destructor. + intptr_t end_object_size_; + // Size of memory allocated from OS set in constructor. intptr_t start_memory_size_; + // Size of memory allocated from OS set in destructor. + intptr_t end_memory_size_; + // Type of collector. GarbageCollector collector_; - // A count (including this one, e.g. the first collection is 1) of the - // number of garbage collections. - unsigned int gc_count_; - - // A count (including this one) of the number of full garbage collections. - int full_gc_count_; - // Amounts of time spent in different scopes during GC. - double scopes_[Scope::kNumberOfScopes]; + double scopes_[Scope::NUMBER_OF_SCOPES]; // Total amount of space either wasted or contained in one of free lists // before the current GC. @@ -2642,6 +2647,8 @@ class GCTracer BASE_EMBEDDED { const char* gc_reason_; const char* collector_reason_; + + DISALLOW_COPY_AND_ASSIGN(GCTracer); };