Warn user in case extension delays network traffic too much.

chrome/browser/extensions/extension_webrequest_time_tracker.cc

Index: chrome/browser/extensions/extension_webrequest_time_tracker.cc
diff --git a/chrome/browser/extensions/extension_webrequest_time_tracker.cc b/chrome/browser/extensions/extension_webrequest_time_tracker.cc
index 9ccdef7387e43ae3668d033c8343aaddba75e9a5..780a287fa850703c82b7119ae35d4b8df9501602 100644
--- a/chrome/browser/extensions/extension_webrequest_time_tracker.cc
+++ b/chrome/browser/extensions/extension_webrequest_time_tracker.cc
@@ -15,6 +15,10 @@ const size_t kMaxRequestsLogged = 100u;
 // Any delays on such a request was negligible.
 const int kMinRequestTimeToCareMs = 10;
 
+// TODO(battre): remove TRIGGER_WARNINGS_EARLY before committing the CL.
+// This is just to simplify manual testing.
+// #define TRIGGER_WARNINGS_EARLY
+#ifndef TRIGGER_WARNINGS_EARLY
 // Thresholds above which we consider a delay caused by an extension to be "too
 // much". This is given in percentage of total request time that was spent
 // waiting on the extension.
@@ -25,23 +29,34 @@ const double kThresholdExcessiveDelay = 0.50;
 // delay, then we will warn the user.
 const size_t kNumModerateDelaysBeforeWarning = 50u;
 const size_t kNumExcessiveDelaysBeforeWarning = 10u;
+#else
+const double kThresholdModerateDelay = 0.10;
+const double kThresholdExcessiveDelay = 0.20;
+const size_t kNumModerateDelaysBeforeWarning = 5u;
+const size_t kNumExcessiveDelaysBeforeWarning = 2u;
+#endif // TRIGGER_WARNINGS_EARLY
+
 }  // namespace
 
 ExtensionWebRequestTimeTracker::RequestTimeLog::RequestTimeLog()
-    : completed(false) {
+    : profile(NULL), completed(false) {
 }
 
 ExtensionWebRequestTimeTracker::RequestTimeLog::~RequestTimeLog() {
 }
 
-ExtensionWebRequestTimeTracker::ExtensionWebRequestTimeTracker() {
+ExtensionWebRequestTimeTracker::ExtensionWebRequestTimeTracker()
+    : delegate_(NULL) {
 }
 
 ExtensionWebRequestTimeTracker::~ExtensionWebRequestTimeTracker() {
 }
 
 void ExtensionWebRequestTimeTracker::LogRequestStartTime(
-    int64 request_id, const base::Time& start_time, const GURL& url) {
+    int64 request_id,
+    const base::Time& start_time,
+    const GURL& url,
+    void* profile) {
   // Trim old completed request logs.
   while (request_ids_.size() > kMaxRequestsLogged) {
     int64 to_remove = request_ids_.front();
@@ -64,6 +79,7 @@ void ExtensionWebRequestTimeTracker::LogRequestStartTime(
   RequestTimeLog& log = request_time_logs_[request_id];
   log.request_start_time = start_time;
   log.url = url;
+  log.profile = profile;
 }
 
 void ExtensionWebRequestTimeTracker::LogRequestEndTime(
@@ -86,6 +102,18 @@ void ExtensionWebRequestTimeTracker::LogRequestEndTime(
   Analyze(request_id);
 }
 
+std::set<std::string> ExtensionWebRequestTimeTracker::GetExtensionIds(

[Matt Perry, 2011/10/06 22:55:54]

this is probably OK for now, but not really correct. It will blame all
extensions that happened to intercept a request that any 1 extension slowed
down. See my TODO in Analyze. I think what we should do is:
- wait until moderate or excessive delays hits the threshold.
- when it does, go back through all requests, and tally up individual block
times for extensions.
- only blame either (a) the slowest extension, or (b) the extensions that have
contributed more than X delay, where X is to be determined.

[battre, 2011/10/07 14:09:24]

I agree.

+    const RequestTimeLog& log) const {
+  std::set<std::string> result;
+  for (std::map<std::string, base::TimeDelta>::const_iterator i =
+           log.extension_block_durations.begin();
+       i != log.extension_block_durations.end();
+       ++i) {
+    result.insert(i->first);
+  }
+  return result;
+}
+
 void ExtensionWebRequestTimeTracker::Analyze(int64 request_id) {
   RequestTimeLog& log = request_time_logs_[request_id];
 
@@ -101,18 +129,31 @@ void ExtensionWebRequestTimeTracker::Analyze(int64 request_id) {
       log.block_duration.InMilliseconds() << "/" <<
       log.request_duration.InMilliseconds() << " = " << percentage;
 
-  // TODO(mpcomplete): need actual UI for the warning.
   // TODO(mpcomplete): blame a specific extension. Maybe go through the list
   // of recent requests and find the extension that has caused the most delays.
   if (percentage > kThresholdExcessiveDelay) {
     excessive_delays_.insert(request_id);
     if (excessive_delays_.size() > kNumExcessiveDelaysBeforeWarning) {
       LOG(ERROR) << "WR excessive delays:" << excessive_delays_.size();
+      if (delegate_) {
+        delegate_->NotifyExcessiveDelays(log.profile,
+                                         excessive_delays_.size(),
+                                         request_ids_.size(),
+                                         GetExtensionIds(log));
+      }
     }
   } else if (percentage > kThresholdModerateDelay) {
     moderate_delays_.insert(request_id);
-    if (moderate_delays_.size() > kNumModerateDelaysBeforeWarning) {
+    if (moderate_delays_.size() + excessive_delays_.size() >
+            kNumModerateDelaysBeforeWarning) {
       LOG(ERROR) << "WR moderate delays:" << moderate_delays_.size();
+      if (delegate_) {
+        delegate_->NotifyModerateDelays(
+            log.profile,
+            moderate_delays_.size() + excessive_delays_.size(),
+            request_ids_.size(),
+            GetExtensionIds(log));
+      }
     }
   }
 }
@@ -152,3 +193,8 @@ void ExtensionWebRequestTimeTracker::SetRequestRedirected(int64 request_id) {
   // down this request. Just ignore it.
   request_time_logs_.erase(request_id);
 }
+
+void ExtensionWebRequestTimeTracker::SetDelegate(
+    ExtensionWebRequestTimeTrackerDelegate* delegate) {
+  delegate_ = delegate;
+}