extensions/browser/api/web_request/web_request_time_tracker.cc

   1 // Copyright (c) 2012 The Chromium Authors. All rights reserved.
   2 // Use of this source code is governed by a BSD-style license that can be
   3 // found in the LICENSE file.
   4
   5 #include "extensions/browser/api/web_request/web_request_time_tracker.h"
   6
   7 #include "base/bind.h"
   8 #include "base/compiler_specific.h"
   9 #include "base/metrics/histogram.h"
  10 #include "extensions/browser/warning_set.h"
  11
  12
  13 // TODO(mpcomplete): tweak all these constants.
  14 namespace {
  15 // The number of requests we keep track of at a time.
  16 const size_t kMaxRequestsLogged = 100u;
  17
  18 // If a request completes faster than this amount (in ms), then we ignore it.
  19 // Any delays on such a request was negligible.
  20 const int kMinRequestTimeToCareMs = 10;
  21
  22 // Thresholds above which we consider a delay caused by an extension to be "too
  23 // much". This is given in percentage of total request time that was spent
  24 // waiting on the extension.
  25 const double kThresholdModerateDelay = 0.20;
  26 const double kThresholdExcessiveDelay = 0.50;
  27
  28 // If this many requests (of the past kMaxRequestsLogged) have had "too much"
  29 // delay, then we will warn the user.
  30 const size_t kNumModerateDelaysBeforeWarning = 50u;
  31 const size_t kNumExcessiveDelaysBeforeWarning = 10u;
  32
  33 // Default implementation for ExtensionWebRequestTimeTrackerDelegate
  34 // that sets a warning in the extension service of |profile|.
  35 class DefaultDelegate : public ExtensionWebRequestTimeTrackerDelegate {
  36  public:
  37   ~DefaultDelegate() override {}
  38
  39   // Implementation of ExtensionWebRequestTimeTrackerDelegate.
  40   void NotifyExcessiveDelays(
  41       void* profile,
  42       size_t num_delayed_messages,
  43       size_t total_num_messages,
  44       const std::set<std::string>& extension_ids) override;
  45   void NotifyModerateDelays(
  46       void* profile,
  47       size_t num_delayed_messages,
  48       size_t total_num_messages,
  49       const std::set<std::string>& extension_ids) override;
  50 };
  51
  52 void DefaultDelegate::NotifyExcessiveDelays(
  53     void* profile,
  54     size_t num_delayed_messages,
  55     size_t total_num_messages,
  56     const std::set<std::string>& extension_ids) {
  57   // TODO(battre) Enable warning the user if extensions misbehave as soon as we
  58   // have data that allows us to decide on reasonable limits for triggering the
  59   // warnings.
  60   // BrowserThread::PostTask(
  61   //     BrowserThread::UI,
  62   //     FROM_HERE,
  63   //     base::Bind(&ExtensionWarningSet::NotifyWarningsOnUI,
  64   //                profile,
  65   //                extension_ids,
  66   //                ExtensionWarningSet::kNetworkDelay));
  67 }
  68
  69 void DefaultDelegate::NotifyModerateDelays(
  70     void* profile,
  71     size_t num_delayed_messages,
  72     size_t total_num_messages,
  73     const std::set<std::string>& extension_ids) {
  74   // TODO(battre) Enable warning the user if extensions misbehave as soon as we
  75   // have data that allows us to decide on reasonable limits for triggering the
  76   // warnings.
  77   // BrowserThread::PostTask(
  78   //     BrowserThread::UI,
  79   //     FROM_HERE,
  80   //     base::Bind(&ExtensionWarningSet::NotifyWarningsOnUI,
  81   //                profile,
  82   //                extension_ids,
  83   //                ExtensionWarningSet::kNetworkDelay));
  84 }
  85
  86 }  // namespace
  87
  88 ExtensionWebRequestTimeTracker::RequestTimeLog::RequestTimeLog()
  89     : profile(NULL), completed(false) {
  90 }
  91
  92 ExtensionWebRequestTimeTracker::RequestTimeLog::~RequestTimeLog() {
  93 }
  94
  95 ExtensionWebRequestTimeTracker::ExtensionWebRequestTimeTracker()
  96     : delegate_(new DefaultDelegate) {
  97 }
  98
  99 ExtensionWebRequestTimeTracker::~ExtensionWebRequestTimeTracker() {
 100 }
 101
 102 void ExtensionWebRequestTimeTracker::LogRequestStartTime(
 103     int64 request_id,
 104     const base::Time& start_time,
 105     const GURL& url,
 106     void* profile) {
 107   // Trim old completed request logs.
 108   while (request_ids_.size() > kMaxRequestsLogged) {
 109     int64 to_remove = request_ids_.front();
 110     request_ids_.pop();
 111     std::map<int64, RequestTimeLog>::iterator iter =
 112         request_time_logs_.find(to_remove);
 113     if (iter != request_time_logs_.end() && iter->second.completed) {
 114       request_time_logs_.erase(iter);
 115       moderate_delays_.erase(to_remove);
 116       excessive_delays_.erase(to_remove);
 117     }
 118   }
 119   request_ids_.push(request_id);
 120
 121   if (request_time_logs_.find(request_id) != request_time_logs_.end()) {
 122     RequestTimeLog& log = request_time_logs_[request_id];
 123     DCHECK(!log.completed);
 124     return;
 125   }
 126   RequestTimeLog& log = request_time_logs_[request_id];
 127   log.request_start_time = start_time;
 128   log.url = url;
 129   log.profile = profile;
 130 }
 131
 132 void ExtensionWebRequestTimeTracker::LogRequestEndTime(
 133     int64 request_id, const base::Time& end_time) {
 134   if (request_time_logs_.find(request_id) == request_time_logs_.end())
 135     return;
 136
 137   RequestTimeLog& log = request_time_logs_[request_id];
 138   if (log.completed)
 139     return;
 140
 141   log.request_duration = end_time - log.request_start_time;
 142   log.completed = true;
 143
 144   if (log.extension_block_durations.empty())
 145     return;
 146
 147   UMA_HISTOGRAM_TIMES("Extensions.NetworkDelay", log.block_duration);
 148
 149   Analyze(request_id);
 150 }
 151
 152 std::set<std::string> ExtensionWebRequestTimeTracker::GetExtensionIds(
 153     const RequestTimeLog& log) const {
 154   std::set<std::string> result;
 155   for (std::map<std::string, base::TimeDelta>::const_iterator i =
 156            log.extension_block_durations.begin();
 157        i != log.extension_block_durations.end();
 158        ++i) {
 159     result.insert(i->first);
 160   }
 161   return result;
 162 }
 163
 164 void ExtensionWebRequestTimeTracker::Analyze(int64 request_id) {
 165   RequestTimeLog& log = request_time_logs_[request_id];
 166
 167   // Ignore really short requests. Time spent on these is negligible, and any
 168   // extra delay the extension adds is likely to be noise.
 169   if (log.request_duration.InMilliseconds() < kMinRequestTimeToCareMs)
 170     return;
 171
 172   double percentage =
 173       log.block_duration.InMillisecondsF() /
 174       log.request_duration.InMillisecondsF();
 175   UMA_HISTOGRAM_PERCENTAGE("Extensions.NetworkDelayPercentage",
 176                            static_cast<int>(100*percentage));
 177   VLOG(1) << "WR percent " << request_id << ": " << log.url << ": " <<
 178       log.block_duration.InMilliseconds() << "/" <<
 179       log.request_duration.InMilliseconds() << " = " << percentage;
 180
 181   // TODO(mpcomplete): blame a specific extension. Maybe go through the list
 182   // of recent requests and find the extension that has caused the most delays.
 183   if (percentage > kThresholdExcessiveDelay) {
 184     excessive_delays_.insert(request_id);
 185     if (excessive_delays_.size() > kNumExcessiveDelaysBeforeWarning) {
 186       VLOG(1) << "WR excessive delays:" << excessive_delays_.size();
 187       if (delegate_.get()) {
 188         delegate_->NotifyExcessiveDelays(log.profile,
 189                                          excessive_delays_.size(),
 190                                          request_ids_.size(),
 191                                          GetExtensionIds(log));
 192       }
 193     }
 194   } else if (percentage > kThresholdModerateDelay) {
 195     moderate_delays_.insert(request_id);
 196     if (moderate_delays_.size() + excessive_delays_.size() >
 197             kNumModerateDelaysBeforeWarning) {
 198       VLOG(1) << "WR moderate delays:" << moderate_delays_.size();
 199       if (delegate_.get()) {
 200         delegate_->NotifyModerateDelays(
 201             log.profile,
 202             moderate_delays_.size() + excessive_delays_.size(),
 203             request_ids_.size(),
 204             GetExtensionIds(log));
 205       }
 206     }
 207   }
 208 }
 209
 210 void ExtensionWebRequestTimeTracker::IncrementExtensionBlockTime(
 211     const std::string& extension_id,
 212     int64 request_id,
 213     const base::TimeDelta& block_time) {
 214   if (request_time_logs_.find(request_id) == request_time_logs_.end())
 215     return;
 216   RequestTimeLog& log = request_time_logs_[request_id];
 217   log.extension_block_durations[extension_id] += block_time;
 218 }
 219
 220 void ExtensionWebRequestTimeTracker::IncrementTotalBlockTime(
 221     int64 request_id,
 222     const base::TimeDelta& block_time) {
 223   if (request_time_logs_.find(request_id) == request_time_logs_.end())
 224     return;
 225   RequestTimeLog& log = request_time_logs_[request_id];
 226   log.block_duration += block_time;
 227 }
 228
 229 void ExtensionWebRequestTimeTracker::SetRequestCanceled(int64 request_id) {
 230   // Canceled requests won't actually hit the network, so we can't compare
 231   // their request time to the time spent waiting on the extension. Just ignore
 232   // them.
 233   // TODO(mpcomplete): may want to count cancels as "bonuses" for an extension.
 234   // i.e. if it slows down 50% of requests but cancels 25% of the rest, that
 235   // might average out to only being "25% slow".
 236   request_time_logs_.erase(request_id);
 237 }
 238
 239 void ExtensionWebRequestTimeTracker::SetRequestRedirected(int64 request_id) {
 240   // When a request is redirected, we have no way of knowing how long the
 241   // request would have taken, so we can't say how much an extension slowed
 242   // down this request. Just ignore it.
 243   request_time_logs_.erase(request_id);
 244 }
 245
 246 void ExtensionWebRequestTimeTracker::SetDelegate(
 247     ExtensionWebRequestTimeTrackerDelegate* delegate) {
 248   delegate_.reset(delegate);
 249 }