1 /*
2 * Copyright 2013 The WebRTC Project Authors. All rights reserved.
3 *
4 * Use of this source code is governed by a BSD-style license
5 * that can be found in the LICENSE file in the root of the source
6 * tree. An additional intellectual property rights grant can be found
7 * in the file PATENTS. All contributing project authors may
8 * be found in the AUTHORS file in the root of the source tree.
9 */
10
11 #include "webrtc/base/profiler.h"
12
13 #include <math.h>
14
15 #include "webrtc/base/timeutils.h"
16
17 namespace {
18
19 // When written to an ostream, FormattedTime chooses an appropriate scale and
20 // suffix for a time value given in seconds.
21 class FormattedTime {
22 public:
FormattedTime(double t)23 explicit FormattedTime(double t) : time_(t) {}
time() const24 double time() const { return time_; }
25 private:
26 double time_;
27 };
28
operator <<(std::ostream & stream,const FormattedTime & time)29 std::ostream& operator<<(std::ostream& stream, const FormattedTime& time) {
30 if (time.time() < 1.0) {
31 stream << (time.time() * 1000.0) << "ms";
32 } else {
33 stream << time.time() << 's';
34 }
35 return stream;
36 }
37
38 } // namespace
39
40 namespace rtc {
41
ProfilerEvent()42 ProfilerEvent::ProfilerEvent()
43 : total_time_(0.0),
44 mean_(0.0),
45 sum_of_squared_differences_(0.0),
46 start_count_(0),
47 event_count_(0) {
48 }
49
Start()50 void ProfilerEvent::Start() {
51 if (start_count_ == 0) {
52 current_start_time_ = TimeNanos();
53 }
54 ++start_count_;
55 }
56
Stop(uint64 stop_time)57 void ProfilerEvent::Stop(uint64 stop_time) {
58 --start_count_;
59 ASSERT(start_count_ >= 0);
60 if (start_count_ == 0) {
61 double elapsed = static_cast<double>(stop_time - current_start_time_) /
62 kNumNanosecsPerSec;
63 total_time_ += elapsed;
64 if (event_count_ == 0) {
65 minimum_ = maximum_ = elapsed;
66 } else {
67 minimum_ = _min(minimum_, elapsed);
68 maximum_ = _max(maximum_, elapsed);
69 }
70 // Online variance and mean algorithm: http://en.wikipedia.org/wiki/
71 // Algorithms_for_calculating_variance#Online_algorithm
72 ++event_count_;
73 double delta = elapsed - mean_;
74 mean_ = mean_ + delta / event_count_;
75 sum_of_squared_differences_ += delta * (elapsed - mean_);
76 }
77 }
78
Stop()79 void ProfilerEvent::Stop() {
80 Stop(TimeNanos());
81 }
82
standard_deviation() const83 double ProfilerEvent::standard_deviation() const {
84 if (event_count_ <= 1) return 0.0;
85 return sqrt(sum_of_squared_differences_ / (event_count_ - 1.0));
86 }
87
Instance()88 Profiler* Profiler::Instance() {
89 LIBJINGLE_DEFINE_STATIC_LOCAL(Profiler, instance, ());
90 return &instance;
91 }
92
StartEvent(const std::string & event_name)93 void Profiler::StartEvent(const std::string& event_name) {
94 lock_.LockShared();
95 EventMap::iterator it = events_.find(event_name);
96 bool needs_insert = (it == events_.end());
97 lock_.UnlockShared();
98
99 if (needs_insert) {
100 // Need an exclusive lock to modify the map.
101 ExclusiveScope scope(&lock_);
102 it = events_.insert(
103 EventMap::value_type(event_name, ProfilerEvent())).first;
104 }
105
106 it->second.Start();
107 }
108
StopEvent(const std::string & event_name)109 void Profiler::StopEvent(const std::string& event_name) {
110 // Get the time ASAP, then wait for the lock.
111 uint64 stop_time = TimeNanos();
112 SharedScope scope(&lock_);
113 EventMap::iterator it = events_.find(event_name);
114 if (it != events_.end()) {
115 it->second.Stop(stop_time);
116 }
117 }
118
ReportToLog(const char * file,int line,LoggingSeverity severity_to_use,const std::string & event_prefix)119 void Profiler::ReportToLog(const char* file, int line,
120 LoggingSeverity severity_to_use,
121 const std::string& event_prefix) {
122 if (!LogMessage::Loggable(severity_to_use)) {
123 return;
124 }
125
126 SharedScope scope(&lock_);
127
128 { // Output first line.
129 LogMessage msg(file, line, severity_to_use);
130 msg.stream() << "=== Profile report ";
131 if (event_prefix.empty()) {
132 msg.stream() << "(prefix: '" << event_prefix << "') ";
133 }
134 msg.stream() << "===";
135 }
136 for (EventMap::const_iterator it = events_.begin();
137 it != events_.end(); ++it) {
138 if (event_prefix.empty() || it->first.find(event_prefix) == 0) {
139 LogMessage(file, line, severity_to_use).stream()
140 << it->first << " " << it->second;
141 }
142 }
143 LogMessage(file, line, severity_to_use).stream()
144 << "=== End profile report ===";
145 }
146
ReportAllToLog(const char * file,int line,LoggingSeverity severity_to_use)147 void Profiler::ReportAllToLog(const char* file, int line,
148 LoggingSeverity severity_to_use) {
149 ReportToLog(file, line, severity_to_use, "");
150 }
151
GetEvent(const std::string & event_name) const152 const ProfilerEvent* Profiler::GetEvent(const std::string& event_name) const {
153 SharedScope scope(&lock_);
154 EventMap::const_iterator it =
155 events_.find(event_name);
156 return (it == events_.end()) ? NULL : &it->second;
157 }
158
Clear()159 bool Profiler::Clear() {
160 ExclusiveScope scope(&lock_);
161 bool result = true;
162 // Clear all events that aren't started.
163 EventMap::iterator it = events_.begin();
164 while (it != events_.end()) {
165 if (it->second.is_started()) {
166 ++it; // Can't clear started events.
167 result = false;
168 } else {
169 events_.erase(it++);
170 }
171 }
172 return result;
173 }
174
operator <<(std::ostream & stream,const ProfilerEvent & profiler_event)175 std::ostream& operator<<(std::ostream& stream,
176 const ProfilerEvent& profiler_event) {
177 stream << "count=" << profiler_event.event_count()
178 << " total=" << FormattedTime(profiler_event.total_time())
179 << " mean=" << FormattedTime(profiler_event.mean())
180 << " min=" << FormattedTime(profiler_event.minimum())
181 << " max=" << FormattedTime(profiler_event.maximum())
182 << " sd=" << profiler_event.standard_deviation();
183 return stream;
184 }
185
186 } // namespace rtc
187