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 #include <algorithm>
     15 
     16 #include "webrtc/base/timeutils.h"
     17 
     18 namespace {
     19 
     20 // When written to an ostream, FormattedTime chooses an appropriate scale and
     21 // suffix for a time value given in seconds.
     22 class FormattedTime {
     23  public:
     24   explicit FormattedTime(double t) : time_(t) {}
     25   double time() const { return time_; }
     26  private:
     27   double time_;
     28 };
     29 
     30 std::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 
     41 namespace rtc {
     42 
     43 ProfilerEvent::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 
     51 void ProfilerEvent::Start() {
     52   if (start_count_ == 0) {
     53     current_start_time_ = TimeNanos();
     54   }
     55   ++start_count_;
     56 }
     57 
     58 void 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 
     80 void ProfilerEvent::Stop() {
     81   Stop(TimeNanos());
     82 }
     83 
     84 double 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 
     89 Profiler::~Profiler() = default;
     90 
     91 Profiler* Profiler::Instance() {
     92   RTC_DEFINE_STATIC_LOCAL(Profiler, instance, ());
     93   return &instance;
     94 }
     95 
     96 Profiler::Profiler() {
     97 }
     98 
     99 void 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 
    115 void 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 
    125 void 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 
    153 void Profiler::ReportAllToLog(const char* file, int line,
    154                            LoggingSeverity severity_to_use) {
    155   ReportToLog(file, line, severity_to_use, "");
    156 }
    157 
    158 const 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 
    165 bool 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 
    181 std::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