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
diff --git a/runtime/base/histogram-inl.h b/runtime/base/histogram-inl.h
index b329a31..812ed86 100644
--- a/runtime/base/histogram-inl.h
+++ b/runtime/base/histogram-inl.h
@@ -35,10 +35,13 @@
DCHECK_GT(new_max, max_);
GrowBuckets(new_max);
}
-
BucketiseValue(value);
}
+template <class Value> inline void Histogram<Value>::AdjustAndAddValue(Value value) {
+ AddValue(value / kAdjust);
+}
+
template <class Value> inline Histogram<Value>::Histogram(const char* name)
: kAdjust(0),
kInitialBucketCount(0),
diff --git a/runtime/base/histogram.h b/runtime/base/histogram.h
index 1e12be8..78f6e1c 100644
--- a/runtime/base/histogram.h
+++ b/runtime/base/histogram.h
@@ -46,6 +46,7 @@
// 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 9e6a800..8be18be 100644
--- a/runtime/gc/collector/garbage_collector.cc
+++ b/runtime/gc/collector/garbage_collector.cc
@@ -102,7 +102,7 @@
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 0587bb5..d27e282 100644
--- a/runtime/gc/heap.cc
+++ b/runtime/gc/heap.cc
@@ -859,7 +859,7 @@
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 65a8bd0..968e89d 100644
--- a/runtime/thread_list.cc
+++ b/runtime/thread_list.cc
@@ -27,6 +27,7 @@
#include <sstream>
+#include "base/histogram-inl.h"
#include "base/mutex.h"
#include "base/mutex-inl.h"
#include "base/timing_logger.h"
@@ -46,7 +47,8 @@
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::DumpForSigQuit(std::ostream& os) {
+ {
+ ScopedObjectAccess soa(Thread::Current());
+ Histogram<uint64_t>::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 @@
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 @@
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 13684c7..43c065a 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 @@
~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 @@
// 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<uint64_t> suspend_all_historam_ GUARDED_BY(Locks::mutator_lock_);
+
friend class Thread;
DISALLOW_COPY_AND_ASSIGN(ThreadList);