diff options
author | Mathieu Chartier <mathieuc@google.com> | 2013-11-20 17:26:00 -0800 |
---|---|---|
committer | Mathieu Chartier <mathieuc@google.com> | 2013-11-21 12:02:28 -0800 |
commit | b2f9936cab87a187f078187c22d9b29d4a188a62 (patch) | |
tree | 601a1673d4c4aca428d69dff29a80c8f10cad214 | |
parent | dcc5c7598d38fcb555266c8618df720acea3b954 (diff) | |
download | art-b2f9936cab87a187f078187c22d9b29d4a188a62.tar.gz art-b2f9936cab87a187f078187c22d9b29d4a188a62.tar.bz2 art-b2f9936cab87a187f078187c22d9b29d4a188a62.zip |
Add histogram for GC pause times.
Printed when you dump the GC performance info.
Bug: 10855285
Change-Id: I3bf7f958305f97c52cb31c03bdd6218c321575b9
-rw-r--r-- | runtime/base/histogram-inl.h | 3 | ||||
-rw-r--r-- | runtime/base/histogram.h | 2 | ||||
-rw-r--r-- | runtime/gc/collector/garbage_collector.cc | 17 | ||||
-rw-r--r-- | runtime/gc/collector/garbage_collector.h | 15 | ||||
-rw-r--r-- | runtime/gc/collector/mark_sweep.cc | 3 | ||||
-rw-r--r-- | runtime/gc/collector/semi_space.cc | 3 | ||||
-rw-r--r-- | runtime/gc/heap.cc | 5 |
7 files changed, 28 insertions, 20 deletions
diff --git a/runtime/base/histogram-inl.h b/runtime/base/histogram-inl.h index 4cd68cda44..7c0999992e 100644 --- a/runtime/base/histogram-inl.h +++ b/runtime/base/histogram-inl.h @@ -178,7 +178,8 @@ inline void Histogram<Value>::PrintConfidenceIntervals(std::ostream &os, double os << FormatDuration(Max() * kAdjust, unit) << "\n"; } -template <class Value> inline void Histogram<Value>::CreateHistogram(CumulativeData* out_data) { +template <class Value> +inline void Histogram<Value>::CreateHistogram(CumulativeData* out_data) const { DCHECK_GT(sample_size_, 0ull); out_data->freq_.clear(); out_data->perc_.clear(); diff --git a/runtime/base/histogram.h b/runtime/base/histogram.h index d4eb1f41a5..4e5d29a297 100644 --- a/runtime/base/histogram.h +++ b/runtime/base/histogram.h @@ -49,7 +49,7 @@ template <class Value> class Histogram { // cumulative_freq[i] = sum(frequency[j] : 0 < j < i ) // Accumulative summation of percentiles; which is the frequency / SampleSize // cumulative_perc[i] = sum(frequency[j] / SampleSize : 0 < j < i ) - void CreateHistogram(CumulativeData* data); + void CreateHistogram(CumulativeData* data) const; // Reset the cumulative values, next time CreateHistogram is called it will recreate the cache. void Reset(); double Mean() const; diff --git a/runtime/gc/collector/garbage_collector.cc b/runtime/gc/collector/garbage_collector.cc index 56d9ef4d4d..cf301feafe 100644 --- a/runtime/gc/collector/garbage_collector.cc +++ b/runtime/gc/collector/garbage_collector.cc @@ -21,6 +21,7 @@ #include "garbage_collector.h" +#include "base/histogram-inl.h" #include "base/logging.h" #include "base/mutex-inl.h" #include "gc/accounting/heap_bitmap.h" @@ -40,6 +41,7 @@ GarbageCollector::GarbageCollector(Heap* heap, const std::string& name) verbose_(VLOG_IS_ON(heap)), duration_ns_(0), timings_(name_.c_str(), true, verbose_), + pause_histogram_((name_ + " paused").c_str(), kPauseBucketSize, kPauseBucketCount), cumulative_timings_(name) { ResetCumulativeStatistics(); } @@ -55,8 +57,8 @@ void GarbageCollector::RegisterPause(uint64_t nano_length) { void GarbageCollector::ResetCumulativeStatistics() { cumulative_timings_.Reset(); + pause_histogram_.Reset(); total_time_ns_ = 0; - total_paused_time_ns_ = 0; total_freed_objects_ = 0; total_freed_bytes_ = 0; } @@ -86,8 +88,7 @@ void GarbageCollector::Run(bool clear_soft_references) { GetHeap()->RevokeAllThreadLocalBuffers(); thread_list->ResumeAll(); ATRACE_END(); - uint64_t pause_end = NanoTime(); - pause_times_.push_back(pause_end - pause_start); + RegisterPause(NanoTime() - pause_start); } else { Thread* self = Thread::Current(); { @@ -110,18 +111,20 @@ void GarbageCollector::Run(bool clear_soft_references) { ATRACE_BEGIN("Resuming mutator threads"); thread_list->ResumeAll(); ATRACE_END(); - pause_times_.push_back(pause_end - pause_start); + RegisterPause(pause_end - pause_start); } { ReaderMutexLock mu(self, *Locks::mutator_lock_); ReclaimPhase(); } } - + FinishPhase(); uint64_t end_time = NanoTime(); duration_ns_ = end_time - start_time; - - FinishPhase(); + total_time_ns_ += GetDurationNs(); + for (uint64_t pause_time : pause_times_) { + pause_histogram_.AddValue(pause_time / 1000); + } } void GarbageCollector::SwapBitmaps() { diff --git a/runtime/gc/collector/garbage_collector.h b/runtime/gc/collector/garbage_collector.h index a80f5935c2..17793393fe 100644 --- a/runtime/gc/collector/garbage_collector.h +++ b/runtime/gc/collector/garbage_collector.h @@ -17,10 +17,10 @@ #ifndef ART_RUNTIME_GC_COLLECTOR_GARBAGE_COLLECTOR_H_ #define ART_RUNTIME_GC_COLLECTOR_GARBAGE_COLLECTOR_H_ +#include "base/histogram.h" +#include "base/timing_logger.h" #include "gc_type.h" #include "locks.h" -#include "base/timing_logger.h" - #include <stdint.h> #include <vector> @@ -95,7 +95,7 @@ class GarbageCollector { } uint64_t GetTotalPausedTimeNs() const { - return total_paused_time_ns_; + return pause_histogram_.Sum(); } uint64_t GetTotalFreedBytes() const { @@ -106,6 +106,10 @@ class GarbageCollector { return total_freed_objects_; } + const Histogram<uint64_t>& GetPauseHistogram() const { + return pause_histogram_; + } + protected: // The initial phase. Done without mutators paused. virtual void InitializePhase() = 0; @@ -122,6 +126,9 @@ class GarbageCollector { // Called after the GC is finished. Done without mutators paused. virtual void FinishPhase() = 0; + static constexpr size_t kPauseBucketSize = 500; + static constexpr size_t kPauseBucketCount = 32; + Heap* const heap_; std::string name_; @@ -134,8 +141,8 @@ class GarbageCollector { TimingLogger timings_; // Cumulative statistics. + Histogram<uint64_t> pause_histogram_; uint64_t total_time_ns_; - uint64_t total_paused_time_ns_; uint64_t total_freed_objects_; uint64_t total_freed_bytes_; diff --git a/runtime/gc/collector/mark_sweep.cc b/runtime/gc/collector/mark_sweep.cc index 58068b1bcd..0697a6515b 100644 --- a/runtime/gc/collector/mark_sweep.cc +++ b/runtime/gc/collector/mark_sweep.cc @@ -1449,9 +1449,6 @@ void MarkSweep::FinishPhase() { heap->RequestHeapTrim(); // Update the cumulative statistics - total_time_ns_ += GetDurationNs(); - total_paused_time_ns_ += std::accumulate(GetPauseTimes().begin(), GetPauseTimes().end(), 0, - std::plus<uint64_t>()); total_freed_objects_ += GetFreedObjects() + GetFreedLargeObjects(); total_freed_bytes_ += GetFreedBytes() + GetFreedLargeObjectBytes(); diff --git a/runtime/gc/collector/semi_space.cc b/runtime/gc/collector/semi_space.cc index 00794d69bc..393935474a 100644 --- a/runtime/gc/collector/semi_space.cc +++ b/runtime/gc/collector/semi_space.cc @@ -584,9 +584,6 @@ void SemiSpace::FinishPhase() { from_space_ = nullptr; // Update the cumulative statistics - total_time_ns_ += GetDurationNs(); - total_paused_time_ns_ += std::accumulate(GetPauseTimes().begin(), GetPauseTimes().end(), 0, - std::plus<uint64_t>()); total_freed_objects_ += GetFreedObjects() + GetFreedLargeObjects(); total_freed_bytes_ += GetFreedBytes() + GetFreedLargeObjectBytes(); diff --git a/runtime/gc/heap.cc b/runtime/gc/heap.cc index c31e3e982b..ef9d157c50 100644 --- a/runtime/gc/heap.cc +++ b/runtime/gc/heap.cc @@ -23,6 +23,7 @@ #include <vector> #include <valgrind.h> +#include "base/histogram-inl.h" #include "base/stl_util.h" #include "common_throws.h" #include "cutils/sched_policy.h" @@ -558,8 +559,10 @@ void Heap::DumpGcPerformanceInfo(std::ostream& os) { double seconds = NsToMs(logger.GetTotalNs()) / 1000.0; const uint64_t freed_bytes = collector->GetTotalFreedBytes(); const uint64_t freed_objects = collector->GetTotalFreedObjects(); + Histogram<uint64_t>::CumulativeData cumulative_data; + collector->GetPauseHistogram().CreateHistogram(&cumulative_data); + collector->GetPauseHistogram().PrintConfidenceIntervals(os, 0.99, cumulative_data); os << collector->GetName() << " total time: " << PrettyDuration(total_ns) << "\n" - << collector->GetName() << " paused time: " << PrettyDuration(total_pause_ns) << "\n" << collector->GetName() << " freed: " << freed_objects << " objects with total size " << PrettySize(freed_bytes) << "\n" << collector->GetName() << " throughput: " << freed_objects / seconds << "/s / " |