Added tracking of time spent waiting on extensions to the webRequest API.

chrome/browser/extensions/extension_webrequest_api.cc

 // Copyright (c) 2011 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "chrome/browser/extensions/extension_webrequest_api.h"
 
 #include <algorithm>
 
 #include "base/json/json_writer.h"
 #include "base/metrics/histogram.h"
 #include "base/string_number_conversions.h"
 #include "base/utf_string_conversions.h"
 #include "base/values.h"
 #include "chrome/browser/extensions/extension_event_router.h"
 #include "chrome/browser/extensions/extension_info_map.h"
 #include "chrome/browser/extensions/extension_prefs.h"
 #include "chrome/browser/extensions/extension_service.h"
 #include "chrome/browser/extensions/extension_tab_id_map.h"
 #include "chrome/browser/extensions/extension_webrequest_api_constants.h"
+#include "chrome/browser/extensions/extension_webrequest_time_tracker.h"
 #include "chrome/browser/profiles/profile.h"
 #include "chrome/browser/renderer_host/chrome_render_message_filter.h"
 #include "chrome/common/extensions/extension.h"
 #include "chrome/common/extensions/extension_error_utils.h"
 #include "chrome/common/extensions/url_pattern.h"
 #include "chrome/common/url_constants.h"
 #include "content/browser/browser_message_filter.h"
 #include "content/browser/browser_thread.h"
 #include "content/browser/renderer_host/resource_dispatcher_host.h"
 #include "content/browser/renderer_host/resource_dispatcher_host_request_info.h"
@@ skipping 394 matching lines @@
 // static
 void ExtensionWebRequestEventRouter::SetAllowChromeExtensionScheme() {
   allow_extension_scheme = true;
 }
 
 // static
 ExtensionWebRequestEventRouter* ExtensionWebRequestEventRouter::GetInstance() {
   return Singleton<ExtensionWebRequestEventRouter>::get();
 }
 
-ExtensionWebRequestEventRouter::ExtensionWebRequestEventRouter() {
+ExtensionWebRequestEventRouter::ExtensionWebRequestEventRouter()
+    : request_time_tracker_(new ExtensionWebRequestTimeTracker) {
 }
 
 ExtensionWebRequestEventRouter::~ExtensionWebRequestEventRouter() {
 }
 
 int ExtensionWebRequestEventRouter::OnBeforeRequest(
     void* profile,
     ExtensionInfoMap* extension_info_map,
     net::URLRequest* request,
     net::CompletionCallback* callback,
     GURL* new_url) {
   // TODO(jochen): Figure out what to do with events from the system context.
   if (!profile)
     return net::OK;
 
   if (!HasWebRequestScheme(request->url()))
     return net::OK;
 
+  request_time_tracker_->LogRequestStartTime(request->identifier(),
+                                             base::Time::Now(),
+                                             request->url());
+
   bool is_main_frame = false;
   int64 frame_id = -1;
   int frame_id_for_extension = -1;
   int tab_id = -1;
   int window_id = -1;
   ResourceType::Type resource_type = ResourceType::LAST_TYPE;
   ExtractRequestInfo(request, &is_main_frame, &frame_id, &tab_id, &window_id,
                      &resource_type);
   frame_id_for_extension = GetFrameId(is_main_frame, frame_id);
 
@@ skipping 264 matching lines @@
 void ExtensionWebRequestEventRouter::OnCompleted(
     void* profile,
     ExtensionInfoMap* extension_info_map,
     net::URLRequest* request) {
   if (!profile)
     return;
 
   if (!HasWebRequestScheme(request->url()))
     return;
 
+  request_time_tracker_->LogRequestEndTime(request->identifier(),
+                                           base::Time::Now());
+
   DCHECK(request->status().status() == net::URLRequestStatus::SUCCESS);
 
   DCHECK(!GetAndSetSignaled(request->identifier(), kOnCompleted));
 
   base::Time time(base::Time::Now());
 
   int extra_info_spec = 0;
   std::vector<const EventListener*> listeners =
       GetMatchingListeners(profile, extension_info_map,
                            keys::kOnCompleted, request, &extra_info_spec);
@@ skipping 31 matching lines @@
 void ExtensionWebRequestEventRouter::OnErrorOccurred(
     void* profile,
     ExtensionInfoMap* extension_info_map,
     net::URLRequest* request) {
   if (!profile)
       return;
 
   if (!HasWebRequestScheme(request->url()))
     return;
 
+  request_time_tracker_->LogRequestEndTime(request->identifier(),
+                                           base::Time::Now());
+
   DCHECK(request->status().status() == net::URLRequestStatus::FAILED ||
          request->status().status() == net::URLRequestStatus::CANCELED);
 
   DCHECK(!GetAndSetSignaled(request->identifier(), kOnErrorOccurred));
 
   base::Time time(base::Time::Now());
 
   int extra_info_spec = 0;
   std::vector<const EventListener*> listeners =
       GetMatchingListeners(profile, extension_info_map,
@@ skipping 16 matching lines @@
   dict->SetDouble(keys::kTimeStampKey, time.ToDoubleT() * 1000);
   args.Append(dict);
 
   DispatchEvent(profile, request, listeners, args);
 }
 
 void ExtensionWebRequestEventRouter::OnURLRequestDestroyed(
     void* profile, net::URLRequest* request) {
   blocked_requests_.erase(request->identifier());
   signaled_requests_.erase(request->identifier());
+
+  request_time_tracker_->LogRequestEndTime(request->identifier(),
+                                           base::Time::Now());
 }
 
 bool ExtensionWebRequestEventRouter::DispatchEvent(
     void* profile,
     net::URLRequest* request,
     const std::vector<const EventListener*>& listeners,
     const ListValue& args) {
   std::string json_args;
 
   // TODO(mpcomplete): Consider consolidating common (extension_id,json_args)
@@ skipping 52 matching lines @@
   listener.extension_id = extension_id;
   listener.sub_event_name = sub_event_name;
 
   // The listener may have been removed (e.g. due to the process going away)
   // before we got here.
   std::set<EventListener>::iterator found =
       listeners_[profile][event_name].find(listener);
   if (found != listeners_[profile][event_name].end())
     found->blocked_requests.erase(request_id);
 
-  DecrementBlockCount(profile, event_name, request_id, response);
+  DecrementBlockCount(profile, extension_id, event_name, request_id, response);
 }
 
 void ExtensionWebRequestEventRouter::AddEventListener(
     void* profile,
     const std::string& extension_id,
     const std::string& extension_name,
     const std::string& event_name,
     const std::string& sub_event_name,
     const RequestFilter& filter,
     int extra_info_spec,
@@ skipping 35 matching lines @@
       listeners_[profile][event_name].find(listener);
   if (found == listeners_[profile][event_name].end())
     return;
 
   CHECK_EQ(listeners_[profile][event_name].count(listener), 1u) <<
       "extension=" << extension_id << " event=" << event_name;
 
   // Unblock any request that this event listener may have been blocking.
   for (std::set<uint64>::iterator it = found->blocked_requests.begin();
        it != found->blocked_requests.end(); ++it) {
-    DecrementBlockCount(profile, event_name, *it, NULL);
+    DecrementBlockCount(profile, extension_id, event_name, *it, NULL);
   }
 
   listeners_[profile][event_name].erase(listener);
 }
 
 void ExtensionWebRequestEventRouter::OnOTRProfileCreated(
     void* original_profile, void* otr_profile) {
   cross_profile_map_[original_profile] = otr_profile;
   cross_profile_map_[otr_profile] = original_profile;
 }
@@ skipping 267 matching lines @@
       request->net_log->AddEvent(
           net::NetLog::TYPE_CHROME_EXTENSION_IGNORED_DUE_TO_CONFLICT,
           make_scoped_refptr(
               new NetLogExtensionIdParameter((*delta)->extension_id)));
     }
   }
 }
 
 void ExtensionWebRequestEventRouter::DecrementBlockCount(
     void* profile,
+    const std::string& extension_id,
     const std::string& event_name,
     uint64 request_id,
     EventResponse* response) {
   scoped_ptr<EventResponse> response_scoped(response);
 
   // It's possible that this request was deleted, or cancelled by a previous
   // event handler. If so, ignore this response.
   if (blocked_requests_.find(request_id) == blocked_requests_.end())
     return;
 
   BlockedRequest& blocked_request = blocked_requests_[request_id];
   int num_handlers_blocking = --blocked_request.num_handlers_blocking;
   CHECK_GE(num_handlers_blocking, 0);
 
   if (response) {
     blocked_request.response_deltas.push_back(
         CalculateDelta(&blocked_request, response));
   }
 
+  base::TimeDelta block_time =
+      base::Time::Now() - blocked_request.blocking_time;
+  request_time_tracker_->IncrementExtensionBlockTime(
+      extension_id, request_id, block_time);
+
   if (num_handlers_blocking == 0) {
-    // TODO(mpcomplete): it would be better if we accumulated the blocking times
-    // for a given request over all events.
-    HISTOGRAM_TIMES("Extensions.NetworkDelay",
-                     base::Time::Now() - blocked_request.blocking_time);
+    request_time_tracker_->IncrementTotalBlockTime(request_id, block_time);
 
     EventResponseDeltas::iterator i;
     EventResponseDeltas& deltas = blocked_request.response_deltas;
 
     bool canceled = false;
     for (i = deltas.begin(); i != deltas.end(); ++i) {
       if ((*i)->cancel) {
         canceled = true;
         blocked_request.net_log->AddEvent(
             net::NetLog::TYPE_CHROME_EXTENSION_ABORTED_REQUEST,
@@ skipping 19 matching lines @@
     std::list<std::string>::iterator conflict_iter;
     for (conflict_iter = conflicting_extensions.begin();
          conflict_iter != conflicting_extensions.end();
          ++conflict_iter) {
       // TODO(mpcomplete): Do some fancy notification in the UI.
       LOG(ERROR) << "Extension " << *conflict_iter << " was ignored in "
                     "webRequest API because of conflicting request "
                     "modifications.";
     }
 
+    if (canceled) {
+      request_time_tracker_->SetRequestCanceled(request_id);
+    } else if (blocked_request.new_url &&
+               !blocked_request.new_url->is_empty()) {
+      request_time_tracker_->SetRequestRedirected(request_id);
+    }
+
     // This signals a failed request to subscribers of onErrorOccurred in case
     // a request is cancelled because net::ERR_EMPTY_RESPONSE cannot be
     // distinguished from a regular failure.
     if (blocked_request.callback) {
       int rv = canceled ? net::ERR_EMPTY_RESPONSE : net::OK;
       net::CompletionCallback* callback = blocked_request.callback;
       // Ensure that request is removed before callback because the callback
       // might trigger the next event.
       blocked_requests_.erase(request_id);
       callback->Run(rv);
@@ skipping 148 matching lines @@
       }
     }
   }
 
   ExtensionWebRequestEventRouter::GetInstance()->OnEventHandled(
       profile(), extension_id(), event_name, sub_event_name, request_id,
       response.release());
 
   return true;
 }