Home | History | Annotate | Download | only in base 
      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
    204