Instrument ProxyService and InitProxyResolver with LoadLog.

BUG=http://crbug.com/14478

Review URL: http://codereview.chromium.org/172020

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

7 files changed, 246 insertions, 37 deletions

diff --git a/net/base/load_log_event_type_list.h b/net/base/load_log_event_type_list.h
index e259515..ba6b040 100644
--- a/net/base/load_log_event_type_list.h
+++ b/net/base/load_log_event_type_list.h
@@ -32,3 +32,31 @@ EVENT_TYPE(HOST_RESOLVER_IMPL_OBSERVER_ONFINISH)
 
 // The start/end of HostResolver::Observer::OnCancelResolution.
 EVENT_TYPE(HOST_RESOLVER_IMPL_OBSERVER_ONCANCEL)
+
+// ------------------------------------------------------------------------
+// InitProxyResolver
+// ------------------------------------------------------------------------
+
+// The start/end of auto-detect + custom PAC URL configuration.
+EVENT_TYPE(INIT_PROXY_RESOLVER)
+
+// The start/end of download of a PAC script. This could be the well-known
+// WPAD URL (if testing auto-detect), or a custom PAC URL.
+EVENT_TYPE(INIT_PROXY_RESOLVER_FETCH_PAC_SCRIPT)
+
+// The start/end of the testing of a PAC script (trying to parse the fetched
+// file as javascript).
+EVENT_TYPE(INIT_PROXY_RESOLVER_SET_PAC_SCRIPT)
+
+// ------------------------------------------------------------------------
+// ProxyService
+// ------------------------------------------------------------------------
+
+// The start/end of a proxy resolve request.
+EVENT_TYPE(PROXY_SERVICE)
+
+// The time while a request is waiting on InitProxyResolver to configure
+// against either WPAD or custom PAC URL. The specifics on this time
+// are found from ProxyService::init_proxy_resolver_log().
+EVENT_TYPE(PROXY_SERVICE_WAITING_FOR_INIT_PAC)
+
diff --git a/net/proxy/init_proxy_resolver.cc b/net/proxy/init_proxy_resolver.cc
index 7b98c4a..a185278 100644
--- a/net/proxy/init_proxy_resolver.cc
+++ b/net/proxy/init_proxy_resolver.cc
@@ -6,6 +6,7 @@
 
 #include "base/compiler_specific.h"
 #include "base/logging.h"
+#include "net/base/load_log.h"
 #include "net/base/net_errors.h"
 #include "net/proxy/proxy_config.h"
 #include "net/proxy/proxy_resolver.h"
@@ -25,23 +26,21 @@ InitProxyResolver::InitProxyResolver(ProxyResolver* resolver,
 }
 
 InitProxyResolver::~InitProxyResolver() {
-  switch (next_state_) {
-    case STATE_FETCH_PAC_SCRIPT_COMPLETE:
-      proxy_script_fetcher_->Cancel();
-      break;
-    case STATE_SET_PAC_SCRIPT_COMPLETE:
-      resolver_->CancelSetPacScript();
-      break;
-    default:
-      break;
-  }
+  if (next_state_ != STATE_NONE)
+    Cancel();
 }
 
 int InitProxyResolver::Init(const ProxyConfig& config,
-                            CompletionCallback* callback) {
+                            CompletionCallback* callback,
+                            LoadLog* load_log) {
   DCHECK_EQ(STATE_NONE, next_state_);
   DCHECK(callback);
   DCHECK(config.MayRequirePACResolver());
+  DCHECK(!load_log_);
+
+  load_log_ = load_log;
+
+  LoadLog::BeginEvent(load_log_, LoadLog::TYPE_INIT_PROXY_RESOLVER);
 
   pac_urls_ = BuildPacUrlsFallbackList(config);
   DCHECK(!pac_urls_.empty());
@@ -51,6 +50,9 @@ int InitProxyResolver::Init(const ProxyConfig& config,
   int rv = DoLoop(OK);
   if (rv == ERR_IO_PENDING)
     user_callback_ = callback;
+  else
+    DidCompleteInit();
+
   return rv;
 }
 
@@ -73,8 +75,10 @@ InitProxyResolver::UrlList InitProxyResolver::BuildPacUrlsFallbackList(
 void InitProxyResolver::OnIOCompletion(int result) {
   DCHECK_NE(STATE_NONE, next_state_);
   int rv = DoLoop(result);
-  if (rv != ERR_IO_PENDING)
+  if (rv != ERR_IO_PENDING) {
+    DidCompleteInit();
     DoCallback(rv);
+  }
 }
 
 int InitProxyResolver::DoLoop(int result) {
@@ -116,6 +120,9 @@ void InitProxyResolver::DoCallback(int result) {
 int InitProxyResolver::DoFetchPacScript() {
   DCHECK(resolver_->expects_pac_bytes());
 
+  LoadLog::BeginEvent(load_log_,
+      LoadLog::TYPE_INIT_PROXY_RESOLVER_FETCH_PAC_SCRIPT);
+
   next_state_ = STATE_FETCH_PAC_SCRIPT_COMPLETE;
 
   const GURL& pac_url = current_pac_url();
@@ -128,6 +135,9 @@ int InitProxyResolver::DoFetchPacScript() {
 int InitProxyResolver::DoFetchPacScriptComplete(int result) {
   DCHECK(resolver_->expects_pac_bytes());
 
+  LoadLog::EndEvent(load_log_,
+      LoadLog::TYPE_INIT_PROXY_RESOLVER_FETCH_PAC_SCRIPT);
+
   LOG(INFO) << "Completed PAC script fetch of " << current_pac_url()
             << " with result " << ErrorToString(result)
             << ". Fetched a total of " << pac_bytes_.size() << " bytes";
@@ -140,6 +150,9 @@ int InitProxyResolver::DoFetchPacScriptComplete(int result) {
 }
 
 int InitProxyResolver::DoSetPacScript() {
+  LoadLog::BeginEvent(load_log_,
+      LoadLog::TYPE_INIT_PROXY_RESOLVER_SET_PAC_SCRIPT);
+
   const GURL& pac_url = current_pac_url();
 
   next_state_ = STATE_SET_PAC_SCRIPT_COMPLETE;
@@ -150,6 +163,9 @@ int InitProxyResolver::DoSetPacScript() {
 }
 
 int InitProxyResolver::DoSetPacScriptComplete(int result) {
+  LoadLog::EndEvent(load_log_,
+      LoadLog::TYPE_INIT_PROXY_RESOLVER_SET_PAC_SCRIPT);
+
   if (result != OK) {
     LOG(INFO) << "Failed configuring PAC using " << current_pac_url()
               << " with error " << ErrorToString(result);
@@ -186,4 +202,28 @@ const GURL& InitProxyResolver::current_pac_url() const {
   return pac_urls_[current_pac_url_index_];
 }
 
+void InitProxyResolver::DidCompleteInit() {
+  LoadLog::EndEvent(load_log_, LoadLog::TYPE_INIT_PROXY_RESOLVER);
+}
+
+void InitProxyResolver::Cancel() {
+  DCHECK_NE(STATE_NONE, next_state_);
+
+  LoadLog::AddEvent(load_log_, LoadLog::TYPE_CANCELLED);
+
+  switch (next_state_) {
+    case STATE_FETCH_PAC_SCRIPT_COMPLETE:
+      proxy_script_fetcher_->Cancel();
+      break;
+    case STATE_SET_PAC_SCRIPT_COMPLETE:
+      resolver_->CancelSetPacScript();
+      break;
+    default:
+      NOTREACHED();
+      break;
+  }
+
+  DidCompleteInit();
+}
+
 }  // namespace net
diff --git a/net/proxy/init_proxy_resolver.h b/net/proxy/init_proxy_resolver.h
index 4da28f2..0bec8e9 100644
--- a/net/proxy/init_proxy_resolver.h
+++ b/net/proxy/init_proxy_resolver.h
@@ -13,6 +13,7 @@
 
 namespace net {
 
+class LoadLog;
 class ProxyConfig;
 class ProxyResolver;
 class ProxyScriptFetcher;
@@ -44,7 +45,9 @@ class InitProxyResolver {
   ~InitProxyResolver();
 
   // Apply the PAC settings of |config| to |resolver_|.
-  int Init(const ProxyConfig& config, CompletionCallback* callback);
+  int Init(const ProxyConfig& config,
+           CompletionCallback* callback,
+           LoadLog* load_log);
 
  private:
   enum State {
@@ -82,6 +85,9 @@ class InitProxyResolver {
   // Returns the current PAC URL we are fetching/testing.
   const GURL& current_pac_url() const;
 
+  void DidCompleteInit();
+  void Cancel();
+
   ProxyResolver* resolver_;
   ProxyScriptFetcher* proxy_script_fetcher_;
 
@@ -96,6 +102,8 @@ class InitProxyResolver {
   UrlList pac_urls_;
   State next_state_;
 
+  scoped_refptr<LoadLog> load_log_;
+
   DISALLOW_COPY_AND_ASSIGN(InitProxyResolver);
 };
 
diff --git a/net/proxy/init_proxy_resolver_unittest.cc b/net/proxy/init_proxy_resolver_unittest.cc
index 1f4417d..c1e45a8 100644
--- a/net/proxy/init_proxy_resolver_unittest.cc
+++ b/net/proxy/init_proxy_resolver_unittest.cc
@@ -5,6 +5,8 @@
 #include <vector>
 
 #include "net/base/net_errors.h"
+#include "net/base/load_log.h"
+#include "net/base/load_log_unittest.h"
 #include "net/base/test_completion_callback.h"
 #include "net/proxy/init_proxy_resolver.h"
 #include "net/proxy/proxy_config.h"
@@ -168,9 +170,25 @@ TEST(InitProxyResolverTest, CustomPacSucceeds) {
   Rules::Rule rule = rules.AddSuccessRule("http://custom/proxy.pac");
 
   TestCompletionCallback callback;
+  scoped_refptr<LoadLog> log(new LoadLog);
   InitProxyResolver init(&resolver, &fetcher);
-  EXPECT_EQ(OK, init.Init(config, &callback));
+  EXPECT_EQ(OK, init.Init(config, &callback, log));
   EXPECT_EQ(rule.bytes(), resolver.pac_bytes());
+
+  // Check the LoadLog was filled correctly.
+  EXPECT_EQ(6u, log->events().size());
+  ExpectLogContains(log, 0, LoadLog::TYPE_INIT_PROXY_RESOLVER,
+      LoadLog::PHASE_BEGIN);
+  ExpectLogContains(log, 1, LoadLog::TYPE_INIT_PROXY_RESOLVER_FETCH_PAC_SCRIPT,
+      LoadLog::PHASE_BEGIN);
+  ExpectLogContains(log, 2, LoadLog::TYPE_INIT_PROXY_RESOLVER_FETCH_PAC_SCRIPT,
+      LoadLog::PHASE_END);
+  ExpectLogContains(log, 3, LoadLog::TYPE_INIT_PROXY_RESOLVER_SET_PAC_SCRIPT,
+      LoadLog::PHASE_BEGIN);
+  ExpectLogContains(log, 4, LoadLog::TYPE_INIT_PROXY_RESOLVER_SET_PAC_SCRIPT,
+      LoadLog::PHASE_END);
+  ExpectLogContains(log, 5, LoadLog::TYPE_INIT_PROXY_RESOLVER,
+      LoadLog::PHASE_END);
 }
 
 // Fail downloading the custom PAC script.
@@ -185,9 +203,21 @@ TEST(InitProxyResolverTest, CustomPacFails1) {
   rules.AddFailDownloadRule("http://custom/proxy.pac");
 
   TestCompletionCallback callback;
+  scoped_refptr<LoadLog> log(new LoadLog);
   InitProxyResolver init(&resolver, &fetcher);
-  EXPECT_EQ(kFailedDownloading, init.Init(config, &callback));
+  EXPECT_EQ(kFailedDownloading, init.Init(config, &callback, log));
   EXPECT_EQ("", resolver.pac_bytes());
+
+  // Check the LoadLog was filled correctly.
+  EXPECT_EQ(4u, log->events().size());
+  ExpectLogContains(log, 0, LoadLog::TYPE_INIT_PROXY_RESOLVER,
+      LoadLog::PHASE_BEGIN);
+  ExpectLogContains(log, 1, LoadLog::TYPE_INIT_PROXY_RESOLVER_FETCH_PAC_SCRIPT,
+      LoadLog::PHASE_BEGIN);
+  ExpectLogContains(log, 2, LoadLog::TYPE_INIT_PROXY_RESOLVER_FETCH_PAC_SCRIPT,
+      LoadLog::PHASE_END);
+  ExpectLogContains(log, 3, LoadLog::TYPE_INIT_PROXY_RESOLVER,
+      LoadLog::PHASE_END);
 }
 
 // Fail parsing the custom PAC script.
@@ -203,7 +233,7 @@ TEST(InitProxyResolverTest, CustomPacFails2) {
 
   TestCompletionCallback callback;
   InitProxyResolver init(&resolver, &fetcher);
-  EXPECT_EQ(kFailedParsing, init.Init(config, &callback));
+  EXPECT_EQ(kFailedParsing, init.Init(config, &callback, NULL));
   EXPECT_EQ("", resolver.pac_bytes());
 }
 
@@ -220,7 +250,7 @@ TEST(InitProxyResolverTest, AutodetectSuccess) {
 
   TestCompletionCallback callback;
   InitProxyResolver init(&resolver, &fetcher);
-  EXPECT_EQ(OK, init.Init(config, &callback));
+  EXPECT_EQ(OK, init.Init(config, &callback, NULL));
   EXPECT_EQ(rule.bytes(), resolver.pac_bytes());
 }
 
@@ -239,7 +269,7 @@ TEST(InitProxyResolverTest, AutodetectFailCustomSuccess1) {
 
   TestCompletionCallback callback;
   InitProxyResolver init(&resolver, &fetcher);
-  EXPECT_EQ(OK, init.Init(config, &callback));
+  EXPECT_EQ(OK, init.Init(config, &callback, NULL));
   EXPECT_EQ(rule.bytes(), resolver.pac_bytes());
 }
 
@@ -257,9 +287,35 @@ TEST(InitProxyResolverTest, AutodetectFailCustomSuccess2) {
   Rules::Rule rule = rules.AddSuccessRule("http://custom/proxy.pac");
 
   TestCompletionCallback callback;
+  scoped_refptr<LoadLog> log(new LoadLog);
   InitProxyResolver init(&resolver, &fetcher);
-  EXPECT_EQ(OK, init.Init(config, &callback));
+  EXPECT_EQ(OK, init.Init(config, &callback, log));
   EXPECT_EQ(rule.bytes(), resolver.pac_bytes());
+
+  // Check the LoadLog was filled correctly.
+  // (Note that the Fetch and Set states are repeated since both WPAD and custom
+  // PAC scripts are tried).
+  EXPECT_EQ(10u, log->events().size());
+  ExpectLogContains(log, 0, LoadLog::TYPE_INIT_PROXY_RESOLVER,
+      LoadLog::PHASE_BEGIN);
+  ExpectLogContains(log, 1, LoadLog::TYPE_INIT_PROXY_RESOLVER_FETCH_PAC_SCRIPT,
+      LoadLog::PHASE_BEGIN);
+  ExpectLogContains(log, 2, LoadLog::TYPE_INIT_PROXY_RESOLVER_FETCH_PAC_SCRIPT,
+      LoadLog::PHASE_END);
+  ExpectLogContains(log, 3, LoadLog::TYPE_INIT_PROXY_RESOLVER_SET_PAC_SCRIPT,
+      LoadLog::PHASE_BEGIN);
+  ExpectLogContains(log, 4, LoadLog::TYPE_INIT_PROXY_RESOLVER_SET_PAC_SCRIPT,
+      LoadLog::PHASE_END);
+  ExpectLogContains(log, 5, LoadLog::TYPE_INIT_PROXY_RESOLVER_FETCH_PAC_SCRIPT,
+      LoadLog::PHASE_BEGIN);
+  ExpectLogContains(log, 6, LoadLog::TYPE_INIT_PROXY_RESOLVER_FETCH_PAC_SCRIPT,
+      LoadLog::PHASE_END);
+  ExpectLogContains(log, 7, LoadLog::TYPE_INIT_PROXY_RESOLVER_SET_PAC_SCRIPT,
+      LoadLog::PHASE_BEGIN);
+  ExpectLogContains(log, 8, LoadLog::TYPE_INIT_PROXY_RESOLVER_SET_PAC_SCRIPT,
+      LoadLog::PHASE_END);
+  ExpectLogContains(log, 9, LoadLog::TYPE_INIT_PROXY_RESOLVER,
+      LoadLog::PHASE_END);
 }
 
 // Fails at WPAD (downloading), and fails at custom PAC (downloading).
@@ -277,7 +333,7 @@ TEST(InitProxyResolverTest, AutodetectFailCustomFails1) {
 
   TestCompletionCallback callback;
   InitProxyResolver init(&resolver, &fetcher);
-  EXPECT_EQ(kFailedDownloading, init.Init(config, &callback));
+  EXPECT_EQ(kFailedDownloading, init.Init(config, &callback, NULL));
   EXPECT_EQ("", resolver.pac_bytes());
 }
 
@@ -296,7 +352,7 @@ TEST(InitProxyResolverTest, AutodetectFailCustomFails2) {
 
   TestCompletionCallback callback;
   InitProxyResolver init(&resolver, &fetcher);
-  EXPECT_EQ(kFailedParsing, init.Init(config, &callback));
+  EXPECT_EQ(kFailedParsing, init.Init(config, &callback, NULL));
   EXPECT_EQ("", resolver.pac_bytes());
 }
 
@@ -317,7 +373,7 @@ TEST(InitProxyResolverTest, AutodetectFailCustomSuccess2_NoFetch) {
 
   TestCompletionCallback callback;
   InitProxyResolver init(&resolver, &fetcher);
-  EXPECT_EQ(OK, init.Init(config, &callback));
+  EXPECT_EQ(OK, init.Init(config, &callback, NULL));
   EXPECT_EQ(rule.url, resolver.pac_url());
 }
 
diff --git a/net/proxy/proxy_service.cc b/net/proxy/proxy_service.cc
index 43e6808..34d7b3c 100644
--- a/net/proxy/proxy_service.cc
+++ b/net/proxy/proxy_service.cc
@@ -11,6 +11,7 @@
 #include "base/message_loop.h"
 #include "base/string_util.h"
 #include "googleurl/src/gurl.h"
+#include "net/base/load_log.h"
 #include "net/base/net_errors.h"
 #include "net/base/net_util.h"
 #include "net/proxy/init_proxy_resolver.h"
@@ -77,7 +78,8 @@ class ProxyService::PacRequest
   PacRequest(ProxyService* service,
              const GURL& url,
              ProxyInfo* results,
-             CompletionCallback* user_callback)
+             CompletionCallback* user_callback,
+             LoadLog* load_log)
       : service_(service),
         user_callback_(user_callback),
         ALLOW_THIS_IN_INITIALIZER_LIST(io_callback_(
@@ -85,7 +87,8 @@ class ProxyService::PacRequest
         results_(results),
         url_(url),
         resolve_job_(NULL),
-        config_id_(ProxyConfig::INVALID_ID) {
+        config_id_(ProxyConfig::INVALID_ID),
+        load_log_(load_log) {
     DCHECK(user_callback);
   }
 
@@ -96,8 +99,11 @@ class ProxyService::PacRequest
 
     config_id_ = service_->config_.id();
 
+    // TODO(eroman): ProxyResolver::GetProxyForURL should take LoadLog*.
+    // Then we can pass in |load_log_| and understand how much time is
+    // spent in bindings like dnsResolve()!
     return resolver()->GetProxyForURL(
-        url_, results_, &io_callback_, &resolve_job_);
+        url_, results_, &io_callback_, &resolve_job_/*, load_log_*/);
   }
 
   bool is_started() const {
@@ -114,21 +120,25 @@ class ProxyService::PacRequest
   }
 
   void CancelResolveJob() {
+    DCHECK(is_started());
     // The request may already be running in the resolver.
-    if (is_started()) {
-      resolver()->CancelRequest(resolve_job_);
-      resolve_job_ = NULL;
-    }
+    resolver()->CancelRequest(resolve_job_);
+    resolve_job_ = NULL;
     DCHECK(!is_started());
   }
 
   void Cancel() {
-    CancelResolveJob();
+    LoadLog::AddEvent(load_log_, LoadLog::TYPE_CANCELLED);
+
+    if (is_started())
+      CancelResolveJob();
 
     // Mark as cancelled, to prevent accessing this again later.
     service_ = NULL;
     user_callback_ = NULL;
     results_ = NULL;
+
+    LoadLog::EndEvent(load_log_, LoadLog::TYPE_PROXY_SERVICE);
   }
 
   // Returns true if Cancel() has been called.
@@ -154,9 +164,13 @@ class ProxyService::PacRequest
     if (result_code == OK)
       results_->RemoveBadProxies(service_->proxy_retry_info_);
 
+    LoadLog::EndEvent(load_log_, LoadLog::TYPE_PROXY_SERVICE);
+
     return result_code;
   }
 
+  LoadLog* load_log() const { return load_log_; }
+
  private:
   // Callback for when the ProxyResolver request has completed.
   void QueryComplete(int result_code) {
@@ -179,6 +193,7 @@ class ProxyService::PacRequest
   GURL url_;
   ProxyResolver::RequestHandle resolve_job_;
   ProxyConfig::ID config_id_;  // The config id when the resolve was started.
+  scoped_refptr<LoadLog> load_log_;
 };
 
 // ProxyService ---------------------------------------------------------------
@@ -253,6 +268,8 @@ int ProxyService::ResolveProxy(const GURL& raw_url,
                                LoadLog* load_log) {
   DCHECK(callback);
 
+  LoadLog::BeginEvent(load_log, LoadLog::TYPE_PROXY_SERVICE);
+
   // Strip away any reference fragments and the username/password, as they
   // are not relevant to proxy resolution.
   GURL url = SimplifyUrlForRequest(raw_url);
@@ -261,10 +278,13 @@ int ProxyService::ResolveProxy(const GURL& raw_url,
   // using a direct connection, or when the config is bad.
   UpdateConfigIfOld();
   int rv = TryToCompleteSynchronously(url, result);
-  if (rv != ERR_IO_PENDING)
+  if (rv != ERR_IO_PENDING) {
+    LoadLog::EndEvent(load_log, LoadLog::TYPE_PROXY_SERVICE);
     return rv;
+  }
 
-  scoped_refptr<PacRequest> req = new PacRequest(this, url, result, callback);
+  scoped_refptr<PacRequest> req =
+      new PacRequest(this, url, result, callback, load_log);
 
   bool resolver_is_ready = !IsInitializingProxyResolver();
 
@@ -273,6 +293,9 @@ int ProxyService::ResolveProxy(const GURL& raw_url,
     rv = req->Start();
     if (rv != ERR_IO_PENDING)
       return req->QueryDidComplete(rv);
+  } else {
+    LoadLog::BeginEvent(req->load_log(),
+        LoadLog::TYPE_PROXY_SERVICE_WAITING_FOR_INIT_PAC);
   }
 
   DCHECK_EQ(ERR_IO_PENDING, rv);
@@ -363,7 +386,13 @@ void ProxyService::SuspendAllPendingRequests() {
   for (PendingRequests::iterator it = pending_requests_.begin();
        it != pending_requests_.end();
        ++it) {
-    it->get()->CancelResolveJob();
+    PacRequest* req = it->get();
+    if (req->is_started()) {
+      req->CancelResolveJob();
+
+      LoadLog::BeginEvent(req->load_log(),
+          LoadLog::TYPE_PROXY_SERVICE_WAITING_FOR_INIT_PAC);
+    }
   }
 }
 
@@ -380,6 +409,9 @@ void ProxyService::ResumeAllPendingRequests() {
        ++it) {
     PacRequest* req = it->get();
     if (!req->is_started() && !req->was_cancelled()) {
+      LoadLog::EndEvent(req->load_log(),
+          LoadLog::TYPE_PROXY_SERVICE_WAITING_FOR_INIT_PAC);
+
       // Note that we re-check for synchronous completion, in case we are
       // no longer using a ProxyResolver (can happen if we fell-back to manual).
       req->StartAndCompleteCheckingForSynchronous();
@@ -590,8 +622,12 @@ void ProxyService::SetConfig(const ProxyConfig& config) {
 
     init_proxy_resolver_.reset(
         new InitProxyResolver(resolver_.get(), proxy_script_fetcher_.get()));
+
+    init_proxy_resolver_log_ = new LoadLog;
+
     int rv = init_proxy_resolver_->Init(
-        config_, &init_proxy_resolver_callback_);
+        config_, &init_proxy_resolver_callback_, init_proxy_resolver_log_);
+
     if (rv != ERR_IO_PENDING)
       OnInitProxyResolverComplete(rv);
   }
diff --git a/net/proxy/proxy_service.h b/net/proxy/proxy_service.h
index 994cb5a..483e055 100644
--- a/net/proxy/proxy_service.h
+++ b/net/proxy/proxy_service.h
@@ -103,6 +103,13 @@ class ProxyService {
   // |new_proxy_config_service|.
   void ResetConfigService(ProxyConfigService* new_proxy_config_service);
 
+  // Returns the log for the most recent WPAD + PAC initialization.
+  // (This shows how much time was spent downloading and parsing the
+  // PAC scripts for the current configuration).
+  LoadLog* init_proxy_resolver_log() const {
+    return init_proxy_resolver_log_;
+  }
+
   // Creates a proxy service using the specified settings. If |pc| is NULL then
   // the system's default proxy settings will be used (on Windows this will
   // use IE's settings).
@@ -224,6 +231,9 @@ class ProxyService {
   // Helper to download the PAC script (wpad + custom) and apply fallback rules.
   scoped_ptr<InitProxyResolver> init_proxy_resolver_;
 
+  // Log from the *last* time |init_proxy_resolver_.Init()| was called, or NULL.
+  scoped_refptr<LoadLog> init_proxy_resolver_log_;
+
   scoped_ptr<ProxyConfigService> config_service_;
   scoped_ptr<ProxyResolver> resolver_;
 
diff --git a/net/proxy/proxy_service_unittest.cc b/net/proxy/proxy_service_unittest.cc
index 3fde148..7018cda 100644
--- a/net/proxy/proxy_service_unittest.cc
+++ b/net/proxy/proxy_service_unittest.cc
@@ -7,6 +7,8 @@
 #include "base/logging.h"
 #include "base/string_util.h"
 #include "googleurl/src/gurl.h"
+#include "net/base/load_log.h"
+#include "net/base/load_log_unittest.h"
 #include "net/base/net_errors.h"
 #include "net/base/test_completion_callback.h"
 #include "net/proxy/mock_proxy_resolver.h"
@@ -92,11 +94,18 @@ TEST(ProxyServiceTest, Direct) {
 
   ProxyInfo info;
   TestCompletionCallback callback;
-  int rv = service.ResolveProxy(url, &info, &callback, NULL, NULL);
+  scoped_refptr<LoadLog> log(new LoadLog);
+  int rv = service.ResolveProxy(url, &info, &callback, NULL, log);
   EXPECT_EQ(OK, rv);
   EXPECT_TRUE(resolver->pending_requests().empty());
+  EXPECT_TRUE(NULL == service.init_proxy_resolver_log());
 
   EXPECT_TRUE(info.is_direct());
+
+  // Check the LoadLog was filled correctly.
+  EXPECT_EQ(2u, log->events().size());
+  ExpectLogContains(log, 0, LoadLog::TYPE_PROXY_SERVICE, LoadLog::PHASE_BEGIN);
+  ExpectLogContains(log, 1, LoadLog::TYPE_PROXY_SERVICE, LoadLog::PHASE_END);
 }
 
 TEST(ProxyServiceTest, PAC) {
@@ -111,11 +120,13 @@ TEST(ProxyServiceTest, PAC) {
 
   ProxyInfo info;
   TestCompletionCallback callback;
-  int rv = service.ResolveProxy(url, &info, &callback, NULL, NULL);
+  scoped_refptr<LoadLog> log(new LoadLog);
+  int rv = service.ResolveProxy(url, &info, &callback, NULL, log);
   EXPECT_EQ(ERR_IO_PENDING, rv);
 
   EXPECT_EQ(GURL("http://foopy/proxy.pac"),
             resolver->pending_set_pac_script_request()->pac_url());
+  EXPECT_FALSE(NULL == service.init_proxy_resolver_log());
   resolver->pending_set_pac_script_request()->CompleteNow(OK);
 
   ASSERT_EQ(1u, resolver->pending_requests().size());
@@ -128,6 +139,15 @@ TEST(ProxyServiceTest, PAC) {
   EXPECT_EQ(OK, callback.WaitForResult());
   EXPECT_FALSE(info.is_direct());
   EXPECT_EQ("foopy:80", info.proxy_server().ToURI());
+
+  // Check the LoadLog was filled correctly.
+  EXPECT_EQ(4u, log->events().size());
+  ExpectLogContains(log, 0, LoadLog::TYPE_PROXY_SERVICE, LoadLog::PHASE_BEGIN);
+  ExpectLogContains(log, 1, LoadLog::TYPE_PROXY_SERVICE_WAITING_FOR_INIT_PAC,
+      LoadLog::PHASE_BEGIN);
+  ExpectLogContains(log, 2, LoadLog::TYPE_PROXY_SERVICE_WAITING_FOR_INIT_PAC,
+      LoadLog::PHASE_END);
+  ExpectLogContains(log, 3, LoadLog::TYPE_PROXY_SERVICE, LoadLog::PHASE_END);
 }
 
 // Test that the proxy resolver does not see the URL's username/password
@@ -989,8 +1009,9 @@ TEST(ProxyServiceTest, CancelWhilePACFetching) {
   ProxyInfo info1;
   TestCompletionCallback callback1;
   ProxyService::PacRequest* request1;
+  scoped_refptr<LoadLog> log1(new LoadLog);
   int rv = service.ResolveProxy(
-      GURL("http://request1"), &info1, &callback1, &request1, NULL);
+      GURL("http://request1"), &info1, &callback1, &request1, log1);
   EXPECT_EQ(ERR_IO_PENDING, rv);
 
   // The first request should have triggered download of PAC script.
@@ -1041,6 +1062,16 @@ TEST(ProxyServiceTest, CancelWhilePACFetching) {
 
   EXPECT_FALSE(callback1.have_result());  // Cancelled.
   EXPECT_FALSE(callback2.have_result());  // Cancelled.
+
+  // Check the LoadLog for request 1 (which was cancelled) got filled properly.
+  EXPECT_EQ(4u, log1->events().size());
+  ExpectLogContains(log1, 0, LoadLog::TYPE_PROXY_SERVICE, LoadLog::PHASE_BEGIN);
+  ExpectLogContains(log1, 1, 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);
 }
 
 // Test that if auto-detect fails, we fall-back to the custom pac.