blob: dfb0220d465e3b9f4d754ccce4a485af3e0a321a [file] [log] [blame]
Sameer Abu Asala8439542013-02-14 16:06:42 -08001/*
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
Anwar Ghuloum6f28d912013-07-24 15:02:53 -070017
18#define ATRACE_TAG ATRACE_TAG_DALVIK
19#include <stdio.h>
20#include <cutils/trace.h>
21
Sameer Abu Asala8439542013-02-14 16:06:42 -080022#include "timing_logger.h"
23
24#include "base/logging.h"
25#include "thread.h"
26#include "base/stl_util.h"
27#include "base/histogram-inl.h"
28
29#include <cmath>
30#include <iomanip>
31
32namespace art {
33
Ian Rogers45357052013-04-18 20:49:43 -070034CumulativeLogger::CumulativeLogger(const std::string& name)
Sameer Abu Asala8439542013-02-14 16:06:42 -080035 : name_(name),
Ian Rogers45357052013-04-18 20:49:43 -070036 lock_name_("CumulativeLoggerLock" + name),
37 lock_(lock_name_.c_str(), kDefaultMutexLevel, true) {
Sameer Abu Asala8439542013-02-14 16:06:42 -080038 Reset();
39}
40
Ian Rogers45357052013-04-18 20:49:43 -070041CumulativeLogger::~CumulativeLogger() {
42 STLDeleteElements(&histograms_);
43}
Sameer Abu Asala8439542013-02-14 16:06:42 -080044
Ian Rogers45357052013-04-18 20:49:43 -070045void CumulativeLogger::SetName(const std::string& name) {
Ian Rogers1d54e732013-05-02 21:10:01 -070046 name_.assign(name);
Ian Rogers45357052013-04-18 20:49:43 -070047}
Sameer Abu Asala8439542013-02-14 16:06:42 -080048
49void CumulativeLogger::Start() {
50 MutexLock mu(Thread::Current(), lock_);
51 index_ = 0;
52}
53
54void CumulativeLogger::End() {
55 MutexLock mu(Thread::Current(), lock_);
56 iterations_++;
57}
58void CumulativeLogger::Reset() {
59 MutexLock mu(Thread::Current(), lock_);
60 iterations_ = 0;
61 STLDeleteElements(&histograms_);
62}
63
64uint64_t CumulativeLogger::GetTotalNs() const {
65 return GetTotalTime() * kAdjust;
66}
67
68uint64_t CumulativeLogger::GetTotalTime() const {
69 MutexLock mu(Thread::Current(), lock_);
70 uint64_t total = 0;
71 for (size_t i = 0; i < histograms_.size(); ++i) {
72 total += histograms_[i]->Sum();
73 }
74 return total;
75}
76
Sameer Abu Asala8439542013-02-14 16:06:42 -080077
Anwar Ghuloum6f28d912013-07-24 15:02:53 -070078void CumulativeLogger::AddLogger(const base::TimingLogger &logger) {
Ian Rogers1d54e732013-05-02 21:10:01 -070079 MutexLock mu(Thread::Current(), lock_);
80 const std::vector<std::pair<uint64_t, const char*> >& splits = logger.GetSplits();
81 typedef std::vector<std::pair<uint64_t, const char*> >::const_iterator It;
82 if (kIsDebugBuild && splits.size() != histograms_.size()) {
83 LOG(ERROR) << "Mismatch in splits.";
84 typedef std::vector<Histogram<uint64_t> *>::const_iterator It2;
85 It it = splits.begin();
86 It2 it2 = histograms_.begin();
87 while ((it != splits.end()) && (it2 != histograms_.end())) {
88 if (it != splits.end()) {
89 LOG(ERROR) << "\tsplit: " << it->second;
90 ++it;
91 }
92 if (it2 != histograms_.end()) {
93 LOG(ERROR) << "\tpreviously record: " << (*it2)->Name();
94 ++it2;
95 }
96 }
97 }
98 for (It it = splits.begin(), end = splits.end(); it != end; ++it) {
99 std::pair<uint64_t, const char*> split = *it;
100 uint64_t split_time = split.first;
101 const char* split_name = split.second;
102 AddPair(split_name, split_time);
103 }
104}
105
Sameer Abu Asala8439542013-02-14 16:06:42 -0800106void CumulativeLogger::Dump(std::ostream &os) {
107 MutexLock mu(Thread::Current(), lock_);
108 DumpHistogram(os);
109}
110
111void CumulativeLogger::AddPair(const std::string &label, uint64_t delta_time) {
Sameer Abu Asala8439542013-02-14 16:06:42 -0800112 // Convert delta time to microseconds so that we don't overflow our counters.
113 delta_time /= kAdjust;
114 if (index_ >= histograms_.size()) {
115 Histogram<uint64_t> *tmp_hist = new Histogram<uint64_t>(label);
116 tmp_hist->AddValue(delta_time);
117 histograms_.push_back(tmp_hist);
118 } else {
119 histograms_[index_]->AddValue(delta_time);
120 DCHECK_EQ(label, histograms_[index_]->Name());
121 }
122 index_++;
123}
124
125void CumulativeLogger::DumpHistogram(std::ostream &os) {
126 os << "Start Dumping histograms for " << iterations_ << " iterations"
127 << " for " << name_ << "\n";
128 for (size_t Idx = 0; Idx < histograms_.size(); Idx++) {
129 Histogram<uint64_t> &hist = *(histograms_[Idx]);
130 hist.CreateHistogram();
131 hist.PrintConfidenceIntervals(os, 0.99);
132 }
133 os << "Done Dumping histograms \n";
134}
135
Ian Rogers1d54e732013-05-02 21:10:01 -0700136
137namespace base {
138
Anwar Ghuloum6f28d912013-07-24 15:02:53 -0700139TimingLogger::TimingLogger(const char* name, bool precise, bool verbose)
Ian Rogers1d54e732013-05-02 21:10:01 -0700140 : name_(name), precise_(precise), verbose_(verbose),
141 current_split_(NULL), current_split_start_ns_(0) {
142}
143
Anwar Ghuloum6f28d912013-07-24 15:02:53 -0700144void TimingLogger::Reset() {
Ian Rogers1d54e732013-05-02 21:10:01 -0700145 current_split_ = NULL;
146 current_split_start_ns_ = 0;
147 splits_.clear();
148}
149
Anwar Ghuloum6f28d912013-07-24 15:02:53 -0700150void TimingLogger::StartSplit(const char* new_split_label) {
Ian Rogers1d54e732013-05-02 21:10:01 -0700151 DCHECK(current_split_ == NULL);
152 if (verbose_) {
153 LOG(INFO) << "Begin: " << new_split_label;
154 }
155 current_split_ = new_split_label;
Anwar Ghuloum6f28d912013-07-24 15:02:53 -0700156 ATRACE_BEGIN(current_split_);
Ian Rogers1d54e732013-05-02 21:10:01 -0700157 current_split_start_ns_ = NanoTime();
158}
159
160// Ends the current split and starts the one given by the label.
Anwar Ghuloum6f28d912013-07-24 15:02:53 -0700161void TimingLogger::NewSplit(const char* new_split_label) {
Ian Rogers1d54e732013-05-02 21:10:01 -0700162 DCHECK(current_split_ != NULL);
163 uint64_t current_time = NanoTime();
164 uint64_t split_time = current_time - current_split_start_ns_;
Anwar Ghuloum6f28d912013-07-24 15:02:53 -0700165 ATRACE_END();
Ian Rogers1d54e732013-05-02 21:10:01 -0700166 splits_.push_back(std::pair<uint64_t, const char*>(split_time, current_split_));
167 if (verbose_) {
168 LOG(INFO) << "End: " << current_split_ << " " << PrettyDuration(split_time) << "\n"
169 << "Begin: " << new_split_label;
170 }
171 current_split_ = new_split_label;
Anwar Ghuloum6f28d912013-07-24 15:02:53 -0700172 ATRACE_BEGIN(current_split_);
Ian Rogers1d54e732013-05-02 21:10:01 -0700173 current_split_start_ns_ = current_time;
174}
175
Anwar Ghuloum6f28d912013-07-24 15:02:53 -0700176void TimingLogger::EndSplit() {
Ian Rogers1d54e732013-05-02 21:10:01 -0700177 DCHECK(current_split_ != NULL);
178 uint64_t current_time = NanoTime();
179 uint64_t split_time = current_time - current_split_start_ns_;
Anwar Ghuloum6f28d912013-07-24 15:02:53 -0700180 ATRACE_END();
Ian Rogers1d54e732013-05-02 21:10:01 -0700181 if (verbose_) {
182 LOG(INFO) << "End: " << current_split_ << " " << PrettyDuration(split_time);
183 }
184 splits_.push_back(std::pair<uint64_t, const char*>(split_time, current_split_));
185}
186
Anwar Ghuloum6f28d912013-07-24 15:02:53 -0700187uint64_t TimingLogger::GetTotalNs() const {
Ian Rogers1d54e732013-05-02 21:10:01 -0700188 uint64_t total_ns = 0;
189 typedef std::vector<std::pair<uint64_t, const char*> >::const_iterator It;
190 for (It it = splits_.begin(), end = splits_.end(); it != end; ++it) {
191 std::pair<uint64_t, const char*> split = *it;
192 total_ns += split.first;
193 }
194 return total_ns;
195}
196
Anwar Ghuloum6f28d912013-07-24 15:02:53 -0700197void TimingLogger::Dump(std::ostream &os) const {
Ian Rogers1d54e732013-05-02 21:10:01 -0700198 uint64_t longest_split = 0;
199 uint64_t total_ns = 0;
200 typedef std::vector<std::pair<uint64_t, const char*> >::const_iterator It;
201 for (It it = splits_.begin(), end = splits_.end(); it != end; ++it) {
202 std::pair<uint64_t, const char*> split = *it;
203 uint64_t split_time = split.first;
204 longest_split = std::max(longest_split, split_time);
205 total_ns += split_time;
206 }
207 // Compute which type of unit we will use for printing the timings.
208 TimeUnit tu = GetAppropriateTimeUnit(longest_split);
209 uint64_t divisor = GetNsToTimeUnitDivisor(tu);
210 // Print formatted splits.
211 for (It it = splits_.begin(), end = splits_.end(); it != end; ++it) {
212 std::pair<uint64_t, const char*> split = *it;
213 uint64_t split_time = split.first;
214 if (!precise_ && divisor >= 1000) {
215 // Make the fractional part 0.
216 split_time -= split_time % (divisor / 1000);
217 }
218 os << name_ << ": " << std::setw(8) << FormatDuration(split_time, tu) << " "
219 << split.second << "\n";
220 }
221 os << name_ << ": end, " << NsToMs(total_ns) << " ms\n";
222}
223
224} // namespace base
Sameer Abu Asala8439542013-02-14 16:06:42 -0800225} // namespace art