1a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal/* 2a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal * Copyright (C) 2011 The Android Open Source Project 3a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal * 4a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal * Licensed under the Apache License, Version 2.0 (the "License"); 5a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal * you may not use this file except in compliance with the License. 6a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal * You may obtain a copy of the License at 7a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal * 8a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal * http://www.apache.org/licenses/LICENSE-2.0 9a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal * 10a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal * Unless required by applicable law or agreed to in writing, software 11a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal * distributed under the License is distributed on an "AS IS" BASIS, 12a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 13a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal * See the License for the specific language governing permissions and 14a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal * limitations under the License. 15a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal */ 16a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal 176f28d91aab952e3244fbb4e707fa38f85538f374Anwar Ghuloum 186f28d91aab952e3244fbb4e707fa38f85538f374Anwar Ghuloum#include <stdio.h> 196f28d91aab952e3244fbb4e707fa38f85538f374Anwar Ghuloum 20a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal#include "timing_logger.h" 21a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal 22a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal#include "base/logging.h" 23a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal#include "base/stl_util.h" 24a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal#include "base/histogram-inl.h" 25dabdc0fe183d4684f3cf4d70cb09d318cff81b42Mathieu Chartier#include "base/systrace.h" 2680afd02024d20e60b197d3adfbb43cc303cf29e0Vladimir Marko#include "base/time_utils.h" 2780afd02024d20e60b197d3adfbb43cc303cf29e0Vladimir Marko#include "thread-inl.h" 28a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal 29a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal#include <cmath> 30a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal#include <iomanip> 31a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal 32a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asalnamespace art { 33a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal 3445c1165558eb8f9c81843b63ed362079a60c8387Mark Mendellconstexpr size_t CumulativeLogger::kLowMemoryBucketCount; 3545c1165558eb8f9c81843b63ed362079a60c8387Mark Mendellconstexpr size_t CumulativeLogger::kDefaultBucketCount; 36f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartierconstexpr size_t TimingLogger::kIndexNotFound; 37f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier 38453570570b00ea7990c8d45506d1311f5228c6f0Ian RogersCumulativeLogger::CumulativeLogger(const std::string& name) 39a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal : name_(name), 40453570570b00ea7990c8d45506d1311f5228c6f0Ian Rogers lock_name_("CumulativeLoggerLock" + name), 41453570570b00ea7990c8d45506d1311f5228c6f0Ian Rogers lock_(lock_name_.c_str(), kDefaultMutexLevel, true) { 42a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal Reset(); 43a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal} 44a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal 45453570570b00ea7990c8d45506d1311f5228c6f0Ian RogersCumulativeLogger::~CumulativeLogger() { 4619b0a913d9127a70ca35ebae166312bc6eee3196Mathieu Chartier STLDeleteElements(&histograms_); 47453570570b00ea7990c8d45506d1311f5228c6f0Ian Rogers} 48a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal 49453570570b00ea7990c8d45506d1311f5228c6f0Ian Rogersvoid CumulativeLogger::SetName(const std::string& name) { 50c528dba35b5faece51ca658fc008b688f8b690adMathieu Chartier MutexLock mu(Thread::Current(), lock_); 511d54e73444e017d3a65234e0f193846f3e27472bIan Rogers name_.assign(name); 52453570570b00ea7990c8d45506d1311f5228c6f0Ian Rogers} 53a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal 54a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asalvoid CumulativeLogger::Start() { 55a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal} 56a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal 57a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asalvoid CumulativeLogger::End() { 58a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal MutexLock mu(Thread::Current(), lock_); 594aeec176eaf11fe03f342aadcbb79142230270edMathieu Chartier ++iterations_; 60a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal} 614446ab9e70dde779d97f451c4904f6b8770232bdAnwar Ghuloum 62a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asalvoid CumulativeLogger::Reset() { 63a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal MutexLock mu(Thread::Current(), lock_); 64a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal iterations_ = 0; 65afe4998fc15b8de093d6b282c9782d7182829e36Mathieu Chartier total_time_ = 0; 6619b0a913d9127a70ca35ebae166312bc6eee3196Mathieu Chartier STLDeleteElements(&histograms_); 67a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal} 68a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal 695fe9af720048673e62ee29597a30bb9e54c903c5Ian Rogersvoid CumulativeLogger::AddLogger(const TimingLogger &logger) { 701d54e73444e017d3a65234e0f193846f3e27472bIan Rogers MutexLock mu(Thread::Current(), lock_); 71f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier TimingLogger::TimingData timing_data(logger.CalculateTimingData()); 72f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier const std::vector<TimingLogger::Timing>& timings = logger.GetTimings(); 73f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier for (size_t i = 0; i < timings.size(); ++i) { 74f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier if (timings[i].IsStartTiming()) { 75f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier AddPair(timings[i].GetName(), timing_data.GetExclusiveTime(i)); 76f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier } 771d54e73444e017d3a65234e0f193846f3e27472bIan Rogers } 784aeec176eaf11fe03f342aadcbb79142230270edMathieu Chartier ++iterations_; 791d54e73444e017d3a65234e0f193846f3e27472bIan Rogers} 801d54e73444e017d3a65234e0f193846f3e27472bIan Rogers 81590fee9e8972f872301c2d16a575d579ee564beeMathieu Chartiersize_t CumulativeLogger::GetIterations() const { 82590fee9e8972f872301c2d16a575d579ee564beeMathieu Chartier MutexLock mu(Thread::Current(), lock_); 83590fee9e8972f872301c2d16a575d579ee564beeMathieu Chartier return iterations_; 84590fee9e8972f872301c2d16a575d579ee564beeMathieu Chartier} 85590fee9e8972f872301c2d16a575d579ee564beeMathieu Chartier 86afe4998fc15b8de093d6b282c9782d7182829e36Mathieu Chartiervoid CumulativeLogger::Dump(std::ostream &os) const { 87a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal MutexLock mu(Thread::Current(), lock_); 88a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal DumpHistogram(os); 89a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal} 90a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal 9119b0a913d9127a70ca35ebae166312bc6eee3196Mathieu Chartiervoid CumulativeLogger::AddPair(const std::string& label, uint64_t delta_time) { 92a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal // Convert delta time to microseconds so that we don't overflow our counters. 93a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal delta_time /= kAdjust; 94afe4998fc15b8de093d6b282c9782d7182829e36Mathieu Chartier total_time_ += delta_time; 9519b0a913d9127a70ca35ebae166312bc6eee3196Mathieu Chartier Histogram<uint64_t>* histogram; 9619b0a913d9127a70ca35ebae166312bc6eee3196Mathieu Chartier Histogram<uint64_t> dummy(label.c_str()); 9719b0a913d9127a70ca35ebae166312bc6eee3196Mathieu Chartier auto it = histograms_.find(&dummy); 9819b0a913d9127a70ca35ebae166312bc6eee3196Mathieu Chartier if (it == histograms_.end()) { 9919b0a913d9127a70ca35ebae166312bc6eee3196Mathieu Chartier const size_t max_buckets = Runtime::Current()->GetHeap()->IsLowMemoryMode() ? 10019b0a913d9127a70ca35ebae166312bc6eee3196Mathieu Chartier kLowMemoryBucketCount : kDefaultBucketCount; 10119b0a913d9127a70ca35ebae166312bc6eee3196Mathieu Chartier histogram = new Histogram<uint64_t>(label.c_str(), kInitialBucketSize, max_buckets); 10219b0a913d9127a70ca35ebae166312bc6eee3196Mathieu Chartier histograms_.insert(histogram); 10319b0a913d9127a70ca35ebae166312bc6eee3196Mathieu Chartier } else { 10419b0a913d9127a70ca35ebae166312bc6eee3196Mathieu Chartier histogram = *it; 105a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal } 10619b0a913d9127a70ca35ebae166312bc6eee3196Mathieu Chartier histogram->AddValue(delta_time); 107a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal} 108a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal 10919b0a913d9127a70ca35ebae166312bc6eee3196Mathieu Chartierclass CompareHistorgramByTimeSpentDeclining { 11019b0a913d9127a70ca35ebae166312bc6eee3196Mathieu Chartier public: 11119b0a913d9127a70ca35ebae166312bc6eee3196Mathieu Chartier bool operator()(const Histogram<uint64_t>* a, const Histogram<uint64_t>* b) const { 11219b0a913d9127a70ca35ebae166312bc6eee3196Mathieu Chartier return a->Sum() > b->Sum(); 11319b0a913d9127a70ca35ebae166312bc6eee3196Mathieu Chartier } 11419b0a913d9127a70ca35ebae166312bc6eee3196Mathieu Chartier}; 11519b0a913d9127a70ca35ebae166312bc6eee3196Mathieu Chartier 116afe4998fc15b8de093d6b282c9782d7182829e36Mathieu Chartiervoid CumulativeLogger::DumpHistogram(std::ostream &os) const { 117a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal os << "Start Dumping histograms for " << iterations_ << " iterations" 118a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal << " for " << name_ << "\n"; 11919b0a913d9127a70ca35ebae166312bc6eee3196Mathieu Chartier std::set<Histogram<uint64_t>*, CompareHistorgramByTimeSpentDeclining> 12019b0a913d9127a70ca35ebae166312bc6eee3196Mathieu Chartier sorted_histograms(histograms_.begin(), histograms_.end()); 12119b0a913d9127a70ca35ebae166312bc6eee3196Mathieu Chartier for (Histogram<uint64_t>* histogram : sorted_histograms) { 122e5426c9995d28bcb19391d8dbf0ad70606cf1770Mathieu Chartier Histogram<uint64_t>::CumulativeData cumulative_data; 12319b0a913d9127a70ca35ebae166312bc6eee3196Mathieu Chartier // We don't expect DumpHistogram to be called often, so it is not performance critical. 12419b0a913d9127a70ca35ebae166312bc6eee3196Mathieu Chartier histogram->CreateHistogram(&cumulative_data); 12519b0a913d9127a70ca35ebae166312bc6eee3196Mathieu Chartier histogram->PrintConfidenceIntervals(os, 0.99, cumulative_data); 126a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal } 127a190645a005eb5da53ee82e9d3857ba66d99f845Christopher Ferris os << "Done Dumping histograms\n"; 128a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal} 129a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal 1306f28d91aab952e3244fbb4e707fa38f85538f374Anwar GhuloumTimingLogger::TimingLogger(const char* name, bool precise, bool verbose) 131f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier : name_(name), precise_(precise), verbose_(verbose) { 1321d54e73444e017d3a65234e0f193846f3e27472bIan Rogers} 1331d54e73444e017d3a65234e0f193846f3e27472bIan Rogers 1346f28d91aab952e3244fbb4e707fa38f85538f374Anwar Ghuloumvoid TimingLogger::Reset() { 135f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier timings_.clear(); 1361d54e73444e017d3a65234e0f193846f3e27472bIan Rogers} 1371d54e73444e017d3a65234e0f193846f3e27472bIan Rogers 138f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartiervoid TimingLogger::StartTiming(const char* label) { 139f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier DCHECK(label != nullptr); 140f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier timings_.push_back(Timing(NanoTime(), label)); 141f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier ATRACE_BEGIN(label); 1424446ab9e70dde779d97f451c4904f6b8770232bdAnwar Ghuloum} 1434446ab9e70dde779d97f451c4904f6b8770232bdAnwar Ghuloum 144f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartiervoid TimingLogger::EndTiming() { 145f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier timings_.push_back(Timing(NanoTime(), nullptr)); 146f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier ATRACE_END(); 1471d54e73444e017d3a65234e0f193846f3e27472bIan Rogers} 1481d54e73444e017d3a65234e0f193846f3e27472bIan Rogers 149f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartieruint64_t TimingLogger::GetTotalNs() const { 150f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier if (timings_.size() < 2) { 151f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier return 0; 1525fe9af720048673e62ee29597a30bb9e54c903c5Ian Rogers } 153f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier return timings_.back().GetTime() - timings_.front().GetTime(); 1541d54e73444e017d3a65234e0f193846f3e27472bIan Rogers} 1551d54e73444e017d3a65234e0f193846f3e27472bIan Rogers 156f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartiersize_t TimingLogger::FindTimingIndex(const char* name, size_t start_idx) const { 157f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier DCHECK_LT(start_idx, timings_.size()); 158f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier for (size_t i = start_idx; i < timings_.size(); ++i) { 159f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier if (timings_[i].IsStartTiming() && strcmp(timings_[i].GetName(), name) == 0) { 160f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier return i; 161f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier } 1621d54e73444e017d3a65234e0f193846f3e27472bIan Rogers } 163f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier return kIndexNotFound; 164f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier} 165f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier 166f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu ChartierTimingLogger::TimingData TimingLogger::CalculateTimingData() const { 167f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier TimingLogger::TimingData ret; 168f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier ret.data_.resize(timings_.size()); 169f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier std::vector<size_t> open_stack; 170f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier for (size_t i = 0; i < timings_.size(); ++i) { 171f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier if (timings_[i].IsEndTiming()) { 172f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier CHECK(!open_stack.empty()) << "No starting split for ending split at index " << i; 173f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier size_t open_idx = open_stack.back(); 174f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier uint64_t time = timings_[i].GetTime() - timings_[open_idx].GetTime(); 175f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier ret.data_[open_idx].exclusive_time += time; 176f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier DCHECK_EQ(ret.data_[open_idx].total_time, 0U); 177f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier ret.data_[open_idx].total_time += time; 178f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier // Each open split has exactly one end. 179f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier open_stack.pop_back(); 180f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier // If there is a parent node, subtract from the exclusive time. 181f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier if (!open_stack.empty()) { 182f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier // Note this may go negative, but will work due to 2s complement when we add the value 183f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier // total time value later. 184f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier ret.data_[open_stack.back()].exclusive_time -= time; 185f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier } 186f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier } else { 187f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier open_stack.push_back(i); 188f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier } 189f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier } 190f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier CHECK(open_stack.empty()) << "Missing ending for timing " 191f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier << timings_[open_stack.back()].GetName() << " at index " << open_stack.back(); 192f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier return ret; // No need to fear, C++11 move semantics are here. 1931d54e73444e017d3a65234e0f193846f3e27472bIan Rogers} 1941d54e73444e017d3a65234e0f193846f3e27472bIan Rogers 195f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartiervoid TimingLogger::Dump(std::ostream &os, const char* indent_string) const { 196f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier static constexpr size_t kFractionalDigits = 3; 197f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier TimingLogger::TimingData timing_data(CalculateTimingData()); 1981d54e73444e017d3a65234e0f193846f3e27472bIan Rogers uint64_t longest_split = 0; 199f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier for (size_t i = 0; i < timings_.size(); ++i) { 200f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier longest_split = std::max(longest_split, timing_data.GetTotalTime(i)); 2011d54e73444e017d3a65234e0f193846f3e27472bIan Rogers } 2021d54e73444e017d3a65234e0f193846f3e27472bIan Rogers // Compute which type of unit we will use for printing the timings. 2031d54e73444e017d3a65234e0f193846f3e27472bIan Rogers TimeUnit tu = GetAppropriateTimeUnit(longest_split); 2041d54e73444e017d3a65234e0f193846f3e27472bIan Rogers uint64_t divisor = GetNsToTimeUnitDivisor(tu); 205f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier uint64_t mod_fraction = divisor >= 1000 ? divisor / 1000 : 1; 2061d54e73444e017d3a65234e0f193846f3e27472bIan Rogers // Print formatted splits. 207f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier size_t tab_count = 1; 208f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier os << name_ << " [Exclusive time] [Total time]\n"; 209f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier for (size_t i = 0; i < timings_.size(); ++i) { 210f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier if (timings_[i].IsStartTiming()) { 211f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier uint64_t exclusive_time = timing_data.GetExclusiveTime(i); 212f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier uint64_t total_time = timing_data.GetTotalTime(i); 213f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier if (!precise_) { 214f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier // Make the fractional part 0. 215f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier exclusive_time -= exclusive_time % mod_fraction; 216f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier total_time -= total_time % mod_fraction; 217f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier } 218f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier for (size_t j = 0; j < tab_count; ++j) { 219f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier os << indent_string; 220f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier } 221f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier os << FormatDuration(exclusive_time, tu, kFractionalDigits); 222f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier // If they are the same, just print one value to prevent spam. 223f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier if (exclusive_time != total_time) { 224f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier os << "/" << FormatDuration(total_time, tu, kFractionalDigits); 225f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier } 226f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier os << " " << timings_[i].GetName() << "\n"; 227f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier ++tab_count; 228f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier } else { 229f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier --tab_count; 2301d54e73444e017d3a65234e0f193846f3e27472bIan Rogers } 2311d54e73444e017d3a65234e0f193846f3e27472bIan Rogers } 232f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier os << name_ << ": end, " << PrettyDuration(GetTotalNs()) << "\n"; 2331d54e73444e017d3a65234e0f193846f3e27472bIan Rogers} 2341d54e73444e017d3a65234e0f193846f3e27472bIan Rogers 235f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartiervoid TimingLogger::Verify() { 236f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier size_t counts[2] = { 0 }; 237f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier for (size_t i = 0; i < timings_.size(); ++i) { 238f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier if (i > 0) { 239f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier CHECK_LE(timings_[i - 1].GetTime(), timings_[i].GetTime()); 240f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier } 241f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier ++counts[timings_[i].IsStartTiming() ? 0 : 1]; 2424446ab9e70dde779d97f451c4904f6b8770232bdAnwar Ghuloum } 243f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier CHECK_EQ(counts[0], counts[1]) << "Number of StartTiming and EndTiming doesn't match"; 2444446ab9e70dde779d97f451c4904f6b8770232bdAnwar Ghuloum} 2454446ab9e70dde779d97f451c4904f6b8770232bdAnwar Ghuloum 246f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu ChartierTimingLogger::~TimingLogger() { 247f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier if (kIsDebugBuild) { 248f5997b4d3f889569d5a2b724d83d764bfbb8d106Mathieu Chartier Verify(); 2494446ab9e70dde779d97f451c4904f6b8770232bdAnwar Ghuloum } 2504446ab9e70dde779d97f451c4904f6b8770232bdAnwar Ghuloum} 2514446ab9e70dde779d97f451c4904f6b8770232bdAnwar Ghuloum 252a84395489098e4531619b1cffd1afc282b14510eSameer Abu Asal} // namespace art 253