summaryrefslogtreecommitdiffstats
path: root/runtime/base/timing_logger.cc
diff options
context:
space:
mode:
Diffstat (limited to 'runtime/base/timing_logger.cc')
-rw-r--r--runtime/base/timing_logger.cc269
1 files changed, 269 insertions, 0 deletions
diff --git a/runtime/base/timing_logger.cc b/runtime/base/timing_logger.cc
new file mode 100644
index 0000000000..c7cbbe504f
--- /dev/null
+++ b/runtime/base/timing_logger.cc
@@ -0,0 +1,269 @@
+/*
+ * 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_name_("CumulativeLoggerLock" + name),
+ lock_(lock_name_.c_str(), kDefaultMutexLevel, true) {
+ Reset();
+}
+
+CumulativeLogger::~CumulativeLogger() {
+ STLDeleteElements(&histograms_);
+}
+
+void CumulativeLogger::SetName(const std::string& name) {
+ name_.assign(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::AddNewLogger(const base::NewTimingLogger &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;
+ if (kIsDebugBuild && 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;
+ uint64_t split_time = split.first;
+ const char* split_name = split.second;
+ AddPair(split_name, split_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 base {
+
+NewTimingLogger::NewTimingLogger(const char* name, bool precise, bool verbose)
+ : name_(name), precise_(precise), verbose_(verbose),
+ current_split_(NULL), current_split_start_ns_(0) {
+}
+
+void NewTimingLogger::Reset() {
+ current_split_ = NULL;
+ current_split_start_ns_ = 0;
+ splits_.clear();
+}
+
+void NewTimingLogger::StartSplit(const char* new_split_label) {
+ DCHECK(current_split_ == NULL);
+ if (verbose_) {
+ LOG(INFO) << "Begin: " << new_split_label;
+ }
+ current_split_ = new_split_label;
+ current_split_start_ns_ = NanoTime();
+}
+
+// Ends the current split and starts the one given by the label.
+void NewTimingLogger::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_;
+ 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;
+ current_split_start_ns_ = current_time;
+}
+
+void NewTimingLogger::EndSplit() {
+ DCHECK(current_split_ != NULL);
+ uint64_t current_time = NanoTime();
+ uint64_t split_time = current_time - current_split_start_ns_;
+ if (verbose_) {
+ LOG(INFO) << "End: " << current_split_ << " " << PrettyDuration(split_time);
+ }
+ splits_.push_back(std::pair<uint64_t, const char*>(split_time, current_split_));
+}
+
+uint64_t NewTimingLogger::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;
+ total_ns += split.first;
+ }
+ return total_ns;
+}
+
+void NewTimingLogger::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;
+ uint64_t split_time = split.first;
+ longest_split = std::max(longest_split, split_time);
+ total_ns += split_time;
+ }
+ // Compute which type of unit we will use for printing the timings.
+ 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;
+ uint64_t split_time = split.first;
+ if (!precise_ && divisor >= 1000) {
+ // Make the fractional part 0.
+ split_time -= split_time % (divisor / 1000);
+ }
+ os << name_ << ": " << std::setw(8) << FormatDuration(split_time, tu) << " "
+ << split.second << "\n";
+ }
+ os << name_ << ": end, " << NsToMs(total_ns) << " ms\n";
+}
+
+} // namespace base
+} // namespace art
generated by cgit v1.2.3 (git 2.25.1) at 2025-07-23 10:01:08 +0000