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 virtual ~DefaultDelegate() {} 38 39 // Implementation of ExtensionWebRequestTimeTrackerDelegate. 40 virtual 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 virtual 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 } 250
