diff options
author | Anwar Ghuloum <anwarg@google.com> | 2013-08-09 21:17:25 -0700 |
---|---|---|
committer | Anwar Ghuloum <anwarg@google.com> | 2013-08-09 21:17:25 -0700 |
commit | 4446ab9e70dde779d97f451c4904f6b8770232bd (patch) | |
tree | a19ddb0ffa054c6dcaf635afb228730506232d8e /runtime/base | |
parent | cc386f94631dd1d60b0b0b2d4e1e243dda363f32 (diff) | |
download | art-4446ab9e70dde779d97f451c4904f6b8770232bd.zip art-4446ab9e70dde779d97f451c4904f6b8770232bd.tar.gz art-4446ab9e70dde779d97f451c4904f6b8770232bd.tar.bz2 |
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
Diffstat (limited to 'runtime/base')
-rw-r--r-- | runtime/base/timing_logger.cc | 219 | ||||
-rw-r--r-- | runtime/base/timing_logger.h | 75 | ||||
-rw-r--r-- | runtime/base/timing_logger_test.cc | 160 |
3 files changed, 364 insertions, 90 deletions
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(const std::string& name) } CumulativeLogger::~CumulativeLogger() { - STLDeleteElements(&histograms_); + STLDeleteValues(&histograms_); } void CumulativeLogger::SetName(const std::string& name) { @@ -47,18 +47,17 @@ void CumulativeLogger::SetName(const std::string& name) { } 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::GetTotalNs() const { 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::Dump(std::ostream &os) { 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 @@ void CumulativeLogger::DumpHistogram(std::ostream &os) { 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 @@ uint64_t TimingLogger::GetTotalNs() const { 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 @@ void TimingLogger::Dump(std::ostream &os) const { 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 @@ void TimingLogger::Dump(std::ostream &os) const { 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 diff --git a/runtime/base/timing_logger.h b/runtime/base/timing_logger.h index 0998837..8649a96 100644 --- a/runtime/base/timing_logger.h +++ b/runtime/base/timing_logger.h @@ -23,6 +23,7 @@ #include <string> #include <vector> +#include <map> namespace art { @@ -32,6 +33,9 @@ namespace base { class CumulativeLogger { public: + typedef std::map<std::string, Histogram<uint64_t> *> Histograms; + typedef std::map<std::string, Histogram<uint64_t> *>::const_iterator HistogramsIterator; + explicit CumulativeLogger(const std::string& name); void prepare_stats(); ~CumulativeLogger(); @@ -51,11 +55,10 @@ class CumulativeLogger { void DumpHistogram(std::ostream &os) EXCLUSIVE_LOCKS_REQUIRED(lock_); uint64_t GetTotalTime() const; static const uint64_t kAdjust = 1000; - std::vector<Histogram<uint64_t> *> histograms_ GUARDED_BY(lock_); + Histograms histograms_ GUARDED_BY(lock_); std::string name_; const std::string lock_name_; mutable Mutex lock_ DEFAULT_MUTEX_ACQUIRED_AFTER; - size_t index_ GUARDED_BY(lock_); size_t iterations_ GUARDED_BY(lock_); DISALLOW_COPY_AND_ASSIGN(CumulativeLogger); @@ -63,16 +66,22 @@ class CumulativeLogger { namespace base { -// A replacement to timing logger that know when a split starts for the purposes of logging. + +// A timing logger that knows when a split starts for the purposes of logging tools, like systrace. class TimingLogger { public: + // Splits are nanosecond times and split names. + typedef std::pair<uint64_t, const char*> SplitTiming; + typedef std::vector<SplitTiming> SplitTimings; + typedef std::vector<SplitTiming>::const_iterator SplitsIterator; + explicit TimingLogger(const char* name, bool precise, bool verbose); // Clears current splits and labels. void Reset(); - // Starts a split, a split shouldn't be in progress. - void StartSplit(const char* new_split_label); + // Starts a split + void StartSplit(const char* new_split_label); // Ends the current split and starts the one given by the label. void NewSplit(const char* new_split_label); @@ -84,10 +93,53 @@ class TimingLogger { void Dump(std::ostream& os) const; - const std::vector<std::pair<uint64_t, const char*> >& GetSplits() const { + // Scoped timing splits that can be nested and composed with the explicit split + // starts and ends. + class ScopedSplit { + public: + explicit ScopedSplit(const char* label, TimingLogger* timing_logger); + + ~ScopedSplit(); + + friend class TimingLogger; + + private: + // Pauses timing of the split, usually due to nesting of another split. + void Pause(); + + // Unpauses timing of the split, usually because a nested split has ended. + void UnPause(); + + // Used by new split to swap splits in place in a ScopedSplit instance. + void TailInsertSplit(const char* label); + + // The scoped split immediately enclosing this split. Essentially, we get a + // stack of nested splits through this field. + ScopedSplit* enclosing_split_; + + // Was this created via TimingLogger's StartSplit? + bool explicit_; + + // The split's name. + const char* label_; + + // The current split's latest start time. (It may have been paused and restarted.) + uint64_t start_ns_; + + // The running time, outside of pauses. + uint64_t running_ns_; + + // The timing logger holding this split. + TimingLogger* timing_logger_; + + DISALLOW_COPY_AND_ASSIGN(ScopedSplit); + }; + + const SplitTimings& GetSplits() const { return splits_; } + friend class ScopedSplit; protected: // The name of the timing logger. const char* name_; @@ -99,14 +151,11 @@ class TimingLogger { // Verbose logging. const bool verbose_; - // The name of the current split. - const char* current_split_; + // The current scoped split is also the 'top' of the stack of splits in progress. + ScopedSplit* current_split_; - // The nanosecond time the current split started on. - uint64_t current_split_start_ns_; - - // Splits are nanosecond times and split names. - std::vector<std::pair<uint64_t, const char*> > splits_; + // Splits that have ended. + SplitTimings splits_; private: DISALLOW_COPY_AND_ASSIGN(TimingLogger); diff --git a/runtime/base/timing_logger_test.cc b/runtime/base/timing_logger_test.cc new file mode 100644 index 0000000..8f28e48 --- /dev/null +++ b/runtime/base/timing_logger_test.cc @@ -0,0 +1,160 @@ +/* + * Copyright (C) 2012 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +#include "timing_logger.h" + +#include "common_test.h" + +namespace art { + +class TimingLoggerTest : public CommonTest {}; + +// TODO: Negative test cases (improper pairing of EndSplit, etc.) + +TEST_F(TimingLoggerTest, StartEnd) { + const char* split1name = "First Split"; + base::TimingLogger timings("StartEnd", true, false); + + timings.StartSplit(split1name); + + timings.EndSplit(); // Ends split1. + + const base::TimingLogger::SplitTimings& splits = timings.GetSplits(); + + EXPECT_EQ(1U, splits.size()); + EXPECT_STREQ(splits[0].second, split1name); +} + + +TEST_F(TimingLoggerTest, StartNewEnd) { + const char* split1name = "First Split"; + const char* split2name = "Second Split"; + const char* split3name = "Third Split"; + base::TimingLogger timings("StartNewEnd", true, false); + + timings.StartSplit(split1name); + + timings.NewSplit(split2name); // Ends split1. + + timings.NewSplit(split3name); // Ends split2. + + timings.EndSplit(); // Ends split3. + + const base::TimingLogger::SplitTimings& splits = timings.GetSplits(); + + EXPECT_EQ(3U, splits.size()); + EXPECT_STREQ(splits[0].second, split1name); + EXPECT_STREQ(splits[1].second, split2name); + EXPECT_STREQ(splits[2].second, split3name); +} + +TEST_F(TimingLoggerTest, StartNewEndNested) { + const char* split1name = "First Split"; + const char* split2name = "Second Split"; + const char* split3name = "Third Split"; + const char* split4name = "Fourth Split"; + const char* split5name = "Fifth Split"; + base::TimingLogger timings("StartNewEndNested", true, false); + + timings.StartSplit(split1name); + + timings.NewSplit(split2name); // Ends split1. + + timings.StartSplit(split3name); + + timings.StartSplit(split4name); + + timings.NewSplit(split5name); // Ends split4. + + timings.EndSplit(); // Ends split5. + + timings.EndSplit(); // Ends split3. + + timings.EndSplit(); // Ends split2. + + const base::TimingLogger::SplitTimings& splits = timings.GetSplits(); + + EXPECT_EQ(5U, splits.size()); + EXPECT_STREQ(splits[0].second, split1name); + EXPECT_STREQ(splits[1].second, split4name); + EXPECT_STREQ(splits[2].second, split5name); + EXPECT_STREQ(splits[3].second, split3name); + EXPECT_STREQ(splits[4].second, split2name); +} + + +TEST_F(TimingLoggerTest, Scoped) { + const char* outersplit = "Outer Split"; + const char* innersplit1 = "Inner Split 1"; + const char* innerinnersplit1 = "Inner Inner Split 1"; + const char* innersplit2 = "Inner Split 2"; + base::TimingLogger timings("Scoped", true, false); + + { + base::TimingLogger::ScopedSplit outer(outersplit, &timings); + + { + base::TimingLogger::ScopedSplit inner1(innersplit1, &timings); + + { + base::TimingLogger::ScopedSplit innerinner1(innerinnersplit1, &timings); + } // Ends innerinnersplit1. + } // Ends innersplit1. + + { + base::TimingLogger::ScopedSplit inner2(innersplit2, &timings); + } // Ends innersplit2. + } // Ends outersplit. + + const base::TimingLogger::SplitTimings& splits = timings.GetSplits(); + + EXPECT_EQ(4U, splits.size()); + EXPECT_STREQ(splits[0].second, innerinnersplit1); + EXPECT_STREQ(splits[1].second, innersplit1); + EXPECT_STREQ(splits[2].second, innersplit2); + EXPECT_STREQ(splits[3].second, outersplit); +} + + +TEST_F(TimingLoggerTest, ScopedAndExplicit) { + const char* outersplit = "Outer Split"; + const char* innersplit = "Inner Split"; + const char* innerinnersplit1 = "Inner Inner Split 1"; + const char* innerinnersplit2 = "Inner Inner Split 2"; + base::TimingLogger timings("Scoped", true, false); + + timings.StartSplit(outersplit); + + { + base::TimingLogger::ScopedSplit inner(innersplit, &timings); + + timings.StartSplit(innerinnersplit1); + + timings.NewSplit(innerinnersplit2); // Ends innerinnersplit1. + } // Ends innerinnersplit2, then innersplit. + + timings.EndSplit(); // Ends outersplit. + + const base::TimingLogger::SplitTimings& splits = timings.GetSplits(); + + EXPECT_EQ(4U, splits.size()); + EXPECT_STREQ(splits[0].second, innerinnersplit1); + EXPECT_STREQ(splits[1].second, innerinnersplit2); + EXPECT_STREQ(splits[2].second, innersplit); + EXPECT_STREQ(splits[3].second, outersplit); +} + +} // namespace art |