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