src/third_party/libjingle/source/talk/base/profiler.cc

   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
  34 namespace {
  35
  36 // When written to an ostream, FormattedTime chooses an appropriate scale and
  37 // suffix for a time value given in seconds.
  38 class FormattedTime {
  39  public:
  40   explicit FormattedTime(double t) : time_(t) {}
  41   double time() const { return time_; }
  42  private:
  43   double time_;
  44 };
  45
  46 std::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
  57 namespace talk_base {
  58
  59 ProfilerEvent::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
  67 void ProfilerEvent::Start() {
  68   if (start_count_ == 0) {
  69     current_start_time_ = TimeNanos();
  70   }
  71   ++start_count_;
  72 }
  73
  74 void 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
  96 void ProfilerEvent::Stop() {
  97   Stop(TimeNanos());
  98 }
  99
 100 double 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
 105 Profiler* Profiler::Instance() {
 106   LIBJINGLE_DEFINE_STATIC_LOCAL(Profiler, instance, ());
 107   return &instance;
 108 }
 109
 110 void 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
 126 void 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
 136 void 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
 164 void Profiler::ReportAllToLog(const char* file, int line,
 165                            LoggingSeverity severity_to_use) {
 166   ReportToLog(file, line, severity_to_use, "");
 167 }
 168
 169 const 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
 176 bool 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
 192 std::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