Merge "Timing logger clean-up" into dalvik-dev
diff --git a/runtime/base/mutex-inl.h b/runtime/base/mutex-inl.h
index 1337dff..7f3b459 100644
--- a/runtime/base/mutex-inl.h
+++ b/runtime/base/mutex-inl.h
@@ -40,29 +40,25 @@
class ScopedContentionRecorder {
public:
-#if CONTENTION_LOGGING
- ScopedContentionRecorder(BaseMutex* mutex, uint64_t blocked_tid, uint64_t owner_tid) :
- mutex_(mutex), blocked_tid_(blocked_tid), owner_tid_(owner_tid),
- start_milli_time_(MilliTime()) {
+ ScopedContentionRecorder(BaseMutex* mutex, uint64_t blocked_tid, uint64_t owner_tid)
+ : mutex_(kLogLockContentions ? mutex : NULL),
+ blocked_tid_(kLogLockContentions ? blocked_tid : 0),
+ owner_tid_(kLogLockContentions ? owner_tid : 0),
+ start_nano_time_(kLogLockContentions ? NanoTime() : 0) {
}
-#else
- ScopedContentionRecorder(BaseMutex*, uint64_t, uint64_t) {}
-#endif
~ScopedContentionRecorder() {
-#if CONTENTION_LOGGING
- uint64_t end_milli_time = MilliTime();
- mutex_->RecordContention(blocked_tid_, owner_tid_, end_milli_time - start_milli_time_);
-#endif
+ if (kLogLockContentions) {
+ uint64_t end_nano_time = NanoTime();
+ mutex_->RecordContention(blocked_tid_, owner_tid_, end_nano_time - start_nano_time_);
+ }
}
private:
-#if CONTENTION_LOGGING
BaseMutex* const mutex_;
const uint64_t blocked_tid_;
const uint64_t owner_tid_;
- const uint64_t start_milli_time_;
-#endif
+ const uint64_t start_nano_time_;
};
static inline uint64_t SafeGetTid(const Thread* self) {
diff --git a/runtime/base/mutex.cc b/runtime/base/mutex.cc
index d822eed..3007978 100644
--- a/runtime/base/mutex.cc
+++ b/runtime/base/mutex.cc
@@ -19,6 +19,7 @@
#include <errno.h>
#include <sys/time.h>
+#include "atomic.h"
#include "base/logging.h"
#include "cutils/atomic.h"
#include "cutils/atomic-inline.h"
@@ -94,59 +95,78 @@
}
#endif
-#if CONTENTION_LOGGING
-// A guard for all_mutexes_ that's not a mutex (Mutexes must CAS to acquire and busy wait).
-static AtomicInteger all_mutexes_guard_;
-// All created mutexes guarded by all_mutexes_guard_.
-std::set<BaseMutex*>* all_mutexes_;
+struct AllMutexData {
+ // A guard for all_mutexes_ that's not a mutex (Mutexes must CAS to acquire and busy wait).
+ AtomicInteger all_mutexes_guard;
+ // All created mutexes guarded by all_mutexes_guard_.
+ std::set<BaseMutex*>* all_mutexes;
+ AllMutexData() : all_mutexes(NULL) {}
+};
+static struct AllMutexData all_mutex_data[kAllMutexDataSize];
class ScopedAllMutexesLock {
public:
explicit ScopedAllMutexesLock(const BaseMutex* mutex) : mutex_(mutex) {
- while (!all_mutexes_guard_.CompareAndSwap(0, reinterpret_cast<int32_t>(mutex))) {
+ while (!all_mutex_data->all_mutexes_guard.compare_and_swap(0, reinterpret_cast<int32_t>(mutex))) {
NanoSleep(100);
}
}
~ScopedAllMutexesLock() {
- while (!all_mutexes_guard_.CompareAndSwap(reinterpret_cast<int32_t>(mutex_), 0)) {
+ while (!all_mutex_data->all_mutexes_guard.compare_and_swap(reinterpret_cast<int32_t>(mutex_), 0)) {
NanoSleep(100);
}
}
private:
const BaseMutex* const mutex_;
};
-#endif
BaseMutex::BaseMutex(const char* name, LockLevel level) : level_(level), name_(name) {
-#if CONTENTION_LOGGING
- ScopedAllMutexesLock mu(this);
- if (all_mutexes_ == NULL) {
- // We leak the global set of all mutexes to avoid ordering issues in global variable
- // construction/destruction.
- all_mutexes_ = new std::set<BaseMutex*>();
+ if (kLogLockContentions) {
+ ScopedAllMutexesLock mu(this);
+ std::set<BaseMutex*>** all_mutexes_ptr = &all_mutex_data->all_mutexes;
+ if (*all_mutexes_ptr == NULL) {
+ // We leak the global set of all mutexes to avoid ordering issues in global variable
+ // construction/destruction.
+ *all_mutexes_ptr = new std::set<BaseMutex*>();
+ }
+ (*all_mutexes_ptr)->insert(this);
}
- all_mutexes_->insert(this);
-#endif
}
BaseMutex::~BaseMutex() {
-#if CONTENTION_LOGGING
- ScopedAllMutexesLock mu(this);
- all_mutexes_->erase(this);
-#endif
+ if (kLogLockContentions) {
+ ScopedAllMutexesLock mu(this);
+ all_mutex_data->all_mutexes->erase(this);
+ }
}
void BaseMutex::DumpAll(std::ostream& os) {
-#if CONTENTION_LOGGING
- os << "Mutex logging:\n";
- ScopedAllMutexesLock mu(reinterpret_cast<const BaseMutex*>(-1));
- typedef std::set<BaseMutex*>::const_iterator It;
- for (It it = all_mutexes_->begin(); it != all_mutexes_->end(); ++it) {
- BaseMutex* mutex = *it;
- mutex->Dump(os);
- os << "\n";
+ if (kLogLockContentions) {
+ os << "Mutex logging:\n";
+ ScopedAllMutexesLock mu(reinterpret_cast<const BaseMutex*>(-1));
+ std::set<BaseMutex*>* all_mutexes = all_mutex_data->all_mutexes;
+ if (all_mutexes == NULL) {
+ // No mutexes have been created yet during at startup.
+ return;
+ }
+ typedef std::set<BaseMutex*>::const_iterator It;
+ os << "(Contented)\n";
+ for (It it = all_mutexes->begin(); it != all_mutexes->end(); ++it) {
+ BaseMutex* mutex = *it;
+ if (mutex->HasEverContended()) {
+ mutex->Dump(os);
+ os << "\n";
+ }
+ }
+ os << "(Never contented)\n";
+ for (It it = all_mutexes->begin(); it != all_mutexes->end(); ++it) {
+ BaseMutex* mutex = *it;
+ if (!mutex->HasEverContended()) {
+ mutex->Dump(os);
+ os << "\n";
+ }
+ }
}
-#endif
}
void BaseMutex::CheckSafeToWait(Thread* self) {
@@ -172,85 +192,102 @@
}
}
+inline void BaseMutex::ContentionLogData::AddToWaitTime(uint64_t value) {
+ if (kLogLockContentions) {
+ // Atomically add value to wait_time.
+ uint64_t new_val, old_val;
+ volatile int64_t* addr = reinterpret_cast<volatile int64_t*>(&wait_time);
+ volatile const int64_t* caddr = const_cast<volatile const int64_t*>(addr);
+ do {
+ old_val = static_cast<uint64_t>(QuasiAtomic::Read64(caddr));
+ new_val = old_val + value;
+ } while (!QuasiAtomic::Cas64(static_cast<int64_t>(old_val), static_cast<int64_t>(new_val), addr));
+ }
+}
+
void BaseMutex::RecordContention(uint64_t blocked_tid,
uint64_t owner_tid,
- uint64_t milli_time_blocked) {
-#if CONTENTION_LOGGING
- ++contention_count_;
- wait_time_ += static_cast<uint32_t>(milli_time_blocked); // May overflow.
- // This code is intentionally racy as it is only used for diagnostics.
- uint32_t slot = cur_content_log_entry_;
- if (contention_log_[slot].blocked_tid == blocked_tid &&
- contention_log_[slot].owner_tid == blocked_tid) {
- ++contention_log_[slot].count;
- } else {
- uint32_t new_slot;
- do {
- slot = cur_content_log_entry_;
- new_slot = (slot + 1) % kContentionLogSize;
- } while (!cur_content_log_entry_.CompareAndSwap(slot, new_slot));
- contention_log_[new_slot].blocked_tid = blocked_tid;
- contention_log_[new_slot].owner_tid = owner_tid;
- contention_log_[new_slot].count = 1;
+ uint64_t nano_time_blocked) {
+ if (kLogLockContentions) {
+ ContentionLogData* data = contetion_log_data_;
+ ++(data->contention_count);
+ data->AddToWaitTime(nano_time_blocked);
+ ContentionLogEntry* log = data->contention_log;
+ // This code is intentionally racy as it is only used for diagnostics.
+ uint32_t slot = data->cur_content_log_entry;
+ if (log[slot].blocked_tid == blocked_tid &&
+ log[slot].owner_tid == blocked_tid) {
+ ++log[slot].count;
+ } else {
+ uint32_t new_slot;
+ do {
+ slot = data->cur_content_log_entry;
+ new_slot = (slot + 1) % kContentionLogSize;
+ } while (!data->cur_content_log_entry.compare_and_swap(slot, new_slot));
+ log[new_slot].blocked_tid = blocked_tid;
+ log[new_slot].owner_tid = owner_tid;
+ log[new_slot].count = 1;
+ }
}
-#endif
}
void BaseMutex::DumpContention(std::ostream& os) const {
-#if CONTENTION_LOGGING
- uint32_t wait_time = wait_time_;
- uint32_t contention_count = contention_count_;
- if (contention_count == 0) {
- os << "never contended";
- } else {
- os << "contended " << contention_count
- << " times, average wait of contender " << (wait_time / contention_count) << "ms";
- SafeMap<uint64_t, size_t> most_common_blocker;
- SafeMap<uint64_t, size_t> most_common_blocked;
- typedef SafeMap<uint64_t, size_t>::const_iterator It;
- for (size_t i = 0; i < kContentionLogSize; ++i) {
- uint64_t blocked_tid = contention_log_[i].blocked_tid;
- uint64_t owner_tid = contention_log_[i].owner_tid;
- uint32_t count = contention_log_[i].count;
- if (count > 0) {
- It it = most_common_blocked.find(blocked_tid);
- if (it != most_common_blocked.end()) {
- most_common_blocked.Overwrite(blocked_tid, it->second + count);
- } else {
- most_common_blocked.Put(blocked_tid, count);
- }
- it = most_common_blocker.find(owner_tid);
- if (it != most_common_blocker.end()) {
- most_common_blocker.Overwrite(owner_tid, it->second + count);
- } else {
- most_common_blocker.Put(owner_tid, count);
+ if (kLogLockContentions) {
+ const ContentionLogData* data = contetion_log_data_;
+ const ContentionLogEntry* log = data->contention_log;
+ uint64_t wait_time = data->wait_time;
+ uint32_t contention_count = data->contention_count;
+ if (contention_count == 0) {
+ os << "never contended";
+ } else {
+ os << "contended " << contention_count
+ << " times, average wait of contender " << PrettyDuration(wait_time / contention_count);
+ SafeMap<uint64_t, size_t> most_common_blocker;
+ SafeMap<uint64_t, size_t> most_common_blocked;
+ typedef SafeMap<uint64_t, size_t>::const_iterator It;
+ for (size_t i = 0; i < kContentionLogSize; ++i) {
+ uint64_t blocked_tid = log[i].blocked_tid;
+ uint64_t owner_tid = log[i].owner_tid;
+ uint32_t count = log[i].count;
+ if (count > 0) {
+ It it = most_common_blocked.find(blocked_tid);
+ if (it != most_common_blocked.end()) {
+ most_common_blocked.Overwrite(blocked_tid, it->second + count);
+ } else {
+ most_common_blocked.Put(blocked_tid, count);
+ }
+ it = most_common_blocker.find(owner_tid);
+ if (it != most_common_blocker.end()) {
+ most_common_blocker.Overwrite(owner_tid, it->second + count);
+ } else {
+ most_common_blocker.Put(owner_tid, count);
+ }
}
}
- }
- uint64_t max_tid = 0;
- size_t max_tid_count = 0;
- for (It it = most_common_blocked.begin(); it != most_common_blocked.end(); ++it) {
- if (it->second > max_tid_count) {
- max_tid = it->first;
- max_tid_count = it->second;
+ uint64_t max_tid = 0;
+ size_t max_tid_count = 0;
+ for (It it = most_common_blocked.begin(); it != most_common_blocked.end(); ++it) {
+ if (it->second > max_tid_count) {
+ max_tid = it->first;
+ max_tid_count = it->second;
+ }
}
- }
- if (max_tid != 0) {
- os << " sample shows most blocked tid=" << max_tid;
- }
- max_tid = 0;
- max_tid_count = 0;
- for (It it = most_common_blocker.begin(); it != most_common_blocker.end(); ++it) {
- if (it->second > max_tid_count) {
- max_tid = it->first;
- max_tid_count = it->second;
+ if (max_tid != 0) {
+ os << " sample shows most blocked tid=" << max_tid;
}
- }
- if (max_tid != 0) {
- os << " sample shows tid=" << max_tid << " owning during this time";
+ max_tid = 0;
+ max_tid_count = 0;
+ for (It it = most_common_blocker.begin(); it != most_common_blocker.end(); ++it) {
+ if (it->second > max_tid_count) {
+ max_tid = it->first;
+ max_tid_count = it->second;
+ }
+ }
+ if (max_tid != 0) {
+ os << " sample shows tid=" << max_tid << " owning during this time";
+ }
}
}
-#endif
}
diff --git a/runtime/base/mutex.h b/runtime/base/mutex.h
index 2f41bcd..0e5445f 100644
--- a/runtime/base/mutex.h
+++ b/runtime/base/mutex.h
@@ -23,6 +23,7 @@
#include <iosfwd>
#include <string>
+#include "atomic_integer.h"
#include "base/logging.h"
#include "base/macros.h"
#include "globals.h"
@@ -41,13 +42,6 @@
#define HAVE_TIMED_RWLOCK 0
#endif
-// Record Log contention information, dumpable via SIGQUIT.
-#define CONTENTION_LOGGING (0 && ART_USE_FUTEXES)
-const size_t kContentionLogSize = 64;
-#if CONTENTION_LOGGING
-#include "atomic_integer.h"
-#endif
-
namespace art {
class ScopedContentionRecorder;
@@ -55,6 +49,19 @@
const bool kDebugLocking = true || kIsDebugBuild;
+// Record Log contention information, dumpable via SIGQUIT.
+#ifdef ART_USE_FUTEXES
+// To enable lock contention logging, flip this to true.
+const bool kLogLockContentions = false;
+#else
+// Keep this false as lock contention logging is supported only with
+// futex.
+const bool kLogLockContentions = false;
+#endif
+const size_t kContentionLogSize = 64;
+const size_t kContentionLogDataSize = kLogLockContentions ? 1 : 0;
+const size_t kAllMutexDataSize = kLogLockContentions ? 1 : 0;
+
// Base class for all Mutex implementations
class BaseMutex {
public:
@@ -80,12 +87,12 @@
friend class ScopedContentionRecorder;
- void RecordContention(uint64_t blocked_tid, uint64_t owner_tid, uint64_t milli_time_blocked);
+ void RecordContention(uint64_t blocked_tid, uint64_t owner_tid, uint64_t nano_time_blocked);
void DumpContention(std::ostream& os) const;
const LockLevel level_; // Support for lock hierarchy.
const char* const name_;
-#if CONTENTION_LOGGING
+
// A log entry that records contention but makes no guarantee that either tid will be held live.
struct ContentionLogEntry {
ContentionLogEntry() : blocked_tid(0), owner_tid(0) {}
@@ -93,15 +100,27 @@
uint64_t owner_tid;
AtomicInteger count;
};
- ContentionLogEntry contention_log_[kContentionLogSize];
- // The next entry in the contention log to be updated. Value ranges from 0 to
- // kContentionLogSize - 1.
- AtomicInteger cur_content_log_entry_;
- // Number of times the Mutex has been contended.
- AtomicInteger contention_count_;
- // Sum of time waited by all contenders in ms.
- AtomicInteger wait_time_;
-#endif
+ struct ContentionLogData {
+ ContentionLogEntry contention_log[kContentionLogSize];
+ // The next entry in the contention log to be updated. Value ranges from 0 to
+ // kContentionLogSize - 1.
+ AtomicInteger cur_content_log_entry;
+ // Number of times the Mutex has been contended.
+ AtomicInteger contention_count;
+ // Sum of time waited by all contenders in ns.
+ volatile uint64_t wait_time;
+ void AddToWaitTime(uint64_t value);
+ ContentionLogData() : wait_time(0) {}
+ };
+ ContentionLogData contetion_log_data_[kContentionLogDataSize];
+
+ public:
+ bool HasEverContended() const {
+ if (kLogLockContentions) {
+ return contetion_log_data_->contention_count > 0;
+ }
+ return false;
+ }
};
// A Mutex is used to achieve mutual exclusion between threads. A Mutex can be used to gain