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