runtime/base/timing_logger.cc

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


#define ATRACE_TAG ATRACE_TAG_DALVIK
#include <stdio.h>
#include <cutils/trace.h>

#include "timing_logger.h"

#include "base/logging.h"
#include "thread-inl.h"
#include "base/stl_util.h"
#include "base/histogram-inl.h"

#include <cmath>
#include <iomanip>

namespace art {

constexpr size_t CumulativeLogger::kLowMemoryBucketCount;
constexpr size_t CumulativeLogger::kDefaultBucketCount;
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() {
}

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 (Histogram<uint64_t>* histogram : histograms_) {
    total += histogram->Sum();
  }
  return total;
}

void CumulativeLogger::AddLogger(const TimingLogger &logger) {
  MutexLock mu(Thread::Current(), lock_);
  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);
  }
}

size_t CumulativeLogger::GetIterations() const {
  MutexLock mu(Thread::Current(), lock_);
  return iterations_;
}

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;

  Histogram<uint64_t>* histogram;
  Histogram<uint64_t> dummy(label.c_str());
  auto it = histograms_.find(&dummy);
  if (it == histograms_.end()) {
    const size_t max_buckets = Runtime::Current()->GetHeap()->IsLowMemoryMode() ?
        kLowMemoryBucketCount : kDefaultBucketCount;
    histogram = new Histogram<uint64_t>(label.c_str(), kInitialBucketSize, max_buckets);
    histograms_.insert(histogram);
  } else {
    histogram = *it;
  }
  histogram->AddValue(delta_time);
}

class CompareHistorgramByTimeSpentDeclining {
 public:
  bool operator()(const Histogram<uint64_t>* a, const Histogram<uint64_t>* b) const {
    return a->Sum() > b->Sum();
  }
};

void CumulativeLogger::DumpHistogram(std::ostream &os) {
  os << "Start Dumping histograms for " << iterations_ << " iterations"
     << " for " << name_ << "\n";
  std::set<Histogram<uint64_t>*, CompareHistorgramByTimeSpentDeclining>
      sorted_histograms(histograms_.begin(), histograms_.end());
  for (Histogram<uint64_t>* histogram : sorted_histograms) {
    Histogram<uint64_t>::CumulativeData cumulative_data;
    // We don't expect DumpHistogram to be called often, so it is not performance critical.
    histogram->CreateHistogram(&cumulative_data);
    histogram->PrintConfidenceIntervals(os, 0.99, cumulative_data);
  }
  os << "Done Dumping histograms \n";
}

TimingLogger::TimingLogger(const char* name, bool precise, bool verbose)
    : name_(name), precise_(precise), verbose_(verbose), current_split_(NULL) {
}

void TimingLogger::Reset() {
  current_split_ = NULL;
  splits_.clear();
}

void TimingLogger::StartSplit(const char* new_split_label) {
  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_ != 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) {
  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 (auto it = splits_.begin(), end = splits_.end(); it != end; ++it) {
    TimingLogger::SplitTiming split = *it;
    total_ns += split.first;
  }
  return total_ns;
}

void TimingLogger::Dump(std::ostream &os) const {
  uint64_t longest_split = 0;
  uint64_t total_ns = 0;
  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;
  }
  // 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 (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.
      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";
}


TimingLogger::ScopedSplit::ScopedSplit(const char* label, TimingLogger* timing_logger) {
  DCHECK(label != NULL) << "New scoped split (" << label << ") with null label.";
  CHECK(timing_logger != NULL) << "New scoped split (" << label << ") without TimingLogger.";
  timing_logger_ = timing_logger;
  label_ = label;
  running_ns_ = 0;
  explicit_ = false;

  // Stash away the current split and pause it.
  enclosing_split_ = timing_logger->current_split_;
  if (enclosing_split_ != NULL) {
    enclosing_split_->Pause();
  }

  timing_logger_->current_split_ = this;

  ATRACE_BEGIN(label_);

  start_ns_ = NanoTime();
  if (timing_logger_->verbose_) {
    LOG(INFO) << "Begin: " << label_;
  }
}

TimingLogger::ScopedSplit::~ScopedSplit() {
  uint64_t current_time = NanoTime();
  uint64_t split_time = current_time - start_ns_;
  running_ns_ += split_time;
  ATRACE_END();

  if (timing_logger_->verbose_) {
    LOG(INFO) << "End: " << label_ << " " << PrettyDuration(split_time);
  }

  // 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_;
  while ((current != NULL) && (current != this)) {
    delete current;
    current = timing_logger_->current_split_;
  }

  CHECK(current != NULL) << "Missing scoped split (" << this->label_
                           << ") in timing logger (" << timing_logger_->name_ << ").";
  CHECK(timing_logger_->current_split_ == this);

  timing_logger_->splits_.push_back(SplitTiming(running_ns_, label_));

  timing_logger_->current_split_ = enclosing_split_;
  if (enclosing_split_ != NULL) {
    enclosing_split_->Resume();
  }
}


void TimingLogger::ScopedSplit::TailInsertSplit(const char* label) {
  // Sleight of hand here: Rather than embedding a new scoped split, we're updating the current
  // scoped split in place. Basically, it's one way to make explicit and scoped splits compose
  // well while maintaining the current semantics of NewSplit. An alternative is to push a new split
  // since we unwind the stack of scoped splits in the scoped split destructor. However, this implies
  // that the current split is not ended by NewSplit (which calls TailInsertSplit), which would
  // be different from what we had before.

  uint64_t current_time = NanoTime();
  uint64_t split_time = current_time - start_ns_;
  ATRACE_END();
  timing_logger_->splits_.push_back(std::pair<uint64_t, const char*>(split_time, label_));

  if (timing_logger_->verbose_) {
    LOG(INFO) << "End: " << label_ << " " << PrettyDuration(split_time) << "\n"
              << "Begin: " << label;
  }

  label_ = label;
  start_ns_ = current_time;
  running_ns_ = 0;

  ATRACE_BEGIN(label);
}

void TimingLogger::ScopedSplit::Pause() {
  uint64_t current_time = NanoTime();
  uint64_t split_time = current_time - start_ns_;
  running_ns_ += split_time;
  ATRACE_END();
}


void TimingLogger::ScopedSplit::Resume() {
  uint64_t current_time = NanoTime();

  start_ns_ = current_time;
  ATRACE_BEGIN(label_);
}

}  // namespace art