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