Home | History | Annotate | Download | only in base
      1 /*
      2  * Copyright (C) 2011 The Android Open Source Project
      3  *
      4  * Licensed under the Apache License, Version 2.0 (the "License");
      5  * you may not use this file except in compliance with the License.
      6  * You may obtain a copy of the License at
      7  *
      8  *      http://www.apache.org/licenses/LICENSE-2.0
      9  *
     10  * Unless required by applicable law or agreed to in writing, software
     11  * distributed under the License is distributed on an "AS IS" BASIS,
     12  * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
     13  * See the License for the specific language governing permissions and
     14  * limitations under the License.
     15  */
     16 
     17 
     18 #define ATRACE_TAG ATRACE_TAG_DALVIK
     19 #include <stdio.h>
     20 #include <cutils/trace.h>
     21 
     22 #include "timing_logger.h"
     23 
     24 #include "base/logging.h"
     25 #include "thread-inl.h"
     26 #include "base/stl_util.h"
     27 #include "base/histogram-inl.h"
     28 
     29 #include <cmath>
     30 #include <iomanip>
     31 
     32 namespace art {
     33 
     34 constexpr size_t CumulativeLogger::kLowMemoryBucketCount;
     35 constexpr size_t CumulativeLogger::kDefaultBucketCount;
     36 constexpr size_t TimingLogger::kIndexNotFound;
     37 
     38 CumulativeLogger::CumulativeLogger(const std::string& name)
     39     : name_(name),
     40       lock_name_("CumulativeLoggerLock" + name),
     41       lock_(lock_name_.c_str(), kDefaultMutexLevel, true) {
     42   Reset();
     43 }
     44 
     45 CumulativeLogger::~CumulativeLogger() {
     46   STLDeleteElements(&histograms_);
     47 }
     48 
     49 void CumulativeLogger::SetName(const std::string& name) {
     50   MutexLock mu(Thread::Current(), lock_);
     51   name_.assign(name);
     52 }
     53 
     54 void CumulativeLogger::Start() {
     55 }
     56 
     57 void CumulativeLogger::End() {
     58   MutexLock mu(Thread::Current(), lock_);
     59   ++iterations_;
     60 }
     61 
     62 void CumulativeLogger::Reset() {
     63   MutexLock mu(Thread::Current(), lock_);
     64   iterations_ = 0;
     65   total_time_ = 0;
     66   STLDeleteElements(&histograms_);
     67 }
     68 
     69 void CumulativeLogger::AddLogger(const TimingLogger &logger) {
     70   MutexLock mu(Thread::Current(), lock_);
     71   TimingLogger::TimingData timing_data(logger.CalculateTimingData());
     72   const std::vector<TimingLogger::Timing>& timings = logger.GetTimings();
     73   for (size_t i = 0; i < timings.size(); ++i) {
     74     if (timings[i].IsStartTiming()) {
     75       AddPair(timings[i].GetName(), timing_data.GetExclusiveTime(i));
     76     }
     77   }
     78   ++iterations_;
     79 }
     80 
     81 size_t CumulativeLogger::GetIterations() const {
     82   MutexLock mu(Thread::Current(), lock_);
     83   return iterations_;
     84 }
     85 
     86 void CumulativeLogger::Dump(std::ostream &os) const {
     87   MutexLock mu(Thread::Current(), lock_);
     88   DumpHistogram(os);
     89 }
     90 
     91 void CumulativeLogger::AddPair(const std::string& label, uint64_t delta_time) {
     92   // Convert delta time to microseconds so that we don't overflow our counters.
     93   delta_time /= kAdjust;
     94   total_time_ += delta_time;
     95   Histogram<uint64_t>* histogram;
     96   Histogram<uint64_t> dummy(label.c_str());
     97   auto it = histograms_.find(&dummy);
     98   if (it == histograms_.end()) {
     99     const size_t max_buckets = Runtime::Current()->GetHeap()->IsLowMemoryMode() ?
    100         kLowMemoryBucketCount : kDefaultBucketCount;
    101     histogram = new Histogram<uint64_t>(label.c_str(), kInitialBucketSize, max_buckets);
    102     histograms_.insert(histogram);
    103   } else {
    104     histogram = *it;
    105   }
    106   histogram->AddValue(delta_time);
    107 }
    108 
    109 class CompareHistorgramByTimeSpentDeclining {
    110  public:
    111   bool operator()(const Histogram<uint64_t>* a, const Histogram<uint64_t>* b) const {
    112     return a->Sum() > b->Sum();
    113   }
    114 };
    115 
    116 void CumulativeLogger::DumpHistogram(std::ostream &os) const {
    117   os << "Start Dumping histograms for " << iterations_ << " iterations"
    118      << " for " << name_ << "\n";
    119   std::set<Histogram<uint64_t>*, CompareHistorgramByTimeSpentDeclining>
    120       sorted_histograms(histograms_.begin(), histograms_.end());
    121   for (Histogram<uint64_t>* histogram : sorted_histograms) {
    122     Histogram<uint64_t>::CumulativeData cumulative_data;
    123     // We don't expect DumpHistogram to be called often, so it is not performance critical.
    124     histogram->CreateHistogram(&cumulative_data);
    125     histogram->PrintConfidenceIntervals(os, 0.99, cumulative_data);
    126   }
    127   os << "Done Dumping histograms \n";
    128 }
    129 
    130 TimingLogger::TimingLogger(const char* name, bool precise, bool verbose)
    131     : name_(name), precise_(precise), verbose_(verbose) {
    132 }
    133 
    134 void TimingLogger::Reset() {
    135   timings_.clear();
    136 }
    137 
    138 void TimingLogger::StartTiming(const char* label) {
    139   DCHECK(label != nullptr);
    140   timings_.push_back(Timing(NanoTime(), label));
    141   ATRACE_BEGIN(label);
    142 }
    143 
    144 void TimingLogger::EndTiming() {
    145   timings_.push_back(Timing(NanoTime(), nullptr));
    146   ATRACE_END();
    147 }
    148 
    149 uint64_t TimingLogger::GetTotalNs() const {
    150   if (timings_.size() < 2) {
    151     return 0;
    152   }
    153   return timings_.back().GetTime() - timings_.front().GetTime();
    154 }
    155 
    156 size_t TimingLogger::FindTimingIndex(const char* name, size_t start_idx) const {
    157   DCHECK_LT(start_idx, timings_.size());
    158   for (size_t i = start_idx; i < timings_.size(); ++i) {
    159     if (timings_[i].IsStartTiming() && strcmp(timings_[i].GetName(), name) == 0) {
    160       return i;
    161     }
    162   }
    163   return kIndexNotFound;
    164 }
    165 
    166 TimingLogger::TimingData TimingLogger::CalculateTimingData() const {
    167   TimingLogger::TimingData ret;
    168   ret.data_.resize(timings_.size());
    169   std::vector<size_t> open_stack;
    170   for (size_t i = 0; i < timings_.size(); ++i) {
    171     if (timings_[i].IsEndTiming()) {
    172       CHECK(!open_stack.empty()) << "No starting split for ending split at index " << i;
    173       size_t open_idx = open_stack.back();
    174       uint64_t time = timings_[i].GetTime() - timings_[open_idx].GetTime();
    175       ret.data_[open_idx].exclusive_time += time;
    176       DCHECK_EQ(ret.data_[open_idx].total_time, 0U);
    177       ret.data_[open_idx].total_time += time;
    178       // Each open split has exactly one end.
    179       open_stack.pop_back();
    180       // If there is a parent node, subtract from the exclusive time.
    181       if (!open_stack.empty()) {
    182         // Note this may go negative, but will work due to 2s complement when we add the value
    183         // total time value later.
    184         ret.data_[open_stack.back()].exclusive_time -= time;
    185       }
    186     } else {
    187       open_stack.push_back(i);
    188     }
    189   }
    190   CHECK(open_stack.empty()) << "Missing ending for timing "
    191       << timings_[open_stack.back()].GetName() << " at index " << open_stack.back();
    192   return ret;  // No need to fear, C++11 move semantics are here.
    193 }
    194 
    195 void TimingLogger::Dump(std::ostream &os, const char* indent_string) const {
    196   static constexpr size_t kFractionalDigits = 3;
    197   TimingLogger::TimingData timing_data(CalculateTimingData());
    198   uint64_t longest_split = 0;
    199   for (size_t i = 0; i < timings_.size(); ++i) {
    200     longest_split = std::max(longest_split, timing_data.GetTotalTime(i));
    201   }
    202   // Compute which type of unit we will use for printing the timings.
    203   TimeUnit tu = GetAppropriateTimeUnit(longest_split);
    204   uint64_t divisor = GetNsToTimeUnitDivisor(tu);
    205   uint64_t mod_fraction = divisor >= 1000 ? divisor / 1000 : 1;
    206   // Print formatted splits.
    207   size_t tab_count = 1;
    208   os << name_ << " [Exclusive time] [Total time]\n";
    209   for (size_t i = 0; i < timings_.size(); ++i) {
    210     if (timings_[i].IsStartTiming()) {
    211       uint64_t exclusive_time = timing_data.GetExclusiveTime(i);
    212       uint64_t total_time = timing_data.GetTotalTime(i);
    213       if (!precise_) {
    214         // Make the fractional part 0.
    215         exclusive_time -= exclusive_time % mod_fraction;
    216         total_time -= total_time % mod_fraction;
    217       }
    218       for (size_t j = 0; j < tab_count; ++j) {
    219         os << indent_string;
    220       }
    221       os << FormatDuration(exclusive_time, tu, kFractionalDigits);
    222       // If they are the same, just print one value to prevent spam.
    223       if (exclusive_time != total_time) {
    224         os << "/" << FormatDuration(total_time, tu, kFractionalDigits);
    225       }
    226       os << " " << timings_[i].GetName() << "\n";
    227       ++tab_count;
    228     } else {
    229       --tab_count;
    230     }
    231   }
    232   os << name_ << ": end, " << PrettyDuration(GetTotalNs()) << "\n";
    233 }
    234 
    235 void TimingLogger::Verify() {
    236   size_t counts[2] = { 0 };
    237   for (size_t i = 0; i < timings_.size(); ++i) {
    238     if (i > 0) {
    239       CHECK_LE(timings_[i - 1].GetTime(), timings_[i].GetTime());
    240     }
    241     ++counts[timings_[i].IsStartTiming() ? 0 : 1];
    242   }
    243   CHECK_EQ(counts[0], counts[1]) << "Number of StartTiming and EndTiming doesn't match";
    244 }
    245 
    246 TimingLogger::~TimingLogger() {
    247   if (kIsDebugBuild) {
    248     Verify();
    249   }
    250 }
    251 
    252 }  // namespace art
    253