Add a new event to LoadLog:

    PROXY_SERVICE_POLL_CONFIG_SERVICE_FOR_CHANGES

which measures how much time was spent per request retrieving the system proxy settings.

On Windows this corresponds with the function:

  WinHttpGetIEProxyConfigForCurrentUser().

Which seems to be very slow on some systems.

BUG=12189
Review URL: http://codereview.chromium.org/452034

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@33508 0039d316-1c4b-4281-b951-d872f2087c98

3 files changed, 29 insertions, 21 deletions

diff --git a/net/proxy/proxy_service.cc b/net/proxy/proxy_service.cc
index 92870fe..dc97d47 100644
--- a/net/proxy/proxy_service.cc
+++ b/net/proxy/proxy_service.cc
@@ -278,7 +278,7 @@ int ProxyService::ResolveProxy(const GURL& raw_url,
 
   // Check if the request can be completed right away. This is the case when
   // using a direct connection, or when the config is bad.
-  UpdateConfigIfOld();
+  UpdateConfigIfOld(load_log);
   int rv = TryToCompleteSynchronously(url, result);
   if (rv != ERR_IO_PENDING) {
     LoadLog::EndEvent(load_log, LoadLog::TYPE_PROXY_SERVICE);
@@ -450,7 +450,7 @@ int ProxyService::ReconsiderProxyAfterError(const GURL& url,
 
   bool re_resolve = result->config_id_ != config_.id();
   if (!re_resolve) {
-    UpdateConfig();
+    UpdateConfig(load_log);
     if (result->config_id_ != config_.id()) {
       // A new configuration!
       re_resolve = true;
@@ -535,7 +535,7 @@ ProxyScriptFetcher* ProxyService::GetProxyScriptFetcher() const {
 void ProxyService::ResetConfigService(
     ProxyConfigService* new_proxy_config_service) {
   config_service_.reset(new_proxy_config_service);
-  UpdateConfig();
+  UpdateConfig(NULL);
 }
 
 void ProxyService::PurgeMemory() {
@@ -602,11 +602,19 @@ ProxyResolver* ProxyService::CreateNonV8ProxyResolver() {
 #endif
 }
 
-void ProxyService::UpdateConfig() {
+void ProxyService::UpdateConfig(LoadLog* load_log) {
   bool is_first_update = !config_has_been_initialized();
 
   ProxyConfig latest;
-  if (config_service_->GetProxyConfig(&latest) != OK) {
+
+  // Fetch the proxy settings.
+  LoadLog::BeginEvent(load_log,
+      LoadLog::TYPE_PROXY_SERVICE_POLL_CONFIG_SERVICE_FOR_CHANGES);
+  int rv = config_service_->GetProxyConfig(&latest);
+  LoadLog::EndEvent(load_log,
+      LoadLog::TYPE_PROXY_SERVICE_POLL_CONFIG_SERVICE_FOR_CHANGES);
+
+  if (rv != OK) {
     if (is_first_update) {
       // Default to direct-connection if the first fetch fails.
       LOG(INFO) << "Failed initial proxy configuration fetch.";
@@ -665,14 +673,14 @@ void ProxyService::StartInitProxyResolver() {
     OnInitProxyResolverComplete(rv);
 }
 
-void ProxyService::UpdateConfigIfOld() {
+void ProxyService::UpdateConfigIfOld(LoadLog* load_log) {
   // The overhead of calling ProxyConfigService::GetProxyConfig is very low.
   const TimeDelta kProxyConfigMaxAge = TimeDelta::FromSeconds(5);
 
   // Periodically check for a new config.
   if (!config_has_been_initialized() ||
       (TimeTicks::Now() - config_last_update_time_) > kProxyConfigMaxAge)
-    UpdateConfig();
+    UpdateConfig(load_log);
 }
 
 bool ProxyService::ShouldBypassProxyForURL(const GURL& url) {
diff --git a/net/proxy/proxy_service.h b/net/proxy/proxy_service.h
index 4324e40..715a9c2 100644
--- a/net/proxy/proxy_service.h
+++ b/net/proxy/proxy_service.h
@@ -176,7 +176,7 @@ class ProxyService : public base::RefCountedThreadSafe<ProxyService> {
 
   // Checks to see if the proxy configuration changed, and then updates config_
   // to reference the new configuration.
-  void UpdateConfig();
+  void UpdateConfig(LoadLog* load_log);
 
   // Assign |config| as the current configuration.
   void SetConfig(const ProxyConfig& config);
@@ -186,7 +186,7 @@ class ProxyService : public base::RefCountedThreadSafe<ProxyService> {
   void StartInitProxyResolver();
 
   // Tries to update the configuration if it hasn't been checked in a while.
-  void UpdateConfigIfOld();
+  void UpdateConfigIfOld(LoadLog* load_log);
 
   // Returns true if the proxy resolver is being initialized for PAC
   // (downloading PAC script(s) + testing).
diff --git a/net/proxy/proxy_service_unittest.cc b/net/proxy/proxy_service_unittest.cc
index 6dbee99..3422b5a 100644
--- a/net/proxy/proxy_service_unittest.cc
+++ b/net/proxy/proxy_service_unittest.cc
@@ -106,9 +106,9 @@ TEST(ProxyServiceTest, Direct) {
   EXPECT_TRUE(info.is_direct());
 
   // Check the LoadLog was filled correctly.
-  EXPECT_EQ(2u, log->events().size());
+  EXPECT_EQ(4u, log->events().size());
   ExpectLogContains(log, 0, LoadLog::TYPE_PROXY_SERVICE, LoadLog::PHASE_BEGIN);
-  ExpectLogContains(log, 1, LoadLog::TYPE_PROXY_SERVICE, LoadLog::PHASE_END);
+  ExpectLogContains(log, 3, LoadLog::TYPE_PROXY_SERVICE, LoadLog::PHASE_END);
 }
 
 TEST(ProxyServiceTest, PAC) {
@@ -145,13 +145,13 @@ TEST(ProxyServiceTest, PAC) {
   EXPECT_EQ("foopy:80", info.proxy_server().ToURI());
 
   // Check the LoadLog was filled correctly.
-  EXPECT_EQ(4u, log->events().size());
+  EXPECT_EQ(6u, log->events().size());
   ExpectLogContains(log, 0, LoadLog::TYPE_PROXY_SERVICE, LoadLog::PHASE_BEGIN);
-  ExpectLogContains(log, 1, LoadLog::TYPE_PROXY_SERVICE_WAITING_FOR_INIT_PAC,
+  ExpectLogContains(log, 3, LoadLog::TYPE_PROXY_SERVICE_WAITING_FOR_INIT_PAC,
                     LoadLog::PHASE_BEGIN);
-  ExpectLogContains(log, 2, LoadLog::TYPE_PROXY_SERVICE_WAITING_FOR_INIT_PAC,
+  ExpectLogContains(log, 4, LoadLog::TYPE_PROXY_SERVICE_WAITING_FOR_INIT_PAC,
                     LoadLog::PHASE_END);
-  ExpectLogContains(log, 3, LoadLog::TYPE_PROXY_SERVICE, LoadLog::PHASE_END);
+  ExpectLogContains(log, 5, LoadLog::TYPE_PROXY_SERVICE, LoadLog::PHASE_END);
 }
 
 // Test that the proxy resolver does not see the URL's username/password
@@ -1134,14 +1134,14 @@ TEST(ProxyServiceTest, CancelWhilePACFetching) {
   EXPECT_FALSE(callback2.have_result());  // Cancelled.
 
   // Check the LoadLog for request 1 (which was cancelled) got filled properly.
-  EXPECT_EQ(4u, log1->events().size());
+  EXPECT_EQ(6u, log1->events().size());
   ExpectLogContains(log1, 0, LoadLog::TYPE_PROXY_SERVICE, LoadLog::PHASE_BEGIN);
-  ExpectLogContains(log1, 1, LoadLog::TYPE_PROXY_SERVICE_WAITING_FOR_INIT_PAC,
+  ExpectLogContains(log1, 3, LoadLog::TYPE_PROXY_SERVICE_WAITING_FOR_INIT_PAC,
                     LoadLog::PHASE_BEGIN);
   // Note that TYPE_PROXY_SERVICE_WAITING_FOR_INIT_PAC is never completed before
   // the cancellation occured.
-  ExpectLogContains(log1, 2, LoadLog::TYPE_CANCELLED, LoadLog::PHASE_NONE);
-  ExpectLogContains(log1, 3, LoadLog::TYPE_PROXY_SERVICE, LoadLog::PHASE_END);
+  ExpectLogContains(log1, 4, LoadLog::TYPE_CANCELLED, LoadLog::PHASE_NONE);
+  ExpectLogContains(log1, 5, LoadLog::TYPE_PROXY_SERVICE, LoadLog::PHASE_END);
 }
 
 // Test that if auto-detect fails, we fall-back to the custom pac.
@@ -1517,7 +1517,7 @@ TEST(ProxyServiceTest, UpdateConfigAfterFailedAutodetect) {
 
   // Force the ProxyService to pull down a new proxy configuration.
   // (Even though the configuration isn't old/bad).
-  service->UpdateConfig();
+  service->UpdateConfig(NULL);
 
   // Start another request -- the effective configuration has not
   // changed, so we shouldn't re-run the autodetect step.
@@ -1573,7 +1573,7 @@ TEST(ProxyServiceTest, UpdateConfigFromPACToDirect) {
   // requests should complete synchronously now as direct-connect.
   config.auto_detect = false;
   config_service->config = config;
-  service->UpdateConfig();
+  service->UpdateConfig(NULL);
 
   // Start another request -- the effective configuration has changed.
   ProxyInfo info2;