From 5fe9af720048673e62ee29597a30bb9e54c903c5 Mon Sep 17 00:00:00 2001 From: Ian Rogers Date: Thu, 14 Nov 2013 00:17:20 -0800 Subject: Fix memory leaks relating to timing logger. Bug: 11670287. We use pointers to uninitialized values for control-flow in the timing logger code, add TODO comments to clean this up later. Remove base namespace and other bits of tidying. Change-Id: I1e6600a1e92f974c8f58f3a405a4e4abb4d9f80f --- runtime/base/timing_logger.cc | 58 ++++++++++++++++++-------------------- runtime/base/timing_logger.h | 18 ++++-------- runtime/base/timing_logger_test.cc | 30 ++++++++++---------- 3 files changed, 48 insertions(+), 58 deletions(-) (limited to 'runtime/base') diff --git a/runtime/base/timing_logger.cc b/runtime/base/timing_logger.cc index 45a546f..dae8201 100644 --- a/runtime/base/timing_logger.cc +++ b/runtime/base/timing_logger.cc @@ -74,12 +74,11 @@ uint64_t CumulativeLogger::GetTotalTime() const { return total; } -void CumulativeLogger::AddLogger(const base::TimingLogger &logger) { +void CumulativeLogger::AddLogger(const TimingLogger &logger) { MutexLock mu(Thread::Current(), lock_); - const base::TimingLogger::SplitTimings& splits = logger.GetSplits(); - for (base::TimingLogger::SplitTimingsIterator it = splits.begin(), end = splits.end(); - it != end; ++it) { - base::TimingLogger::SplitTiming split = *it; + const TimingLogger::SplitTimings& splits = logger.GetSplits(); + for (auto it = splits.begin(), end = splits.end(); it != end; ++it) { + TimingLogger::SplitTiming split = *it; uint64_t split_time = split.first; const char* split_name = split.second; AddPair(split_name, split_time); @@ -101,7 +100,8 @@ void CumulativeLogger::AddPair(const std::string &label, uint64_t delta_time) { delta_time /= kAdjust; 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? + // TODO: Should 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; // TODO: Should this be a defined constant so we know 50 of WTF? histograms_[label] = new Histogram(label.c_str(), 50, max_buckets); @@ -123,9 +123,6 @@ void CumulativeLogger::DumpHistogram(std::ostream &os) { os << "Done Dumping histograms \n"; } - -namespace base { - TimingLogger::TimingLogger(const char* name, bool precise, bool verbose) : name_(name), precise_(precise), verbose_(verbose), current_split_(NULL) { } @@ -136,33 +133,35 @@ void TimingLogger::Reset() { } void TimingLogger::StartSplit(const char* new_split_label) { - 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); + DCHECK(new_split_label != nullptr) << "Starting split 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_; - + CHECK(current_split_ != nullptr) << "Ending a non-existent split."; + DCHECK(current_split_->label_ != nullptr); + DCHECK(current_split_->explicit_ == true) + << "Explicitly ending scoped split: " << current_split_->label_; delete current_split_; + // TODO: current_split_ = nullptr; } // Ends the current split and starts the one given by the label. void TimingLogger::NewSplit(const char* new_split_label) { - 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."; - - current_split_->TailInsertSplit(new_split_label); + if (current_split_ == nullptr) { + StartSplit(new_split_label); + } else { + DCHECK(new_split_label != nullptr) << "New split (" << new_split_label << ") with null label."; + current_split_->TailInsertSplit(new_split_label); + } } uint64_t TimingLogger::GetTotalNs() const { uint64_t total_ns = 0; - for (base::TimingLogger::SplitTimingsIterator it = splits_.begin(), end = splits_.end(); - it != end; ++it) { - base::TimingLogger::SplitTiming split = *it; + for (auto it = splits_.begin(), end = splits_.end(); it != end; ++it) { + TimingLogger::SplitTiming split = *it; total_ns += split.first; } return total_ns; @@ -171,9 +170,8 @@ uint64_t TimingLogger::GetTotalNs() const { void TimingLogger::Dump(std::ostream &os) const { uint64_t longest_split = 0; uint64_t total_ns = 0; - for (base::TimingLogger::SplitTimingsIterator it = splits_.begin(), end = splits_.end(); - it != end; ++it) { - base::TimingLogger::SplitTiming split = *it; + for (auto it = splits_.begin(), end = splits_.end(); it != end; ++it) { + TimingLogger::SplitTiming split = *it; uint64_t split_time = split.first; longest_split = std::max(longest_split, split_time); total_ns += split_time; @@ -182,9 +180,8 @@ void TimingLogger::Dump(std::ostream &os) const { TimeUnit tu = GetAppropriateTimeUnit(longest_split); uint64_t divisor = GetNsToTimeUnitDivisor(tu); // Print formatted splits. - for (base::TimingLogger::SplitTimingsIterator it = splits_.begin(), end = splits_.end(); - it != end; ++it) { - base::TimingLogger::SplitTiming split = *it; + for (auto it = splits_.begin(), end = splits_.end(); it != end; ++it) { + const TimingLogger::SplitTiming& split = *it; uint64_t split_time = split.first; if (!precise_ && divisor >= 1000) { // Make the fractional part 0. @@ -231,7 +228,7 @@ TimingLogger::ScopedSplit::~ScopedSplit() { LOG(INFO) << "End: " << label_ << " " << PrettyDuration(split_time); } - // If one or more enclosed explcitly started splits are not terminated we can + // If one or more enclosed explicitly 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_; @@ -293,5 +290,4 @@ void TimingLogger::ScopedSplit::Resume() { ATRACE_BEGIN(label_); } -} // namespace base } // namespace art diff --git a/runtime/base/timing_logger.h b/runtime/base/timing_logger.h index 501d2d7..f1f7855 100644 --- a/runtime/base/timing_logger.h +++ b/runtime/base/timing_logger.h @@ -26,10 +26,7 @@ #include namespace art { - -namespace base { - class TimingLogger; -} // namespace base +class TimingLogger; class CumulativeLogger { public: @@ -44,7 +41,7 @@ class CumulativeLogger { // Allow the name to be modified, particularly when the cumulative logger is a field within a // parent class that is unable to determine the "name" of a sub-class. void SetName(const std::string& name); - void AddLogger(const base::TimingLogger& logger) LOCKS_EXCLUDED(lock_); + void AddLogger(const TimingLogger& logger) LOCKS_EXCLUDED(lock_); size_t GetIterations() const; private: @@ -65,19 +62,17 @@ class CumulativeLogger { DISALLOW_COPY_AND_ASSIGN(CumulativeLogger); }; -namespace base { - - // 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 SplitTiming; typedef std::vector SplitTimings; - typedef std::vector::const_iterator SplitTimingsIterator; explicit TimingLogger(const char* name, bool precise, bool verbose); - + ~TimingLogger() { + // TODO: DCHECK(current_split_ == nullptr) << "Forgot to end split: " << current_split_->label_; + } // Clears current splits and labels. void Reset(); @@ -143,7 +138,7 @@ class TimingLogger { friend class ScopedSplit; protected: // The name of the timing logger. - const char* name_; + const char* const name_; // Do we want to print the exactly recorded split (true) or round down to the time unit being // used (false). @@ -162,7 +157,6 @@ class TimingLogger { DISALLOW_COPY_AND_ASSIGN(TimingLogger); }; -} // namespace base } // namespace art #endif // ART_RUNTIME_BASE_TIMING_LOGGER_H_ diff --git a/runtime/base/timing_logger_test.cc b/runtime/base/timing_logger_test.cc index 8f28e48..03cc9cc 100644 --- a/runtime/base/timing_logger_test.cc +++ b/runtime/base/timing_logger_test.cc @@ -26,13 +26,13 @@ class TimingLoggerTest : public CommonTest {}; TEST_F(TimingLoggerTest, StartEnd) { const char* split1name = "First Split"; - base::TimingLogger timings("StartEnd", true, false); + TimingLogger timings("StartEnd", true, false); timings.StartSplit(split1name); timings.EndSplit(); // Ends split1. - const base::TimingLogger::SplitTimings& splits = timings.GetSplits(); + const TimingLogger::SplitTimings& splits = timings.GetSplits(); EXPECT_EQ(1U, splits.size()); EXPECT_STREQ(splits[0].second, split1name); @@ -43,7 +43,7 @@ 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); + TimingLogger timings("StartNewEnd", true, false); timings.StartSplit(split1name); @@ -53,7 +53,7 @@ TEST_F(TimingLoggerTest, StartNewEnd) { timings.EndSplit(); // Ends split3. - const base::TimingLogger::SplitTimings& splits = timings.GetSplits(); + const TimingLogger::SplitTimings& splits = timings.GetSplits(); EXPECT_EQ(3U, splits.size()); EXPECT_STREQ(splits[0].second, split1name); @@ -67,7 +67,7 @@ TEST_F(TimingLoggerTest, StartNewEndNested) { const char* split3name = "Third Split"; const char* split4name = "Fourth Split"; const char* split5name = "Fifth Split"; - base::TimingLogger timings("StartNewEndNested", true, false); + TimingLogger timings("StartNewEndNested", true, false); timings.StartSplit(split1name); @@ -85,7 +85,7 @@ TEST_F(TimingLoggerTest, StartNewEndNested) { timings.EndSplit(); // Ends split2. - const base::TimingLogger::SplitTimings& splits = timings.GetSplits(); + const TimingLogger::SplitTimings& splits = timings.GetSplits(); EXPECT_EQ(5U, splits.size()); EXPECT_STREQ(splits[0].second, split1name); @@ -101,25 +101,25 @@ TEST_F(TimingLoggerTest, Scoped) { 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); + TimingLogger timings("Scoped", true, false); { - base::TimingLogger::ScopedSplit outer(outersplit, &timings); + TimingLogger::ScopedSplit outer(outersplit, &timings); { - base::TimingLogger::ScopedSplit inner1(innersplit1, &timings); + TimingLogger::ScopedSplit inner1(innersplit1, &timings); { - base::TimingLogger::ScopedSplit innerinner1(innerinnersplit1, &timings); + TimingLogger::ScopedSplit innerinner1(innerinnersplit1, &timings); } // Ends innerinnersplit1. } // Ends innersplit1. { - base::TimingLogger::ScopedSplit inner2(innersplit2, &timings); + TimingLogger::ScopedSplit inner2(innersplit2, &timings); } // Ends innersplit2. } // Ends outersplit. - const base::TimingLogger::SplitTimings& splits = timings.GetSplits(); + const TimingLogger::SplitTimings& splits = timings.GetSplits(); EXPECT_EQ(4U, splits.size()); EXPECT_STREQ(splits[0].second, innerinnersplit1); @@ -134,12 +134,12 @@ TEST_F(TimingLoggerTest, ScopedAndExplicit) { 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); + TimingLogger timings("Scoped", true, false); timings.StartSplit(outersplit); { - base::TimingLogger::ScopedSplit inner(innersplit, &timings); + TimingLogger::ScopedSplit inner(innersplit, &timings); timings.StartSplit(innerinnersplit1); @@ -148,7 +148,7 @@ TEST_F(TimingLoggerTest, ScopedAndExplicit) { timings.EndSplit(); // Ends outersplit. - const base::TimingLogger::SplitTimings& splits = timings.GetSplits(); + const TimingLogger::SplitTimings& splits = timings.GetSplits(); EXPECT_EQ(4U, splits.size()); EXPECT_STREQ(splits[0].second, innerinnersplit1); -- cgit v1.1