Add a timing measurement to LoadLog that shows how long a proxy resolve request was stalled waiting to be scheduled to a thread.

TEST=SingleThreadedProxyResolverTest.UpdatesLoadLogWithThreadWait
Review URL: http://codereview.chromium.org/570019

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

2 files changed, 85 insertions, 2 deletions

diff --git a/net/proxy/single_threaded_proxy_resolver.cc b/net/proxy/single_threaded_proxy_resolver.cc
index 5de2865..05c8af0 100644
--- a/net/proxy/single_threaded_proxy_resolver.cc
+++ b/net/proxy/single_threaded_proxy_resolver.cc
@@ -146,6 +146,8 @@ class SingleThreadedProxyResolver::Job
   // Returns true if Cancel() has been called.
   bool was_cancelled() const { return callback_ == NULL; }
 
+  LoadLog* load_log() { return load_log_; }
+
  private:
   friend class base::RefCountedThreadSafe<SingleThreadedProxyResolver::Job>;
 
@@ -235,8 +237,19 @@ int SingleThreadedProxyResolver::GetProxyForURL(const GURL& url,
   DCHECK(callback);
 
   scoped_refptr<Job> job = new Job(this, url, results, callback, load_log);
-  pending_jobs_.push_back(job);
-  ProcessPendingJobs();  // Jobs can never finish synchronously.
+  bool is_first_job = pending_jobs_.empty();
+  pending_jobs_.push_back(job);  // Jobs can never finish synchronously.
+
+  if (is_first_job) {
+    // If there is nothing already running, start the job now.
+    EnsureThreadStarted();
+    job->Start();
+  } else {
+    // Otherwise the job will get started eventually by ProcessPendingJobs().
+    LoadLog::BeginEvent(
+        job->load_log(),
+        LoadLog::TYPE_WAITING_FOR_SINGLE_PROXY_RESOLVER_THREAD);
+  }
 
   // Completion will be notified through |callback|, unless the caller cancels
   // the request using |request|.
@@ -316,6 +329,10 @@ void SingleThreadedProxyResolver::ProcessPendingJobs() {
   if (job->is_started())
     return;
 
+  LoadLog::EndEvent(
+      job->load_log(),
+      LoadLog::TYPE_WAITING_FOR_SINGLE_PROXY_RESOLVER_THREAD);
+
   EnsureThreadStarted();
   job->Start();
 }
diff --git a/net/proxy/single_threaded_proxy_resolver_unittest.cc b/net/proxy/single_threaded_proxy_resolver_unittest.cc
index 46c768e..dc24935 100644
--- a/net/proxy/single_threaded_proxy_resolver_unittest.cc
+++ b/net/proxy/single_threaded_proxy_resolver_unittest.cc
@@ -5,6 +5,7 @@
 #include "base/waitable_event.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/proxy_info.h"
@@ -218,6 +219,71 @@ TEST(SingleThreadedProxyResolverTest, Basic) {
   EXPECT_EQ(1, mock->purge_count());
 }
 
+// Tests that the LoadLog is updated to include the time the request was waiting
+// to be scheduled to a thread.
+TEST(SingleThreadedProxyResolverTest, UpdatesLoadLogWithThreadWait) {
+  BlockableProxyResolver* mock = new BlockableProxyResolver;
+  SingleThreadedProxyResolver resolver(mock);
+
+  int rv;
+
+  // Block the proxy resolver, so no request can complete.
+  mock->Block();
+
+  // Start request 0.
+  ProxyResolver::RequestHandle request0;
+  TestCompletionCallback callback0;
+  ProxyInfo results0;
+  scoped_refptr<LoadLog> log0(new LoadLog(LoadLog::kUnbounded));
+  rv = resolver.GetProxyForURL(
+      GURL("http://request0"), &results0, &callback0, &request0, log0);
+  EXPECT_EQ(ERR_IO_PENDING, rv);
+
+  // Start 2 more requests (request1 and request2).
+
+  TestCompletionCallback callback1;
+  ProxyInfo results1;
+  scoped_refptr<LoadLog> log1(new LoadLog(LoadLog::kUnbounded));
+  rv = resolver.GetProxyForURL(
+      GURL("http://request1"), &results1, &callback1, NULL, log1);
+  EXPECT_EQ(ERR_IO_PENDING, rv);
+
+  ProxyResolver::RequestHandle request2;
+  TestCompletionCallback callback2;
+  ProxyInfo results2;
+  scoped_refptr<LoadLog> log2(new LoadLog(LoadLog::kUnbounded));
+  rv = resolver.GetProxyForURL(
+      GURL("http://request2"), &results2, &callback2, &request2, log2);
+  EXPECT_EQ(ERR_IO_PENDING, rv);
+
+  // Unblock the worker thread so the requests can continue running.
+  mock->Unblock();
+
+  // Check that request 0 completed as expected.
+  // The LoadLog only has 1 entry (that came from the mock proxy resolver.)
+  EXPECT_EQ(0, callback0.WaitForResult());
+  EXPECT_EQ("PROXY request0:80", results0.ToPacString());
+  ASSERT_EQ(1u, log0->entries().size());
+
+  // Check that request 1 completed as expected.
+  EXPECT_EQ(1, callback1.WaitForResult());
+  EXPECT_EQ("PROXY request1:80", results1.ToPacString());
+  ASSERT_EQ(3u, log1->entries().size());
+  EXPECT_TRUE(LogContainsBeginEvent(
+      *log1, 0, LoadLog::TYPE_WAITING_FOR_SINGLE_PROXY_RESOLVER_THREAD));
+  EXPECT_TRUE(LogContainsEndEvent(
+      *log1, 1, LoadLog::TYPE_WAITING_FOR_SINGLE_PROXY_RESOLVER_THREAD));
+
+  // Check that request 2 completed as expected.
+  EXPECT_EQ(2, callback2.WaitForResult());
+  EXPECT_EQ("PROXY request2:80", results2.ToPacString());
+  ASSERT_EQ(3u, log2->entries().size());
+  EXPECT_TRUE(LogContainsBeginEvent(
+      *log2, 0, LoadLog::TYPE_WAITING_FOR_SINGLE_PROXY_RESOLVER_THREAD));
+  EXPECT_TRUE(LogContainsEndEvent(
+      *log2, 1, LoadLog::TYPE_WAITING_FOR_SINGLE_PROXY_RESOLVER_THREAD));
+}
+
 // Cancel a request which is in progress, and then cancel a request which
 // is pending.
 TEST(SingleThreadedProxyResolverTest, CancelRequest) {