From 70a596d61f8cf5b6447326c46c3386e0fbd5bfb5 Mon Sep 17 00:00:00 2001 From: Mathieu Chartier Date: Wed, 17 Dec 2014 14:56:47 -0800 Subject: [PATCH] Add thread suspend histogram Helps measure time to suspend. Example output (maps after a few seconds): suspend all histogram: Sum: 2.806ms 99% C.I. 2us-1090.560us Avg: 43.843us Max: 1126us Change-Id: I7bd9dd3b401fb3e3059e8718556d60910e541611 --- runtime/base/histogram-inl.h | 5 ++++- runtime/base/histogram.h | 1 + runtime/gc/collector/garbage_collector.cc | 2 +- runtime/gc/heap.cc | 2 +- runtime/thread_list.cc | 20 +++++++++++++++----- runtime/thread_list.h | 10 +++++++--- 6 files changed, 29 insertions(+), 11 deletions(-) diff --git a/runtime/base/histogram-inl.h b/runtime/base/histogram-inl.h index b329a31b1..812ed86e4 100644 --- a/runtime/base/histogram-inl.h +++ b/runtime/base/histogram-inl.h @@ -35,10 +35,13 @@ template inline void Histogram::AddValue(Value value) { DCHECK_GT(new_max, max_); GrowBuckets(new_max); } - BucketiseValue(value); } +template inline void Histogram::AdjustAndAddValue(Value value) { + AddValue(value / kAdjust); +} + template inline Histogram::Histogram(const char* name) : kAdjust(0), kInitialBucketCount(0), diff --git a/runtime/base/histogram.h b/runtime/base/histogram.h index 1e12be8c3..78f6e1c7c 100644 --- a/runtime/base/histogram.h +++ b/runtime/base/histogram.h @@ -46,6 +46,7 @@ template class Histogram { // This is the expected constructor when creating new Histograms. Histogram(const char* name, Value initial_bucket_width, size_t max_buckets = 100); void AddValue(Value); + void AdjustAndAddValue(Value); // Add a value after dividing it by kAdjust. // Builds the cumulative distribution function from the frequency data. // Accumulative summation of frequencies. // cumulative_freq[i] = sum(frequency[j] : 0 < j < i ) diff --git a/runtime/gc/collector/garbage_collector.cc b/runtime/gc/collector/garbage_collector.cc index 9e6a8003f..8be18be67 100644 --- a/runtime/gc/collector/garbage_collector.cc +++ b/runtime/gc/collector/garbage_collector.cc @@ -102,7 +102,7 @@ void GarbageCollector::Run(GcCause gc_cause, bool clear_soft_references) { total_time_ns_ += current_iteration->GetDurationNs(); for (uint64_t pause_time : current_iteration->GetPauseTimes()) { MutexLock mu(self, pause_histogram_lock_); - pause_histogram_.AddValue(pause_time / 1000); + pause_histogram_.AdjustAndAddValue(pause_time); } ATRACE_END(); } diff --git a/runtime/gc/heap.cc b/runtime/gc/heap.cc index 0587bb5ab..d27e28277 100644 --- a/runtime/gc/heap.cc +++ b/runtime/gc/heap.cc @@ -859,7 +859,7 @@ void Heap::DumpGcPerformanceInfo(std::ostream& os) { os << "Zygote space size " << PrettySize(zygote_space_->Size()) << "\n"; } os << "Total mutator paused time: " << PrettyDuration(total_paused_time) << "\n"; - os << "Total time waiting for GC to complete: " << PrettyDuration(total_wait_time_) << "\n"; + os << "Total time waiting for GC to complete: " << PrettyDuration(total_wait_time_); BaseMutex::DumpAll(os); } diff --git a/runtime/thread_list.cc b/runtime/thread_list.cc index 65a8bd04a..968e89d1d 100644 --- a/runtime/thread_list.cc +++ b/runtime/thread_list.cc @@ -27,6 +27,7 @@ #include +#include "base/histogram-inl.h" #include "base/mutex.h" #include "base/mutex-inl.h" #include "base/timing_logger.h" @@ -46,7 +47,8 @@ static constexpr uint64_t kLongThreadSuspendThreshold = MsToNs(5); ThreadList::ThreadList() : suspend_all_count_(0), debug_suspend_all_count_(0), - thread_exit_cond_("thread exit condition variable", *Locks::thread_list_lock_) { + thread_exit_cond_("thread exit condition variable", *Locks::thread_list_lock_), + suspend_all_historam_("suspend all histogram", 16, 64) { CHECK(Monitor::IsValidLockWord(LockWord::FromThinLockId(kMaxThreadId, 1))); } @@ -97,6 +99,12 @@ void ThreadList::DumpNativeStacks(std::ostream& os) { } void ThreadList::DumpForSigQuit(std::ostream& os) { + { + ScopedObjectAccess soa(Thread::Current()); + Histogram::CumulativeData data; + suspend_all_historam_.CreateHistogram(&data); + suspend_all_historam_.PrintConfidenceIntervals(os, 0.99, data); // Dump time to suspend. + } Dump(os); DumpUnattachedThreads(os); } @@ -351,7 +359,7 @@ void ThreadList::SuspendAll() { VLOG(threads) << "Thread[null] SuspendAll starting..."; } ATRACE_BEGIN("Suspending mutator threads"); - uint64_t start_time = NanoTime(); + const uint64_t start_time = NanoTime(); Locks::mutator_lock_->AssertNotHeld(self); Locks::thread_list_lock_->AssertNotHeld(self); @@ -384,9 +392,11 @@ void ThreadList::SuspendAll() { Locks::mutator_lock_->ExclusiveLock(self); #endif - uint64_t end_time = NanoTime(); - if (end_time - start_time > kLongThreadSuspendThreshold) { - LOG(WARNING) << "Suspending all threads took: " << PrettyDuration(end_time - start_time); + const uint64_t end_time = NanoTime(); + const uint64_t suspend_time = end_time - start_time; + suspend_all_historam_.AdjustAndAddValue(suspend_time); + if (suspend_time > kLongThreadSuspendThreshold) { + LOG(WARNING) << "Suspending all threads took: " << PrettyDuration(suspend_time); } if (kDebugLocking) { diff --git a/runtime/thread_list.h b/runtime/thread_list.h index 13684c766..43c065ae0 100644 --- a/runtime/thread_list.h +++ b/runtime/thread_list.h @@ -17,6 +17,7 @@ #ifndef ART_RUNTIME_THREAD_LIST_H_ #define ART_RUNTIME_THREAD_LIST_H_ +#include "base/histogram.h" #include "base/mutex.h" #include "jni.h" #include "object_callbacks.h" @@ -39,11 +40,10 @@ class ThreadList { ~ThreadList(); void DumpForSigQuit(std::ostream& os) - LOCKS_EXCLUDED(Locks::thread_list_lock_); + LOCKS_EXCLUDED(Locks::thread_list_lock_, Locks::mutator_lock_); // For thread suspend timeout dumps. void Dump(std::ostream& os) - LOCKS_EXCLUDED(Locks::thread_list_lock_, - Locks::thread_suspend_count_lock_); + LOCKS_EXCLUDED(Locks::thread_list_lock_, Locks::thread_suspend_count_lock_); pid_t GetLockOwner(); // For SignalCatcher. // Thread suspension support. @@ -169,6 +169,10 @@ class ThreadList { // Signaled when threads terminate. Used to determine when all non-daemons have terminated. ConditionVariable thread_exit_cond_ GUARDED_BY(Locks::thread_list_lock_); + // Thread suspend time histogram. Only modified when all the threads are suspended, so guarding + // by mutator lock ensures no thread can read when another thread is modifying it. + Histogram suspend_all_historam_ GUARDED_BY(Locks::mutator_lock_); + friend class Thread; DISALLOW_COPY_AND_ASSIGN(ThreadList); -- 2.11.0