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
17namespace {
18
19// When written to an ostream, FormattedTime chooses an appropriate scale and
20// suffix for a time value given in seconds.
21class FormattedTime {
22 public:
23  explicit FormattedTime(double t) : time_(t) {}
24  double time() const { return time_; }
25 private:
26  double time_;
27};
28
29std::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
40namespace rtc {
41
42ProfilerEvent::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
50void ProfilerEvent::Start() {
51  if (start_count_ == 0) {
52    current_start_time_ = TimeNanos();
53  }
54  ++start_count_;
55}
56
57void 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
79void ProfilerEvent::Stop() {
80  Stop(TimeNanos());
81}
82
83double 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
88Profiler* Profiler::Instance() {
89  LIBJINGLE_DEFINE_STATIC_LOCAL(Profiler, instance, ());
90  return &instance;
91}
92
93void 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
109void 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
119void 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
147void Profiler::ReportAllToLog(const char* file, int line,
148                           LoggingSeverity severity_to_use) {
149  ReportToLog(file, line, severity_to_use, "");
150}
151
152const 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
159bool 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
175std::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