src/base/timing_logger.cc - platform/art - Git at Google

 /*
  * 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
	/*
	* 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