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