1/*
2 * libjingle
3 * Copyright 2013, Google Inc.
4 *
5 * Redistribution and use in source and binary forms, with or without
6 * modification, are permitted provided that the following conditions are met:
7 *
8 *  1. Redistributions of source code must retain the above copyright notice,
9 *     this list of conditions and the following disclaimer.
10 *  2. Redistributions in binary form must reproduce the above copyright notice,
11 *     this list of conditions and the following disclaimer in the documentation
12 *     and/or other materials provided with the distribution.
13 *  3. The name of the author may not be used to endorse or promote products
14 *     derived from this software without specific prior written permission.
15 *
16 * THIS SOFTWARE IS PROVIDED BY THE AUTHOR ``AS IS'' AND ANY EXPRESS OR IMPLIED
17 * WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE IMPLIED WARRANTIES OF
18 * MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO
19 * EVENT SHALL THE AUTHOR BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL,
20 * SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT LIMITED TO,
21 * PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, DATA, OR PROFITS;
22 * OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY,
23 * WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR
24 * OTHERWISE) ARISING IN ANY WAY OUT OF THE USE OF THIS SOFTWARE, EVEN IF
25 * ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
26 */
27
28#include "talk/base/profiler.h"
29
30#include <math.h>
31
32#include "talk/base/timeutils.h"
33
34namespace {
35
36// When written to an ostream, FormattedTime chooses an appropriate scale and
37// suffix for a time value given in seconds.
38class FormattedTime {
39 public:
40  explicit FormattedTime(double t) : time_(t) {}
41  double time() const { return time_; }
42 private:
43  double time_;
44};
45
46std::ostream& operator<<(std::ostream& stream, const FormattedTime& time) {
47  if (time.time() < 1.0) {
48    stream << (time.time() * 1000.0) << "ms";
49  } else {
50    stream << time.time() << 's';
51  }
52  return stream;
53}
54
55}  // namespace
56
57namespace talk_base {
58
59ProfilerEvent::ProfilerEvent()
60    : total_time_(0.0),
61      mean_(0.0),
62      sum_of_squared_differences_(0.0),
63      start_count_(0),
64      event_count_(0) {
65}
66
67void ProfilerEvent::Start() {
68  if (start_count_ == 0) {
69    current_start_time_ = TimeNanos();
70  }
71  ++start_count_;
72}
73
74void ProfilerEvent::Stop(uint64 stop_time) {
75  --start_count_;
76  ASSERT(start_count_ >= 0);
77  if (start_count_ == 0) {
78    double elapsed = static_cast<double>(stop_time - current_start_time_) /
79        kNumNanosecsPerSec;
80    total_time_ += elapsed;
81    if (event_count_ == 0) {
82      minimum_ = maximum_ = elapsed;
83    } else {
84      minimum_ = _min(minimum_, elapsed);
85      maximum_ = _max(maximum_, elapsed);
86    }
87    // Online variance and mean algorithm: http://en.wikipedia.org/wiki/
88    // Algorithms_for_calculating_variance#Online_algorithm
89    ++event_count_;
90    double delta = elapsed - mean_;
91    mean_ = mean_ + delta / event_count_;
92    sum_of_squared_differences_ += delta * (elapsed - mean_);
93  }
94}
95
96void ProfilerEvent::Stop() {
97  Stop(TimeNanos());
98}
99
100double ProfilerEvent::standard_deviation() const {
101    if (event_count_ <= 1) return 0.0;
102    return sqrt(sum_of_squared_differences_ / (event_count_ - 1.0));
103}
104
105Profiler* Profiler::Instance() {
106  LIBJINGLE_DEFINE_STATIC_LOCAL(Profiler, instance, ());
107  return &instance;
108}
109
110void Profiler::StartEvent(const std::string& event_name) {
111  lock_.LockShared();
112  EventMap::iterator it = events_.find(event_name);
113  bool needs_insert = (it == events_.end());
114  lock_.UnlockShared();
115
116  if (needs_insert) {
117    // Need an exclusive lock to modify the map.
118    ExclusiveScope scope(&lock_);
119    it = events_.insert(
120        EventMap::value_type(event_name, ProfilerEvent())).first;
121  }
122
123  it->second.Start();
124}
125
126void Profiler::StopEvent(const std::string& event_name) {
127  // Get the time ASAP, then wait for the lock.
128  uint64 stop_time = TimeNanos();
129  SharedScope scope(&lock_);
130  EventMap::iterator it = events_.find(event_name);
131  if (it != events_.end()) {
132    it->second.Stop(stop_time);
133  }
134}
135
136void Profiler::ReportToLog(const char* file, int line,
137                           LoggingSeverity severity_to_use,
138                           const std::string& event_prefix) {
139  if (!LogMessage::Loggable(severity_to_use)) {
140    return;
141  }
142
143  SharedScope scope(&lock_);
144
145  { // Output first line.
146    LogMessage msg(file, line, severity_to_use);
147    msg.stream() << "=== Profile report ";
148    if (event_prefix.empty()) {
149      msg.stream() << "(prefix: '" << event_prefix << "') ";
150    }
151    msg.stream() << "===";
152  }
153  for (EventMap::const_iterator it = events_.begin();
154       it != events_.end(); ++it) {
155    if (event_prefix.empty() || it->first.find(event_prefix) == 0) {
156      LogMessage(file, line, severity_to_use).stream()
157          << it->first << " " << it->second;
158    }
159  }
160  LogMessage(file, line, severity_to_use).stream()
161      << "=== End profile report ===";
162}
163
164void Profiler::ReportAllToLog(const char* file, int line,
165                           LoggingSeverity severity_to_use) {
166  ReportToLog(file, line, severity_to_use, "");
167}
168
169const ProfilerEvent* Profiler::GetEvent(const std::string& event_name) const {
170  SharedScope scope(&lock_);
171  EventMap::const_iterator it =
172      events_.find(event_name);
173  return (it == events_.end()) ? NULL : &it->second;
174}
175
176bool Profiler::Clear() {
177  ExclusiveScope scope(&lock_);
178  bool result = true;
179  // Clear all events that aren't started.
180  EventMap::iterator it = events_.begin();
181  while (it != events_.end()) {
182    if (it->second.is_started()) {
183      ++it;  // Can't clear started events.
184      result = false;
185    } else {
186      events_.erase(it++);
187    }
188  }
189  return result;
190}
191
192std::ostream& operator<<(std::ostream& stream,
193                         const ProfilerEvent& profiler_event) {
194  stream << "count=" << profiler_event.event_count()
195         << " total=" << FormattedTime(profiler_event.total_time())
196         << " mean=" << FormattedTime(profiler_event.mean())
197         << " min=" << FormattedTime(profiler_event.minimum())
198         << " max=" << FormattedTime(profiler_event.maximum())
199         << " sd=" << profiler_event.standard_deviation();
200  return stream;
201}
202
203}  // namespace talk_base
204