Add systrace support to NewTimingLogger, migrate compiler timing logging to NewTimingLogger
Rpleaced old TimingLogger by NewTimingLogger, renamed NewTimingLogger to TimingLogger, added systrace support to TimingLogger.
Tests passing, phone booting, systrace working.
Change-Id: I2aeffb8bcb7f0fd979d8a2a3a8bcfbaa02413679
diff --git a/runtime/base/timing_logger.cc b/runtime/base/timing_logger.cc
index bf6fd17..dfb0220 100644
--- a/runtime/base/timing_logger.cc
+++ b/runtime/base/timing_logger.cc
@@ -14,6 +14,11 @@
* limitations under the License.
*/
+
+#define ATRACE_TAG ATRACE_TAG_DALVIK
+#include <stdio.h>
+#include <cutils/trace.h>
+
#include "timing_logger.h"
#include "base/logging.h"
@@ -26,49 +31,6 @@
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),
@@ -112,17 +74,8 @@
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) {
+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;
@@ -183,51 +136,55 @@
namespace base {
-NewTimingLogger::NewTimingLogger(const char* name, bool precise, bool verbose)
+TimingLogger::TimingLogger(const char* name, bool precise, bool verbose)
: name_(name), precise_(precise), verbose_(verbose),
current_split_(NULL), current_split_start_ns_(0) {
}
-void NewTimingLogger::Reset() {
+void TimingLogger::Reset() {
current_split_ = NULL;
current_split_start_ns_ = 0;
splits_.clear();
}
-void NewTimingLogger::StartSplit(const char* new_split_label) {
+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();
}
// Ends the current split and starts the one given by the label.
-void NewTimingLogger::NewSplit(const char* new_split_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;
}
-void NewTimingLogger::EndSplit() {
+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_));
}
-uint64_t NewTimingLogger::GetTotalNs() const {
+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) {
@@ -237,7 +194,7 @@
return total_ns;
}
-void NewTimingLogger::Dump(std::ostream &os) 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;