Home | History | Annotate | Download | only in base 
      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:
     23   explicit FormattedTime(double t) : time_(t) {}
     24   double time() const { return time_; }
     25  private:
     26   double time_;
     27 };
     28 
     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 
     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 
     50 void ProfilerEvent::Start() {
     51   if (start_count_ == 0) {
     52     current_start_time_ = TimeNanos();
     53   }
     54   ++start_count_;
     55 }
     56 
     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 
     79 void ProfilerEvent::Stop() {
     80   Stop(TimeNanos());
     81 }
     82 
     83 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 
     88 Profiler* Profiler::Instance() {
     89   LIBJINGLE_DEFINE_STATIC_LOCAL(Profiler, instance, ());
     90   return &instance;
     91 }
     92 
     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 
    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 
    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 
    147 void Profiler::ReportAllToLog(const char* file, int line,
    148                            LoggingSeverity severity_to_use) {
    149   ReportToLog(file, line, severity_to_use, "");
    150 }
    151 
    152 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 
    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 
    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