Using histograms for timing statistics.
Histogram class and test cases added.
Modified make file to add test cases and class file.
Added a guard to avoid race condition in Cumulative logger that
was possible race between Addlogger and Dump() functions.
Change-Id: I060a0d65648c7120963856624e7008c0aa681eb7
diff --git a/build/Android.common.mk b/build/Android.common.mk
index f613399..8b64519 100644
--- a/build/Android.common.mk
+++ b/build/Android.common.mk
@@ -144,6 +144,7 @@
src/base/mutex.cc \
src/base/stringpiece.cc \
src/base/stringprintf.cc \
+ src/base/timing_logger.cc \
src/base/unix_file/fd_file.cc \
src/base/unix_file/mapped_file.cc \
src/base/unix_file/null_file.cc \
@@ -250,7 +251,6 @@
src/thread.cc \
src/thread_list.cc \
src/thread_pool.cc \
- src/timing_logger.cc \
src/trace.cc \
src/utf.cc \
src/utils.cc \
@@ -383,6 +383,7 @@
TEST_COMMON_SRC_FILES := \
src/barrier_test.cc \
+ src/base/histogram_test.cc \
src/base/mutex_test.cc \
src/base/unix_file/fd_file_test.cc \
src/base/unix_file/mapped_file_test.cc \
diff --git a/src/base/histogram-inl.h b/src/base/histogram-inl.h
new file mode 100644
index 0000000..e9e52b6
--- /dev/null
+++ b/src/base/histogram-inl.h
@@ -0,0 +1,238 @@
+/*
+ * Copyright (C) 2013 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.
+ */
+
+#ifndef SRC_BASE_HISTOGRAM_INL_H_
+#define SRC_BASE_HISTOGRAM_INL_H_
+
+#include "histogram.h"
+
+#include "utils.h"
+
+#include <algorithm>
+#include <cmath>
+#include <limits>
+#include <ostream>
+
+namespace art {
+
+template <class Value> inline void Histogram<Value>::AddValue(Value value) {
+ CHECK_GE(value, 0.0);
+ if (value >= max_) {
+ Value new_max = ((value + 1) / bucket_width_ + 1) * bucket_width_;
+ DCHECK_GT(new_max, max_);
+ GrowBuckets(new_max);
+ }
+
+ BucketiseValue(value);
+ new_values_added_ = true;
+}
+
+template <class Value>
+inline Histogram<Value>::Histogram(const std::string name)
+ : kAdjust(1000),
+ kBucketWidth(5),
+ kInitialBucketCount(10),
+ bucket_width_(kBucketWidth),
+ bucket_count_(kInitialBucketCount) {
+ name_ = name;
+ Reset();
+}
+
+template <class Value>
+inline void Histogram<Value>::GrowBuckets(Value new_max) {
+ while (max_ < new_max) {
+ max_ += bucket_width_;
+ ranges_.push_back(max_);
+ frequency_.push_back(0);
+ bucket_count_++;
+ }
+}
+
+template <class Value> inline size_t Histogram<Value>::FindBucket(Value val) {
+ // Since this is only a linear histogram, bucket index can be found simply with
+ // dividing the value by the bucket width.
+ DCHECK_GE(val, min_);
+ DCHECK_LE(val, max_);
+ size_t bucket_idx = static_cast<size_t>((double)(val - min_) / bucket_width_);
+ DCHECK_GE(bucket_idx, 0ul);
+ DCHECK_LE(bucket_idx, bucket_count_);
+ return bucket_idx;
+}
+
+template <class Value>
+inline void Histogram<Value>::BucketiseValue(Value value) {
+ CHECK_LT(value, max_);
+ sum_ += value;
+ sum_of_squares_ += value * value;
+ size_t bucket_idx = FindBucket(value);
+ sample_size_++;
+ if (value > max_value_added_) {
+ max_value_added_ = value;
+ }
+ if (value < min_value_added_) {
+ min_value_added_ = value;
+ }
+ frequency_[bucket_idx]++;
+}
+
+template <class Value> inline void Histogram<Value>::Initialize() {
+ DCHECK_GT(bucket_count_, 0ul);
+ size_t idx = 0;
+ for (; idx < bucket_count_; idx++) {
+ ranges_.push_back(min_ + static_cast<Value>(idx) * (bucket_width_));
+ frequency_.push_back(0);
+ }
+ // Cumulative frequency and ranges has a length of 1 over frequency.
+ ranges_.push_back(min_ + idx * bucket_width_);
+ max_ = bucket_width_ * bucket_count_;
+}
+
+template <class Value> inline void Histogram<Value>::Reset() {
+ bucket_width_ = kBucketWidth;
+ bucket_count_ = kInitialBucketCount;
+ max_ = bucket_width_ * bucket_count_;
+ sum_of_squares_ = 0;
+ sample_size_ = 0;
+ min_ = 0;
+ sum_ = 0;
+ min_value_added_ = std::numeric_limits<Value>::max();
+ max_value_added_ = std::numeric_limits<Value>::min();
+ new_values_added_ = false;
+ ranges_.clear();
+ frequency_.clear();
+ cumulative_freq_.clear();
+ cumulative_perc_.clear();
+ Initialize();
+}
+
+template <class Value> inline void Histogram<Value>::BuildRanges() {
+ for (size_t idx = 0; idx < bucket_count_; ++idx) {
+ ranges_.push_back(min_ + idx * bucket_width_);
+ }
+}
+
+template <class Value> inline double Histogram<Value>::Mean() const {
+ DCHECK_GT(sample_size_, 0ull);
+ return static_cast<double>(sum_) / static_cast<double>(sample_size_);
+}
+
+template <class Value> inline double Histogram<Value>::Variance() const {
+ DCHECK_GT(sample_size_, 0ull);
+ // Using algorithms for calculating variance over a population:
+ // http://en.wikipedia.org/wiki/Algorithms_for_calculating_variance
+ Value sum_squared = sum_ * sum_;
+ double sum_squared_by_n_squared =
+ static_cast<double>(sum_squared) /
+ static_cast<double>(sample_size_ * sample_size_);
+ double sum_of_squares_by_n =
+ static_cast<double>(sum_of_squares_) / static_cast<double>(sample_size_);
+ return sum_of_squares_by_n - sum_squared_by_n_squared;
+}
+
+template <class Value>
+inline void Histogram<Value>::PrintBins(std::ostream &os) {
+ DCHECK_GT(sample_size_, 0ull);
+ DCHECK(new_values_added_);
+ size_t bin_idx = 0;
+ while (bin_idx < cumulative_freq_.size()) {
+ if (bin_idx > 0 &&
+ cumulative_perc_[bin_idx] == cumulative_perc_[bin_idx - 1]) {
+ bin_idx++;
+ continue;
+ }
+ os << ranges_[bin_idx] << ": " << cumulative_freq_[bin_idx] << "\t"
+ << cumulative_perc_[bin_idx] * 100.0 << "%\n";
+ bin_idx++;
+ }
+}
+
+template <class Value>
+inline void Histogram<Value>::PrintConfidenceIntervals(std::ostream &os,
+ double interval) const {
+ DCHECK_GT(interval, 0);
+ DCHECK_LT(interval, 1.0);
+
+ double per_0 = (1.0 - interval) / 2.0;
+ double per_1 = per_0 + interval;
+ os << Name() << ":\t";
+ TimeUnit unit = GetAppropriateTimeUnit(Mean() * kAdjust);
+ os << interval << "% C.I. "
+ << FormatDuration(Percentile(per_0) * kAdjust, unit);
+ os << "-" << FormatDuration(Percentile(per_1) * kAdjust, unit) << " ";
+ os << "Avg: " << FormatDuration(Mean() * kAdjust, unit) << " Max: ";
+ os << FormatDuration(Max() * kAdjust, unit) << "\n";
+}
+
+template <class Value> inline void Histogram<Value>::BuildCDF() {
+ DCHECK_EQ(cumulative_freq_.size(), 0ull);
+ DCHECK_EQ(cumulative_perc_.size(), 0ull);
+ uint64_t accumulated = 0;
+
+ cumulative_freq_.push_back(accumulated);
+ cumulative_perc_.push_back(0.0);
+ for (size_t idx = 0; idx < frequency_.size(); idx++) {
+ accumulated += frequency_[idx];
+ cumulative_freq_.push_back(accumulated);
+ cumulative_perc_.push_back(static_cast<double>(accumulated) /
+ static_cast<double>(sample_size_));
+ }
+ DCHECK_EQ(*(cumulative_freq_.end() - 1), sample_size_);
+ DCHECK_EQ(*(cumulative_perc_.end() - 1), 1.0);
+}
+
+template <class Value> inline void Histogram<Value>::CreateHistogram() {
+ DCHECK_GT(sample_size_, 0ull);
+
+ // Create a histogram only if new values are added.
+ if (!new_values_added_)
+ return;
+
+ // Reset cumulative values in case this is not the first time creating histogram.
+ cumulative_freq_.clear();
+ cumulative_perc_.clear();
+ BuildCDF();
+ new_values_added_ = false;
+}
+;
+
+template <class Value>
+inline double Histogram<Value>::Percentile(double per) const {
+ DCHECK_GT(cumulative_perc_.size(), 0ull);
+ size_t idx;
+ for (idx = 0; idx < cumulative_perc_.size(); idx++) {
+ if (per <= cumulative_perc_[idx + 1])
+ break;
+ }
+ double lower_value = static_cast<double>(ranges_[idx]);
+ double upper_value = static_cast<double>(ranges_[idx + 1]);
+ double lower_perc = cumulative_perc_[idx];
+ double upper_perc = cumulative_perc_[idx + 1];
+ if (per == lower_perc) {
+ return lower_value;
+ }
+ if (per == upper_perc) {
+ return upper_value;
+ }
+ DCHECK_GT(upper_perc, lower_perc);
+ double value = lower_value + (upper_value - lower_value) *
+ (per - lower_perc) / (upper_perc - lower_perc);
+
+ return value;
+}
+
+} // namespace art
+#endif // SRC_BASE_HISTOGRAM_INL_H_
+
diff --git a/src/base/histogram.h b/src/base/histogram.h
new file mode 100644
index 0000000..6878e71
--- /dev/null
+++ b/src/base/histogram.h
@@ -0,0 +1,120 @@
+/*
+ * Copyright (C) 2013 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.
+ */
+#ifndef ART_SRC_BASE_HISTOGRAM_H_
+#define ART_SRC_BASE_HISTOGRAM_H_
+
+#include <vector>
+#include <string>
+
+#include "base/logging.h"
+#include "utils.h"
+
+namespace art {
+
+// Creates a data histogram for a better understanding of statistical data.
+// Histogram analysis goes beyond simple mean and standard deviation to provide
+// percentiles values, describing where the $% of the input data lies.
+// Designed to be simple and used with timing logger in art.
+
+template <class Value> class Histogram {
+
+ const double kAdjust;
+ const Value kBucketWidth;
+ const size_t kInitialBucketCount;
+
+ public:
+ Histogram(std::string);
+ void AddValue(Value);
+ void CreateHistogram();
+ void Reset();
+ double Mean() const;
+ double Variance() const;
+ double Percentile(double) const;
+ void PrintConfidenceIntervals(std::ostream &, double) const;
+ void PrintBins(std::ostream &);
+
+ uint64_t SampleSize() const {
+ return sample_size_;
+ }
+
+ Value Sum() const {
+ return sum_;
+ }
+
+ Value Min() const {
+ return min_value_added_;
+ }
+
+ Value Max() const {
+ return max_value_added_;
+ }
+
+ const std::string &Name() const {
+ return name_;
+ }
+
+
+ private:
+ void BuildRanges();
+ void Initialize();
+ size_t FindBucket(Value);
+ void BucketiseValue(Value);
+ // Builds the cumulative distribution function from the frequency data.
+ // Must be called before using the percentile function.
+ void BuildCDF();
+ // Add more buckets to the histogram to fill in a new value that exceeded
+ // the max_read_value_.
+ void GrowBuckets(Value);
+ bool new_values_added_;
+ std::string name_;
+ // Number of samples placed in histogram.
+ uint64_t sample_size_;
+ // Width of the bucket range. The lower the value is the more accurate
+ // histogram percentiles are.
+ Value bucket_width_;
+ // Number of bucket to have in the histogram. this value will increase
+ // to accommodate for big values that don't fit in initial bucket ranges.
+ size_t bucket_count_;
+ // Represents the ranges of the histograms. Has SampleSize() + 1 elements
+ // e.g. 0,5,10,15 represents ranges 0-5, 5-10, 10-15
+ std::vector<Value> ranges_;
+ // How many occurrences of values fall within a corresponding range that is
+ // saved in the ranges_ vector.
+ std::vector<uint64_t> frequency_;
+ // Accumulative summation of frequencies.
+ // cumulative_freq_[i] = sum(cumulative_freq_[j] : 0 < j < i )
+ std::vector<uint64_t> cumulative_freq_;
+ // Accumulative summation of percentiles; which is the frequency / SampleSize
+ // cumulative_freq_[i] = sum(cumulative_freq_[j] : 0 < j < i )
+ std::vector<double> cumulative_perc_;
+ // Summation of all the elements inputed by the user.
+ Value sum_;
+ // Maximum value that can fit in the histogram, grows adaptively.
+ Value min_;
+ // Minimum value that can fit in the histogram. Fixed to zero for now.
+ Value max_;
+ // Summation of the values entered. Used to calculate variance.
+ Value sum_of_squares_;
+ // Maximum value entered in the histogram.
+ Value min_value_added_;
+ // Minimum value entered in the histogram.
+ Value max_value_added_;
+
+ DISALLOW_COPY_AND_ASSIGN(Histogram);
+};
+}
+
+#endif // ART_SRC_BASE_HISTOGRAM_H_
diff --git a/src/base/histogram_test.cc b/src/base/histogram_test.cc
new file mode 100644
index 0000000..2adb41b
--- /dev/null
+++ b/src/base/histogram_test.cc
@@ -0,0 +1,252 @@
+#include "gtest/gtest.h"
+#include "histogram-inl.h"
+#include <sstream>
+using namespace art;
+
+//Simple usage:
+// Histogram *hist = new Histogram("SimplePercentiles");
+// Percentile PerValue
+// hist->AddValue(121);
+// hist->AddValue(132);
+// hist->AddValue(140);
+// hist->AddValue(145);
+// hist->AddValue(155);
+// hist->CreateHistogram();
+// PerValue = hist->PercentileVal(0.50); finds the 50th percentile(median).
+
+TEST(Histtest, MeanTest) {
+
+ Histogram<uint64_t> *hist = new Histogram<uint64_t>("MeanTest");
+ double mean;
+ for (size_t Idx = 0; Idx < 90; Idx++) {
+ hist->AddValue(static_cast<uint64_t>(50));
+ }
+ mean = hist->Mean();
+ EXPECT_EQ(mean, 50);
+ hist->Reset();
+ hist->AddValue(9);
+ hist->AddValue(17);
+ hist->AddValue(28);
+ hist->AddValue(28);
+ mean = hist->Mean();
+ EXPECT_EQ(mean, 20.5);
+}
+;
+
+TEST(Histtest, VarianceTest) {
+
+ Histogram<uint64_t> *hist = new Histogram<uint64_t>("VarianceTest");
+ double variance;
+ hist->AddValue(9);
+ hist->AddValue(17);
+ hist->AddValue(28);
+ hist->AddValue(28);
+ hist->CreateHistogram();
+ variance = hist->Variance();
+ EXPECT_EQ(variance, 64.25);
+ delete hist;
+}
+;
+
+TEST(Histtest, Percentile) {
+
+ Histogram<uint64_t> *hist = new Histogram<uint64_t>("Percentile");
+ double PerValue;
+
+ hist->AddValue(20);
+ hist->AddValue(31);
+ hist->AddValue(42);
+ hist->AddValue(50);
+ hist->AddValue(60);
+ hist->AddValue(70);
+ hist->AddValue(98);
+ hist->AddValue(110);
+ hist->AddValue(121);
+ hist->AddValue(132);
+ hist->AddValue(140);
+ hist->AddValue(145);
+ hist->AddValue(155);
+
+ hist->CreateHistogram();
+ PerValue = hist->Percentile(0.50);
+ EXPECT_GE(PerValue, 70);
+ EXPECT_LE(PerValue, 110);
+
+ delete hist;
+}
+;
+
+TEST(Histtest, UpdateRange) {
+
+ Histogram<uint64_t> *hist = new Histogram<uint64_t>("UpdateRange");
+ double PerValue;
+
+ hist->AddValue(15);
+ hist->AddValue(17);
+ hist->AddValue(35);
+ hist->AddValue(50);
+ hist->AddValue(68);
+ hist->AddValue(75);
+ hist->AddValue(93);
+ hist->AddValue(110);
+ hist->AddValue(121);
+ hist->AddValue(132);
+ hist->AddValue(140); //Median value
+ hist->AddValue(145);
+ hist->AddValue(155);
+ hist->AddValue(163);
+ hist->AddValue(168);
+ hist->AddValue(175);
+ hist->AddValue(182);
+ hist->AddValue(193);
+ hist->AddValue(200);
+ hist->AddValue(205);
+ hist->AddValue(212);
+ hist->CreateHistogram();
+ PerValue = hist->Percentile(0.50);
+
+ std::string text;
+ std::stringstream stream;
+ std::string expected =
+ "UpdateRange:\t0.99% C.I. 15.262us-214.475us Avg: 126.380us Max: 212us\n";
+ hist->PrintConfidenceIntervals(stream, 0.99);
+
+ EXPECT_EQ(expected, stream.str());
+ EXPECT_GE(PerValue, 132);
+ EXPECT_LE(PerValue, 145);
+
+ delete hist;
+}
+;
+
+TEST(Histtest, Reset) {
+
+ Histogram<uint64_t> *hist = new Histogram<uint64_t>("Reset");
+ double PerValue;
+ hist->AddValue(0);
+ hist->AddValue(189);
+ hist->AddValue(389);
+ hist->Reset();
+ hist->AddValue(15);
+ hist->AddValue(17);
+ hist->AddValue(35);
+ hist->AddValue(50);
+ hist->AddValue(68);
+ hist->AddValue(75);
+ hist->AddValue(93);
+ hist->AddValue(110);
+ hist->AddValue(121);
+ hist->AddValue(132);
+ hist->AddValue(140); //Median value
+ hist->AddValue(145);
+ hist->AddValue(155);
+ hist->AddValue(163);
+ hist->AddValue(168);
+ hist->AddValue(175);
+ hist->AddValue(182);
+ hist->AddValue(193);
+ hist->AddValue(200);
+ hist->AddValue(205);
+ hist->AddValue(212);
+ hist->CreateHistogram();
+ PerValue = hist->Percentile(0.50);
+
+ std::string text;
+ std::stringstream stream;
+ std::string expected =
+ "Reset:\t0.99% C.I. 15.262us-214.475us Avg: 126.380us Max: 212us\n";
+ hist->PrintConfidenceIntervals(stream, 0.99);
+
+ EXPECT_EQ(expected, stream.str());
+ EXPECT_GE(PerValue, 132);
+ EXPECT_LE(PerValue, 145);
+
+ delete hist;
+}
+;
+
+TEST(Histtest, MultipleCreateHist) {
+
+ Histogram<uint64_t> *hist = new Histogram<uint64_t>("MultipleCreateHist");
+ double PerValue;
+ hist->AddValue(15);
+ hist->AddValue(17);
+ hist->AddValue(35);
+ hist->AddValue(50);
+ hist->AddValue(68);
+ hist->AddValue(75);
+ hist->AddValue(93);
+ hist->CreateHistogram();
+ hist->AddValue(110);
+ hist->AddValue(121);
+ hist->AddValue(132);
+ hist->AddValue(140); //Median value
+ hist->AddValue(145);
+ hist->AddValue(155);
+ hist->AddValue(163);
+ hist->AddValue(168);
+ hist->CreateHistogram();
+ hist->AddValue(175);
+ hist->AddValue(182);
+ hist->AddValue(193);
+ hist->AddValue(200);
+ hist->AddValue(205);
+ hist->AddValue(212);
+ hist->CreateHistogram();
+ PerValue = hist->Percentile(0.50);
+
+ std::string text;
+ std::stringstream stream;
+ std::string expected =
+ "MultipleCreateHist:\t0.99% C.I. 15.262us-214.475us Avg: 126.380us Max: 212us\n";
+ hist->PrintConfidenceIntervals(stream, 0.99);
+
+ EXPECT_EQ(expected, stream.str());
+ EXPECT_GE(PerValue, 132);
+ EXPECT_LE(PerValue, 145);
+
+ delete hist;
+}
+;
+
+TEST(Histtest, SingleValue) {
+
+ Histogram<uint64_t> *hist = new Histogram<uint64_t>("SingleValue");
+ double PerValue_10;
+ double PerValue_90;
+
+ hist->AddValue(1);
+ hist->CreateHistogram();
+ PerValue_10 = hist->Percentile(0.1);
+ PerValue_90 = hist->Percentile(0.9);
+
+ EXPECT_GT(PerValue_10, 0);
+ EXPECT_LT(PerValue_90, 5);
+
+ delete hist;
+}
+;
+
+TEST(Histtest, SpikyValues) {
+
+ Histogram<uint64_t> *hist = new Histogram<uint64_t>("SpikyValues");
+ double PerValue_005;
+ double PerValue_995;
+
+ for (size_t Idx = 0; Idx < 300; Idx++) {
+ hist->AddValue(rand() % 200);
+ }
+
+ hist->AddValue(10000);
+ hist->CreateHistogram();
+ PerValue_005 = hist->Percentile(0.005);
+ PerValue_995 = hist->Percentile(0.995);
+
+ EXPECT_EQ(1.075, PerValue_005);
+ EXPECT_EQ(199747, static_cast<int>(PerValue_995 * 1000));
+ delete hist;
+}
+;
+
+
+
diff --git a/src/base/timing_logger.cc b/src/base/timing_logger.cc
new file mode 100644
index 0000000..d2c7eef
--- /dev/null
+++ b/src/base/timing_logger.cc
@@ -0,0 +1,152 @@
+/*
+ * Copyright (C) 2011 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 "base/logging.h"
+#include "thread.h"
+#include "base/stl_util.h"
+#include "base/histogram-inl.h"
+
+#include <cmath>
+#include <iomanip>
+
+namespace art {
+
+void TimingLogger::Reset() {
+ times_.clear();
+ labels_.clear();
+ AddSplit("");
+}
+
+TimingLogger::TimingLogger(const std::string &name, bool precise)
+ : name_(name),
+ precise_(precise) {
+ AddSplit("");
+}
+
+void TimingLogger::AddSplit(const std::string &label) {
+ times_.push_back(NanoTime());
+ labels_.push_back(label);
+}
+
+uint64_t TimingLogger::GetTotalNs() const {
+ return times_.back() - times_.front();
+}
+;
+
+void TimingLogger::Dump(std::ostream &os) const {
+ uint64_t largest_time = 0;
+ os << name_ << ": begin\n";
+ for (size_t i = 1; i < times_.size(); ++i) {
+ uint64_t delta_time = times_[i] - times_[i - 1];
+ largest_time = std::max(largest_time, delta_time);
+ }
+ // Compute which type of unit we will use for printing the timings.
+ TimeUnit tu = GetAppropriateTimeUnit(largest_time);
+ uint64_t divisor = GetNsToTimeUnitDivisor(tu);
+ for (size_t i = 1; i < times_.size(); ++i) {
+ uint64_t delta_time = times_[i] - times_[i - 1];
+ if (!precise_ && divisor >= 1000) {
+ // Make the fraction 0.
+ delta_time -= delta_time % (divisor / 1000);
+ }
+ os << name_ << ": " << std::setw(8) << FormatDuration(delta_time, tu) << " "
+ << labels_[i] << "\n";
+ }
+ os << name_ << ": end, " << NsToMs(GetTotalNs()) << " ms\n";
+}
+
+CumulativeLogger::CumulativeLogger(const std::string &name)
+ : name_(name),
+ lock_(("CumulativeLoggerLock" + name).c_str(), kDefaultMutexLevel, true) {
+ Reset();
+}
+
+CumulativeLogger::~CumulativeLogger() { STLDeleteElements(&histograms_); }
+
+void CumulativeLogger::SetName(const std::string &name) { name_ = 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_);
+}
+
+uint64_t CumulativeLogger::GetTotalNs() const {
+ return GetTotalTime() * kAdjust;
+}
+
+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();
+ }
+ return total;
+}
+
+void CumulativeLogger::AddLogger(const TimingLogger &logger) {
+ MutexLock mu(Thread::Current(), lock_);
+ DCHECK_EQ(logger.times_.size(), logger.labels_.size());
+ for (size_t i = 1; i < logger.times_.size(); ++i) {
+ const uint64_t delta_time = logger.times_[i] - logger.times_[i - 1];
+ const std::string &label = logger.labels_[i];
+ AddPair(label, delta_time);
+ }
+}
+
+void CumulativeLogger::Dump(std::ostream &os) {
+ MutexLock mu(Thread::Current(), lock_);
+ DumpHistogram(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 (index_ >= histograms_.size()) {
+ Histogram<uint64_t> *tmp_hist = new Histogram<uint64_t>(label);
+ tmp_hist->AddValue(delta_time);
+ histograms_.push_back(tmp_hist);
+ } else {
+ histograms_[index_]->AddValue(delta_time);
+ DCHECK_EQ(label, histograms_[index_]->Name());
+ }
+ index_++;
+}
+
+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++) {
+ Histogram<uint64_t> &hist = *(histograms_[Idx]);
+ hist.CreateHistogram();
+ hist.PrintConfidenceIntervals(os, 0.99);
+ }
+ os << "Done Dumping histograms \n";
+}
+
+} // namespace art
diff --git a/src/base/timing_logger.h b/src/base/timing_logger.h
new file mode 100644
index 0000000..d3f7ef4
--- /dev/null
+++ b/src/base/timing_logger.h
@@ -0,0 +1,81 @@
+/*
+ * Copyright (C) 2011 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.
+ */
+
+#ifndef ART_SRC_TIMING_LOGGER_H_
+#define ART_SRC_TIMING_LOGGER_H_
+
+#include "base/histogram.h"
+#include "base/macros.h"
+#include "base/mutex.h"
+
+#include <string>
+#include <vector>
+
+namespace art {
+
+class CumulativeLogger;
+
+class TimingLogger {
+ public:
+ explicit TimingLogger(const std::string &name, bool precise);
+ void AddSplit(const std::string &label);
+ void Dump(std::ostream &os) const;
+ void Reset();
+ uint64_t GetTotalNs() const;
+
+ protected:
+ std::string name_;
+ bool precise_;
+ std::vector<uint64_t> times_;
+ std::vector<std::string> labels_;
+
+ friend class CumulativeLogger;
+};
+
+class CumulativeLogger {
+
+ public:
+
+ explicit CumulativeLogger(const std::string &name);
+ void prepare_stats();
+ ~CumulativeLogger();
+ void Start();
+ void End();
+ void Reset();
+ void Dump(std::ostream &os) LOCKS_EXCLUDED(lock_);
+ uint64_t GetTotalNs() const;
+ void SetName(const std::string &name);
+ void AddLogger(const TimingLogger &logger) LOCKS_EXCLUDED(lock_);
+
+ private:
+
+ void AddPair(const std::string &label, uint64_t delta_time)
+ EXCLUSIVE_LOCKS_REQUIRED(lock_);
+ 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_);
+ std::string 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);
+};
+
+} // namespace art
+
+#endif // ART_SRC_TIMING_LOGGER_H_
diff --git a/src/compiler.cc b/src/compiler.cc
index 48aa335..580da60 100644
--- a/src/compiler.cc
+++ b/src/compiler.cc
@@ -22,6 +22,7 @@
#include <unistd.h>
#include "base/stl_util.h"
+#include "base/timing_logger.h"
#include "class_linker.h"
#include "jni_internal.h"
#include "oat_compilation_unit.h"
@@ -43,7 +44,6 @@
#include "ScopedLocalRef.h"
#include "thread.h"
#include "thread_pool.h"
-#include "timing_logger.h"
#include "verifier/method_verifier.h"
#if defined(__APPLE__)
@@ -489,14 +489,14 @@
DCHECK(!Runtime::Current()->IsStarted());
UniquePtr<ThreadPool> thread_pool(new ThreadPool(thread_count_));
- TimingLogger timings("compiler");
+ TimingLogger timings("compiler", false);
PreCompile(class_loader, dex_files, *thread_pool.get(), timings);
Compile(class_loader, dex_files, *thread_pool.get(), timings);
if (dump_timings_ && timings.GetTotalNs() > MsToNs(1000)) {
- timings.Dump();
+ LOG(INFO) << Dumpable<TimingLogger>(timings);
}
if (dump_stats_) {
@@ -527,7 +527,7 @@
dex_files.push_back(dex_file);
UniquePtr<ThreadPool> thread_pool(new ThreadPool(1U));
- TimingLogger timings("CompileOne");
+ TimingLogger timings("CompileOne", false);
PreCompile(class_loader, dex_files, *thread_pool.get(), timings);
uint32_t method_idx = method->GetDexMethodIndex();
diff --git a/src/dex2oat.cc b/src/dex2oat.cc
index bc38bdc..d0bd2fc 100644
--- a/src/dex2oat.cc
+++ b/src/dex2oat.cc
@@ -25,6 +25,7 @@
#include "base/stl_util.h"
#include "base/stringpiece.h"
+#include "base/timing_logger.h"
#include "base/unix_file/fd_file.h"
#include "class_linker.h"
#include "compiler.h"
@@ -42,7 +43,6 @@
#include "ScopedLocalRef.h"
#include "scoped_thread_state_change.h"
#include "sirt_ref.h"
-#include "timing_logger.h"
#include "vector_output_stream.h"
#include "well_known_classes.h"
#include "zip_archive.h"
diff --git a/src/gc/mark_sweep.cc b/src/gc/mark_sweep.cc
index 81d5e17..8240d11 100644
--- a/src/gc/mark_sweep.cc
+++ b/src/gc/mark_sweep.cc
@@ -25,6 +25,7 @@
#include "base/logging.h"
#include "base/macros.h"
#include "base/mutex-inl.h"
+#include "base/timing_logger.h"
#include "card_table.h"
#include "card_table-inl.h"
#include "heap.h"
@@ -45,7 +46,6 @@
#include "runtime.h"
#include "space.h"
#include "space_bitmap-inl.h"
-#include "timing_logger.h"
#include "thread.h"
#include "thread_list.h"
#include "verifier/method_verifier.h"
@@ -139,7 +139,7 @@
large_object_lock_("large object lock"),
mark_stack_expand_lock_("mark stack expand lock"),
timings_(GetName(), true),
- cumulative_timings_(GetName(), true),
+ cumulative_timings_(GetName()),
is_concurrent_(is_concurrent) {
cumulative_timings_.SetName(GetName());
ResetCumulativeStatistics();
@@ -829,18 +829,6 @@
MarkSweep* mark_sweep_;
};
-Barrier& MarkSweep::GetBarrier() {
- return *gc_barrier_;
-}
-
-const TimingLogger& MarkSweep::GetTimings() const {
- return timings_;
-}
-
-const CumulativeLogger& MarkSweep::GetCumulativeTimings() const {
- return cumulative_timings_;
-}
-
void MarkSweep::ResetCumulativeStatistics() {
cumulative_timings_.Reset();
total_time_ = 0;
diff --git a/src/gc/mark_sweep.h b/src/gc/mark_sweep.h
index 0d43bee..859f309 100644
--- a/src/gc/mark_sweep.h
+++ b/src/gc/mark_sweep.h
@@ -20,11 +20,11 @@
#include "atomic_integer.h"
#include "base/macros.h"
#include "base/mutex.h"
+#include "base/timing_logger.h"
#include "garbage_collector.h"
#include "gc_type.h"
#include "offsets.h"
#include "root_visitor.h"
-#include "timing_logger.h"
#include "UniquePtr.h"
namespace art {
@@ -233,9 +233,18 @@
SHARED_LOCKS_REQUIRED(Locks::mutator_lock_)
EXCLUSIVE_LOCKS_REQUIRED(Locks::heap_bitmap_lock_);
- Barrier& GetBarrier();
- const TimingLogger& GetTimings() const;
- const CumulativeLogger& GetCumulativeTimings() const;
+ Barrier& GetBarrier() {
+ return *gc_barrier_;
+ }
+
+ TimingLogger& GetTimings() {
+ return timings_;
+ }
+
+ CumulativeLogger& GetCumulativeTimings() {
+ return cumulative_timings_;
+ }
+
void ResetCumulativeStatistics();
protected:
diff --git a/src/heap.cc b/src/heap.cc
index e531dc8..f7abe0a 100644
--- a/src/heap.cc
+++ b/src/heap.cc
@@ -51,7 +51,6 @@
#include "scoped_thread_state_change.h"
#include "sirt_ref.h"
#include "thread_list.h"
-#include "timing_logger.h"
#include "UniquePtr.h"
#include "well_known_classes.h"
@@ -377,11 +376,11 @@
// TODO: C++0x
uint64_t total_paused_time = 0;
for (Collectors::const_iterator it = mark_sweep_collectors_.begin();
- it != mark_sweep_collectors_.end(); ++it) {
+ it != mark_sweep_collectors_.end(); ++it) {
MarkSweep* collector = *it;
- const CumulativeLogger& logger = collector->GetCumulativeTimings();
+ CumulativeLogger& logger = collector->GetCumulativeTimings();
if (logger.GetTotalNs() != 0) {
- logger.Dump();
+ LOG(INFO) << Dumpable<CumulativeLogger>(logger);
const uint64_t total_ns = logger.GetTotalNs();
const uint64_t total_pause_ns = (*it)->GetTotalPausedTime();
double seconds = NsToMs(logger.GetTotalNs()) / 1000.0;
@@ -1155,12 +1154,12 @@
<< ((i != pauses.size() - 1) ? ", " : "");
}
LOG(INFO) << gc_cause << " " << collector->GetName()
- << "GC freed " << PrettySize(collector->GetFreedBytes()) << ", "
- << percent_free << "% free, " << PrettySize(current_heap_size) << "/"
- << PrettySize(total_memory) << ", " << "paused " << pause_string.str()
- << " total " << PrettyDuration((duration / 1000) * 1000);
+ << "GC freed " << PrettySize(collector->GetFreedBytes()) << ", "
+ << percent_free << "% free, " << PrettySize(current_heap_size) << "/"
+ << PrettySize(total_memory) << ", " << "paused " << pause_string.str()
+ << " total " << PrettyDuration((duration / 1000) * 1000);
if (VLOG_IS_ON(heap)) {
- collector->GetTimings().Dump();
+ LOG(INFO) << Dumpable<TimingLogger>(collector->GetTimings());
}
}
diff --git a/src/heap.h b/src/heap.h
index 9981f83..7af15cd 100644
--- a/src/heap.h
+++ b/src/heap.h
@@ -22,6 +22,7 @@
#include <vector>
#include "atomic_integer.h"
+#include "base/timing_logger.h"
#include "gc/atomic_stack.h"
#include "gc/card_table.h"
#include "gc/gc_type.h"
@@ -31,7 +32,6 @@
#include "locks.h"
#include "offsets.h"
#include "safe_map.h"
-#include "timing_logger.h"
#include "thread_pool.h"
#define VERIFY_OBJECT_ENABLED 0
diff --git a/src/thread_list.cc b/src/thread_list.cc
index ea8baac..45ddd23 100644
--- a/src/thread_list.cc
+++ b/src/thread_list.cc
@@ -21,9 +21,9 @@
#include <unistd.h>
#include "base/mutex.h"
+#include "base/timing_logger.h"
#include "debugger.h"
#include "thread.h"
-#include "timing_logger.h"
#include "utils.h"
namespace art {
@@ -210,8 +210,8 @@
// Shouldn't need to wait for longer than 1 millisecond.
const uint64_t threshold = 1;
if (NsToMs(end - start) > threshold) {
- LOG(INFO) << "Warning: waited longer than " << threshold << " ms for thread suspend"
- << std::endl;
+ LOG(INFO) << "Warning: waited longer than " << threshold
+ << " ms for thread suspend\n";
}
}
// We know for sure that the thread is suspended at this point.
diff --git a/src/timing_logger.cc b/src/timing_logger.cc
deleted file mode 100644
index fee7a30..0000000
--- a/src/timing_logger.cc
+++ /dev/null
@@ -1,98 +0,0 @@
-/*
- * Copyright (C) 2011 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 "base/logging.h"
-#include "utils.h"
-
-#include <cmath>
-#include <iomanip>
-
-namespace art {
-
-void TimingLogger::Dump() const {
- Dump(LOG(INFO));
-}
-
-void TimingLogger::Dump(std::ostream& os) const {
- uint64_t largest_time = 0;
- os << name_ << ": begin\n";
- for (size_t i = 1; i < times_.size(); ++i) {
- uint64_t delta_time = times_[i] - times_[i - 1];
- largest_time = std::max(largest_time, delta_time);
- }
- // Compute which type of unit we will use for printing the timings.
- TimeUnit tu = GetAppropriateTimeUnit(largest_time);
- uint64_t divisor = GetNsToTimeUnitDivisor(tu);
- for (size_t i = 1; i < times_.size(); ++i) {
- uint64_t delta_time = times_[i] - times_[i - 1];
- if (!precise_ && divisor >= 1000) {
- // Make the fraction 0.
- delta_time -= delta_time % (divisor / 1000);
- }
- os << name_ << ": " << std::setw(8) << FormatDuration(delta_time, tu) << " " << labels_[i]
- << "\n";
- }
- os << name_ << ": end, " << NsToMs(GetTotalNs()) << " ms\n";
-}
-
-void CumulativeLogger::Dump() const {
- Dump(LOG(INFO));
-}
-
-void CumulativeLogger::Dump(std::ostream& os) const {
- os << name_ << ": iterations " << iterations_ << " begin\n";
- //Find which unit we will use for the timing logger.
- uint64_t largest_mean = 0;
- for (size_t i = 0; i < times_.size(); ++i) {
- // Convert back to nanoseconds from microseconds.
- uint64_t mean = times_[i] / iterations_;
- largest_mean = std::max(largest_mean, mean);
- }
- // Convert largest mean back to ns
- TimeUnit tu = GetAppropriateTimeUnit(largest_mean * kAdjust);
- uint64_t divisor = GetNsToTimeUnitDivisor(tu);
- for (size_t i = 0; i < times_.size(); ++i) {
- uint64_t mean_x2 = times_squared_[i] / iterations_;
- uint64_t mean = times_[i] / iterations_;
- uint64_t variance = mean_x2 - (mean * mean);
- uint64_t std_dev = static_cast<uint64_t>(std::sqrt(static_cast<double>(variance)));
- if (!precise_ && divisor >= 1000) {
- // Make the fraction 0.
- mean -= mean % (divisor / 1000);
- std_dev -= std_dev % (divisor / 1000);
- }
- os << StringPrintf("%s: %10s (std_dev %8s) %s\n",
- name_.c_str(),
- FormatDuration(mean * kAdjust, tu).c_str(),
- FormatDuration(std_dev * kAdjust, tu).c_str(),
- labels_[i].c_str());
- }
- uint64_t total_mean_x2 = total_time_squared_;
- uint64_t mean_total_ns = GetTotalTime();
- if (iterations_ != 0) {
- total_mean_x2 /= iterations_;
- mean_total_ns /= iterations_;
- }
- uint64_t total_variance = total_mean_x2 - (mean_total_ns * mean_total_ns);
- uint64_t total_std_dev = static_cast<uint64_t>(
- std::sqrt(static_cast<double>(total_variance)));
- os << name_ << ": end, mean " << PrettyDuration(mean_total_ns * kAdjust)
- << " std_dev " << PrettyDuration(total_std_dev * kAdjust) << "\n";
-}
-
-} // namespace art
diff --git a/src/timing_logger.h b/src/timing_logger.h
deleted file mode 100644
index fc47028..0000000
--- a/src/timing_logger.h
+++ /dev/null
@@ -1,160 +0,0 @@
-/*
- * Copyright (C) 2011 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.
- */
-
-#ifndef ART_SRC_TIMING_LOGGER_H_
-#define ART_SRC_TIMING_LOGGER_H_
-
-#include "utils.h" // For NanoTime.
-
-#include <stdint.h>
-#include <string>
-#include <vector>
-
-namespace art {
-
-class CumulativeLogger;
-
-class TimingLogger {
- public:
- explicit TimingLogger(const std::string& name, bool precise = false)
- : name_(name), precise_(precise) {
- AddSplit("");
- }
-
- void Reset() {
- times_.clear();
- labels_.clear();
- AddSplit("");
- }
-
- void AddSplit(const std::string& label) {
- times_.push_back(NanoTime());
- labels_.push_back(label);
- }
-
- void Dump() const;
-
- void Dump(std::ostream& os) const;
-
- uint64_t GetTotalNs() const {
- return times_.back() - times_.front();
- }
-
- protected:
- std::string name_;
- bool precise_;
- std::vector<uint64_t> times_;
- std::vector<std::string> labels_;
-
- friend class CumulativeLogger;
-};
-
-class CumulativeLogger {
- public:
- explicit CumulativeLogger(const std::string& name = "", bool precise = false)
- : name_(name),
- precise_(precise) {
- Reset();
- }
-
- void SetName(const std::string& name) {
- name_ = name;
- }
-
- void Start() {
- index_ = 0;
- last_split_ = NanoTime();
- }
-
- void End() {
- iterations_++;
- }
-
- void AddSplit(const std::string& label) {
- uint64_t cur_time = NanoTime();
- AddPair(label, cur_time - last_split_);
- last_split_ = cur_time;
- }
-
- void Reset() {
- times_.clear();
- labels_.clear();
- times_squared_.clear();
- iterations_ = 0;
- total_time_squared_ = 0;
- }
-
- void 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 (index_ >= times_.size()) {
- times_.push_back(delta_time);
- times_squared_.push_back(delta_time * delta_time);
- labels_.push_back(label);
- } else {
- times_[index_] += delta_time;
- times_squared_[index_] += delta_time * delta_time;
- DCHECK_EQ(labels_[index_], label);
- }
- index_++;
- }
-
- void AddLogger(const TimingLogger& logger) {
- DCHECK_EQ(logger.times_.size(), logger.labels_.size());
- uint64_t total_time = 0;
- for (size_t i = 1; i < logger.times_.size(); ++i) {
- const uint64_t delta_time = logger.times_[i] - logger.times_[i - 1];
- const std::string& label = logger.labels_[i];
- AddPair(label, delta_time);
- total_time += delta_time;
- }
- total_time /= kAdjust;
- total_time_squared_ += total_time * total_time;
- }
-
- void Dump() const;
-
- void Dump(std::ostream& os) const;
-
- uint64_t GetTotalNs() const {
- return GetTotalTime() * kAdjust;
- }
-
- private:
-
- uint64_t GetTotalTime() const {
- uint64_t total = 0;
- for (size_t i = 0; i < times_.size(); ++i) {
- total += times_[i];
- }
- return total;
- }
-
- static const uint64_t kAdjust = 1000;
- std::string name_;
- bool precise_;
- uint64_t total_time_squared_;
- std::vector<uint64_t> times_;
- std::vector<uint64_t> times_squared_;
- std::vector<std::string> labels_;
- size_t index_;
- size_t iterations_;
- uint64_t last_split_;
-};
-
-} // namespace art
-
-#endif // ART_SRC_TIMING_LOGGER_H_