Systrace fixups and refactoring for TimingLogger
Fixed systrace bounds for timing logger in GC. Refactored CumulativeLogger a bit to
allow for multiple identical entries. Added ScopedSplit, now composes with explicit
start/end/new splits. Adds some unit tests.
Bug: 10036801
Change-Id: If0afb88b48ec3a1e19462ed354babb274a9517a7
diff --git a/runtime/base/timing_logger.cc b/runtime/base/timing_logger.cc
index b58b0ac..78a6883 100644
--- a/runtime/base/timing_logger.cc
+++ b/runtime/base/timing_logger.cc
@@ -39,7 +39,7 @@
}
CumulativeLogger::~CumulativeLogger() {
- STLDeleteElements(&histograms_);
+ STLDeleteValues(&histograms_);
}
void CumulativeLogger::SetName(const std::string& name) {
@@ -47,18 +47,17 @@
}
void CumulativeLogger::Start() {
- MutexLock mu(Thread::Current(), lock_);
- index_ = 0;
}
void CumulativeLogger::End() {
MutexLock mu(Thread::Current(), lock_);
iterations_++;
}
+
void CumulativeLogger::Reset() {
MutexLock mu(Thread::Current(), lock_);
iterations_ = 0;
- STLDeleteElements(&histograms_);
+ STLDeleteValues(&histograms_);
}
uint64_t CumulativeLogger::GetTotalNs() const {
@@ -68,36 +67,19 @@
uint64_t CumulativeLogger::GetTotalTime() const {
MutexLock mu(Thread::Current(), lock_);
uint64_t total = 0;
- for (size_t i = 0; i < histograms_.size(); ++i) {
- total += histograms_[i]->Sum();
+ for (CumulativeLogger::HistogramsIterator it = histograms_.begin(), end = histograms_.end();
+ it != end; ++it) {
+ total += it->second->Sum();
}
return total;
}
-
void CumulativeLogger::AddLogger(const base::TimingLogger &logger) {
MutexLock mu(Thread::Current(), lock_);
- const std::vector<std::pair<uint64_t, const char*> >& splits = logger.GetSplits();
- typedef std::vector<std::pair<uint64_t, const char*> >::const_iterator It;
- // The first time this is run, the histograms array will be empty.
- if (kIsDebugBuild && !histograms_.empty() && splits.size() != histograms_.size()) {
- LOG(ERROR) << "Mismatch in splits.";
- typedef std::vector<Histogram<uint64_t> *>::const_iterator It2;
- It it = splits.begin();
- It2 it2 = histograms_.begin();
- while ((it != splits.end()) && (it2 != histograms_.end())) {
- if (it != splits.end()) {
- LOG(ERROR) << "\tsplit: " << it->second;
- ++it;
- }
- if (it2 != histograms_.end()) {
- LOG(ERROR) << "\tpreviously record: " << (*it2)->Name();
- ++it2;
- }
- }
- }
- for (It it = splits.begin(), end = splits.end(); it != end; ++it) {
- std::pair<uint64_t, const char*> split = *it;
+ const base::TimingLogger::SplitTimings& splits = logger.GetSplits();
+ for (base::TimingLogger::SplitsIterator it = splits.begin(), end = splits.end();
+ it != end; ++it) {
+ base::TimingLogger::SplitTiming split = *it;
uint64_t split_time = split.first;
const char* split_name = split.second;
AddPair(split_name, split_time);
@@ -112,23 +94,24 @@
void CumulativeLogger::AddPair(const std::string &label, uint64_t delta_time) {
// Convert delta time to microseconds so that we don't overflow our counters.
delta_time /= kAdjust;
- if (histograms_.size() <= index_) {
+
+ if (histograms_.find(label) == histograms_.end()) {
+ // TODO: Shoud this be a defined constant so we we know out of which orifice 16 and 100 were picked?
const size_t max_buckets = Runtime::Current()->GetHeap()->IsLowMemoryMode() ? 16 : 100;
- histograms_.push_back(new Histogram<uint64_t>(label.c_str(), 50, max_buckets));
- DCHECK_GT(histograms_.size(), index_);
+ // TODO: Should this be a defined constant so we know 50 of WTF?
+ histograms_[label] = new Histogram<uint64_t>(label.c_str(), 50, max_buckets);
}
- histograms_[index_]->AddValue(delta_time);
- DCHECK_EQ(label, histograms_[index_]->Name());
- ++index_;
+ histograms_[label]->AddValue(delta_time);
}
void CumulativeLogger::DumpHistogram(std::ostream &os) {
os << "Start Dumping histograms for " << iterations_ << " iterations"
<< " for " << name_ << "\n";
- for (size_t Idx = 0; Idx < histograms_.size(); Idx++) {
+ for (CumulativeLogger::HistogramsIterator it = histograms_.begin(), end = histograms_.end();
+ it != end; ++it) {
Histogram<uint64_t>::CumulativeData cumulative_data;
- histograms_[Idx]->CreateHistogram(cumulative_data);
- histograms_[Idx]->PrintConfidenceIntervals(os, 0.99, cumulative_data);
+ it->second->CreateHistogram(cumulative_data);
+ it->second->PrintConfidenceIntervals(os, 0.99, cumulative_data);
// Reset cumulative values to save memory. We don't expect DumpHistogram to be called often, so
// it is not performance critical.
}
@@ -139,58 +122,42 @@
namespace base {
TimingLogger::TimingLogger(const char* name, bool precise, bool verbose)
- : name_(name), precise_(precise), verbose_(verbose),
- current_split_(NULL), current_split_start_ns_(0) {
+ : name_(name), precise_(precise), verbose_(verbose), current_split_(NULL) {
}
void TimingLogger::Reset() {
current_split_ = NULL;
- current_split_start_ns_ = 0;
splits_.clear();
}
void TimingLogger::StartSplit(const char* new_split_label) {
- DCHECK(current_split_ == NULL);
- if (verbose_) {
- LOG(INFO) << "Begin: " << new_split_label;
- }
- current_split_ = new_split_label;
- ATRACE_BEGIN(current_split_);
- current_split_start_ns_ = NanoTime();
+ DCHECK(new_split_label != NULL) << "Starting split (" << new_split_label << ") with null label.";
+ TimingLogger::ScopedSplit* explicit_scoped_split = new TimingLogger::ScopedSplit(new_split_label, this);
+ explicit_scoped_split->explicit_ = true;
+}
+
+void TimingLogger::EndSplit() {
+ CHECK(current_split_ != NULL) << "Ending a non-existent split.";
+ DCHECK(current_split_->label_ != NULL);
+ DCHECK(current_split_->explicit_ == true) << "Explicitly ending scoped split: " << current_split_->label_;
+
+ delete current_split_;
}
// Ends the current split and starts the one given by the label.
void TimingLogger::NewSplit(const char* new_split_label) {
- DCHECK(current_split_ != NULL);
- uint64_t current_time = NanoTime();
- uint64_t split_time = current_time - current_split_start_ns_;
- ATRACE_END();
- splits_.push_back(std::pair<uint64_t, const char*>(split_time, current_split_));
- if (verbose_) {
- LOG(INFO) << "End: " << current_split_ << " " << PrettyDuration(split_time) << "\n"
- << "Begin: " << new_split_label;
- }
- current_split_ = new_split_label;
- ATRACE_BEGIN(current_split_);
- current_split_start_ns_ = current_time;
-}
+ CHECK(current_split_ != NULL) << "Inserting a new split (" << new_split_label
+ << ") into a non-existent split.";
+ DCHECK(new_split_label != NULL) << "New split (" << new_split_label << ") with null label.";
-void TimingLogger::EndSplit() {
- DCHECK(current_split_ != NULL);
- uint64_t current_time = NanoTime();
- uint64_t split_time = current_time - current_split_start_ns_;
- ATRACE_END();
- if (verbose_) {
- LOG(INFO) << "End: " << current_split_ << " " << PrettyDuration(split_time);
- }
- splits_.push_back(std::pair<uint64_t, const char*>(split_time, current_split_));
+ current_split_->TailInsertSplit(new_split_label);
}
uint64_t TimingLogger::GetTotalNs() const {
uint64_t total_ns = 0;
- typedef std::vector<std::pair<uint64_t, const char*> >::const_iterator It;
- for (It it = splits_.begin(), end = splits_.end(); it != end; ++it) {
- std::pair<uint64_t, const char*> split = *it;
+ for (base::TimingLogger::SplitsIterator it = splits_.begin(), end = splits_.end();
+ it != end; ++it) {
+ base::TimingLogger::SplitTiming split = *it;
total_ns += split.first;
}
return total_ns;
@@ -199,9 +166,9 @@
void TimingLogger::Dump(std::ostream &os) const {
uint64_t longest_split = 0;
uint64_t total_ns = 0;
- typedef std::vector<std::pair<uint64_t, const char*> >::const_iterator It;
- for (It it = splits_.begin(), end = splits_.end(); it != end; ++it) {
- std::pair<uint64_t, const char*> split = *it;
+ for (base::TimingLogger::SplitsIterator it = splits_.begin(), end = splits_.end();
+ it != end; ++it) {
+ base::TimingLogger::SplitTiming split = *it;
uint64_t split_time = split.first;
longest_split = std::max(longest_split, split_time);
total_ns += split_time;
@@ -210,8 +177,9 @@
TimeUnit tu = GetAppropriateTimeUnit(longest_split);
uint64_t divisor = GetNsToTimeUnitDivisor(tu);
// Print formatted splits.
- for (It it = splits_.begin(), end = splits_.end(); it != end; ++it) {
- std::pair<uint64_t, const char*> split = *it;
+ for (base::TimingLogger::SplitsIterator it = splits_.begin(), end = splits_.end();
+ it != end; ++it) {
+ base::TimingLogger::SplitTiming split = *it;
uint64_t split_time = split.first;
if (!precise_ && divisor >= 1000) {
// Make the fractional part 0.
@@ -223,5 +191,102 @@
os << name_ << ": end, " << NsToMs(total_ns) << " ms\n";
}
+
+TimingLogger::ScopedSplit::ScopedSplit(const char* label, TimingLogger* timing_logger) {
+ DCHECK(label != NULL) << "New scoped split (" << label << ") with null label.";
+ CHECK(timing_logger != NULL) << "New scoped split (" << label << ") without TimingLogger.";
+ timing_logger_ = timing_logger;
+ label_ = label;
+ running_ns_ = 0;
+ explicit_ = false;
+
+ // Stash away the current split and pause it.
+ enclosing_split_ = timing_logger->current_split_;
+ if (enclosing_split_ != NULL) {
+ enclosing_split_->Pause();
+ }
+
+ timing_logger_->current_split_ = this;
+
+ ATRACE_BEGIN(label_);
+
+ start_ns_ = NanoTime();
+ if (timing_logger_->verbose_) {
+ LOG(INFO) << "Begin: " << label_;
+ }
+}
+
+TimingLogger::ScopedSplit::~ScopedSplit() {
+ uint64_t current_time = NanoTime();
+ uint64_t split_time = current_time - start_ns_;
+ running_ns_ += split_time;
+ ATRACE_END();
+
+ if (timing_logger_->verbose_) {
+ LOG(INFO) << "End: " << label_ << " " << PrettyDuration(split_time);
+ }
+
+ // If one or more enclosed explcitly started splits are not terminated we can
+ // either fail or "unwind" the stack of splits in the timing logger to 'this'
+ // (by deleting the intervening scoped splits). This implements the latter.
+ TimingLogger::ScopedSplit* current = timing_logger_->current_split_;
+ while ((current != NULL) && (current != this)) {
+ delete current;
+ current = timing_logger_->current_split_;
+ }
+
+ CHECK(current != NULL) << "Missing scoped split (" << this->label_
+ << ") in timing logger (" << timing_logger_->name_ << ").";
+ CHECK(timing_logger_->current_split_ == this);
+
+ timing_logger_->splits_.push_back(SplitTiming(running_ns_, label_));
+
+ timing_logger_->current_split_ = enclosing_split_;
+ if (enclosing_split_ != NULL) {
+ enclosing_split_->UnPause();
+ }
+}
+
+
+void TimingLogger::ScopedSplit::TailInsertSplit(const char* label) {
+ // Sleight of hand here: Rather than embedding a new scoped split, we're updating the current
+ // scoped split in place. Basically, it's one way to make explicit and scoped splits compose
+ // well while maintaining the current semantics of NewSplit. An alternative is to push a new split
+ // since we unwind the stack of scoped splits in the scoped split destructor. However, this implies
+ // that the current split is not ended by NewSplit (which calls TailInsertSplit), which would
+ // be different from what we had before.
+
+ uint64_t current_time = NanoTime();
+ uint64_t split_time = current_time - start_ns_;
+ ATRACE_END();
+ timing_logger_->splits_.push_back(std::pair<uint64_t, const char*>(split_time, label_));
+
+ if (timing_logger_->verbose_) {
+ LOG(INFO) << "End: " << label_ << " " << PrettyDuration(split_time) << "\n"
+ << "Begin: " << label;
+ }
+
+ label_ = label;
+ start_ns_ = current_time;
+ running_ns_ = 0;
+
+ ATRACE_BEGIN(label);
+}
+
+void TimingLogger::ScopedSplit::Pause() {
+ uint64_t current_time = NanoTime();
+ uint64_t split_time = current_time - start_ns_;
+ running_ns_ += split_time;
+ ATRACE_END();
+}
+
+
+void TimingLogger::ScopedSplit::UnPause() {
+ uint64_t current_time = NanoTime();
+
+ start_ns_ = current_time;
+ ATRACE_BEGIN(label_);
+}
+
} // namespace base
} // namespace art