Add histogram for GC pause times.
Printed when you dump the GC performance info.
Bug: 10855285
Change-Id: I3bf7f958305f97c52cb31c03bdd6218c321575b9
diff --git a/runtime/base/histogram-inl.h b/runtime/base/histogram-inl.h
index 4cd68cd..7c09999 100644
--- a/runtime/base/histogram-inl.h
+++ b/runtime/base/histogram-inl.h
@@ -178,7 +178,8 @@
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 d4eb1f4..4e5d29a 100644
--- a/runtime/base/histogram.h
+++ b/runtime/base/histogram.h
@@ -49,7 +49,7 @@
// 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 56d9ef4..cf301fe 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 @@
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::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 @@
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 @@
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 a80f593..1779339 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 @@
}
uint64_t GetTotalPausedTimeNs() const {
- return total_paused_time_ns_;
+ return pause_histogram_.Sum();
}
uint64_t GetTotalFreedBytes() const {
@@ -106,6 +106,10 @@
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 @@
// 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 @@
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 58068b1..0697a65 100644
--- a/runtime/gc/collector/mark_sweep.cc
+++ b/runtime/gc/collector/mark_sweep.cc
@@ -1449,9 +1449,6 @@
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 00794d6..3939354 100644
--- a/runtime/gc/collector/semi_space.cc
+++ b/runtime/gc/collector/semi_space.cc
@@ -584,9 +584,6 @@
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 c31e3e9..ef9d157 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 @@
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 / "