Add instrumentation to ClientSocketPool, that writes to LoadLog.

BUG=http://crbug.com/14478

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

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

9 files changed, 377 insertions, 59 deletions

diff --git a/net/base/load_log.cc b/net/base/load_log.cc
index 120a58b..42b1b85f 100644
--- a/net/base/load_log.cc
+++ b/net/base/load_log.cc
@@ -19,7 +19,7 @@ const char* LoadLog::EventTypeToString(EventType event) {
   return NULL;
 }
 
-void LoadLog::Add(base::TimeTicks t, EventType event, EventPhase phase) {
+void LoadLog::Add(const Event& event) {
   // Minor optimization. TODO(eroman): use StackVector instead.
   if (events_.empty())
     events_.reserve(kMaxNumEntries / 2);
@@ -28,10 +28,14 @@ void LoadLog::Add(base::TimeTicks t, EventType event, EventPhase phase) {
   // final entry in the list is |TYPE_LOG_TRUNCATED|.
 
   if (events_.size() + 1 == kMaxNumEntries)
-    events_.push_back(Event(t, TYPE_LOG_TRUNCATED, PHASE_NONE));
+    events_.push_back(Event(event.time, TYPE_LOG_TRUNCATED, PHASE_NONE));
+  else if (events_.size() < kMaxNumEntries)
+    events_.push_back(event);
+}
 
-  if (events_.size() < kMaxNumEntries)
-    events_.push_back(Event(t, event, phase));
+void LoadLog::Append(const LoadLog* log) {
+  for (size_t i = 0; i < log->events().size(); ++i)
+    Add(log->events()[i]);
 }
 
 }  // namespace net
diff --git a/net/base/load_log.h b/net/base/load_log.h
index fcb7d6f..d1024cb 100644
--- a/net/base/load_log.h
+++ b/net/base/load_log.h
@@ -93,7 +93,14 @@ class LoadLog : public base::RefCounted<LoadLog> {
   // Returns a C-String symbolic name for |event|.
   static const char* EventTypeToString(EventType event);
 
-  void Add(base::TimeTicks t, EventType event, EventPhase phase);
+  void Add(const Event& event);
+
+  void Add(base::TimeTicks t, EventType event, EventPhase phase) {
+    Add(Event(t, event, phase));
+  }
+
+  // Copies all events from |log|, appending it to the end of |this|.
+  void Append(const LoadLog* log);
 
  private:
   EventList events_;
diff --git a/net/base/load_log_event_type_list.h b/net/base/load_log_event_type_list.h
index ba6b040..75b84b3 100644
--- a/net/base/load_log_event_type_list.h
+++ b/net/base/load_log_event_type_list.h
@@ -60,3 +60,31 @@ EVENT_TYPE(PROXY_SERVICE)
 // are found from ProxyService::init_proxy_resolver_log().
 EVENT_TYPE(PROXY_SERVICE_WAITING_FOR_INIT_PAC)
 
+// ------------------------------------------------------------------------
+// ClientSocketPoolBase::ConnectJob
+// ------------------------------------------------------------------------
+
+// The start/end of a ConnectJob.
+EVENT_TYPE(SOCKET_POOL_CONNECT_JOB)
+
+// Whether the connect job timed out.
+EVENT_TYPE(SOCKET_POOL_CONNECT_JOB_TIMED_OUT)
+
+// ------------------------------------------------------------------------
+// ClientSocketPoolBaseHelper
+// ------------------------------------------------------------------------
+
+// The start/end of a client socket pool request for a socket.
+EVENT_TYPE(SOCKET_POOL)
+
+// The start/end of when a request is sitting in the queue waiting for
+// a connect job to finish. (Only applies to late_binding).
+EVENT_TYPE(SOCKET_POOL_WAITING_IN_QUEUE)
+
+// The request stalled because there are too many sockets in the pool.
+EVENT_TYPE(SOCKET_POOL_STALLED_MAX_SOCKETS)
+
+// The request stalled because there are too many sockets in the group.
+EVENT_TYPE(SOCKET_POOL_STALLED_MAX_SOCKETS_PER_GROUP)
+
+
diff --git a/net/base/load_log_unittest.cc b/net/base/load_log_unittest.cc
index 9634dd9..18178af 100644
--- a/net/base/load_log_unittest.cc
+++ b/net/base/load_log_unittest.cc
@@ -93,6 +93,55 @@ TEST(LoadLogTest, Truncation) {
       LoadLog::TYPE_LOG_TRUNCATED, LoadLog::PHASE_NONE);
 }
 
+TEST(LoadLogTest, Append) {
+  scoped_refptr<LoadLog> log1(new LoadLog);
+  scoped_refptr<LoadLog> log2(new LoadLog);
+
+  log1->Add(MakeTime(0), LoadLog::TYPE_HOST_RESOLVER_IMPL,
+            LoadLog::PHASE_BEGIN);
+
+  log2->Add(MakeTime(3), LoadLog::TYPE_CANCELLED, LoadLog::PHASE_NONE);
+  log2->Add(MakeTime(9), LoadLog::TYPE_HOST_RESOLVER_IMPL, LoadLog::PHASE_END);
+
+  log1->Append(log2);
+
+  // Add something else to log2 (should NOT be reflected in log1).
+  log2->Add(MakeTime(19), LoadLog::TYPE_CANCELLED, LoadLog::PHASE_NONE);
+
+  EXPECT_EQ(3u, log1->events().size());
+
+  ExpectLogContains(log1, 0, MakeTime(0), LoadLog::TYPE_HOST_RESOLVER_IMPL,
+                    LoadLog::PHASE_BEGIN);
+
+  ExpectLogContains(log1, 1, MakeTime(3), LoadLog::TYPE_CANCELLED,
+                    LoadLog::PHASE_NONE);
+
+  ExpectLogContains(log1, 2, MakeTime(9), LoadLog::TYPE_HOST_RESOLVER_IMPL,
+                    LoadLog::PHASE_END);
+}
+
+TEST(LoadLogTest, AppendWithTruncation) {
+  // Append() should also respect the maximum number of entries bound.
+  // (This is basically the same test as LoadLogTest.Truncation).
+
+  // Create two load logs, which are 2/3 capcity.
+  scoped_refptr<LoadLog> log1(new LoadLog);
+  scoped_refptr<LoadLog> log2(new LoadLog);
+  for (size_t i = 0; i < 2 * LoadLog::kMaxNumEntries / 3; ++i) {
+    log1->Add(MakeTime(1), LoadLog::TYPE_CANCELLED, LoadLog::PHASE_NONE);
+    log2->Add(MakeTime(2), LoadLog::TYPE_CANCELLED, LoadLog::PHASE_NONE);
+  }
+
+  // Append log2 to log1.
+  log1->Append(log2);
+
+  EXPECT_EQ(LoadLog::kMaxNumEntries, log1->events().size());
+
+  // We terminated with a "truncation" event.
+  ExpectLogContains(log1, LoadLog::kMaxNumEntries - 1, MakeTime(2),
+                    LoadLog::TYPE_LOG_TRUNCATED, LoadLog::PHASE_NONE);
+}
+
 TEST(LoadLogTest, EventTypeToString) {
   EXPECT_STREQ("HOST_RESOLVER_IMPL",
                LoadLog::EventTypeToString(LoadLog::TYPE_HOST_RESOLVER_IMPL));
diff --git a/net/socket/client_socket_pool_base.cc b/net/socket/client_socket_pool_base.cc
index d966555..7ceaee5 100644
--- a/net/socket/client_socket_pool_base.cc
+++ b/net/socket/client_socket_pool_base.cc
@@ -8,6 +8,7 @@
 #include "base/message_loop.h"
 #include "base/stl_util-inl.h"
 #include "base/time.h"
+#include "net/base/load_log.h"
 #include "net/base/net_errors.h"
 #include "net/socket/client_socket_handle.h"
 
@@ -33,32 +34,62 @@ namespace net {
 ConnectJob::ConnectJob(const std::string& group_name,
                        const ClientSocketHandle* key_handle,
                        base::TimeDelta timeout_duration,
-                       Delegate* delegate)
+                       Delegate* delegate,
+                       LoadLog* load_log)
     : group_name_(group_name),
       key_handle_(key_handle),
       timeout_duration_(timeout_duration),
       delegate_(delegate),
-      load_state_(LOAD_STATE_IDLE) {
+      load_state_(LOAD_STATE_IDLE),
+      load_log_(load_log) {
   DCHECK(!group_name.empty());
   DCHECK(key_handle);
   DCHECK(delegate);
 }
 
-ConnectJob::~ConnectJob() {}
+ConnectJob::~ConnectJob() {
+  if (delegate_) {
+    // If the delegate was not NULLed, then NotifyDelegateOfCompletion has
+    // not been called yet (hence we are cancelling).
+    LoadLog::AddEvent(load_log_, LoadLog::TYPE_CANCELLED);
+    LoadLog::EndEvent(load_log_, LoadLog::TYPE_SOCKET_POOL_CONNECT_JOB);
+  }
+}
 
 int ConnectJob::Connect() {
   if (timeout_duration_ != base::TimeDelta())
     timer_.Start(timeout_duration_, this, &ConnectJob::OnTimeout);
-  return ConnectInternal();
+
+  LoadLog::BeginEvent(load_log_, LoadLog::TYPE_SOCKET_POOL_CONNECT_JOB);
+
+  int rv = ConnectInternal();
+
+  if (rv != ERR_IO_PENDING) {
+    delegate_ = NULL;
+    LoadLog::EndEvent(load_log_, LoadLog::TYPE_SOCKET_POOL_CONNECT_JOB);
+  }
+
+  return rv;
 }
 
-void ConnectJob::OnTimeout() {
-  // Make sure the socket is NULL before calling into |delegate|.
-  set_socket(NULL);
+void ConnectJob::NotifyDelegateOfCompletion(int rv) {
   // The delegate will delete |this|.
   Delegate *delegate = delegate_;
   delegate_ = NULL;
-  delegate->OnConnectJobComplete(ERR_TIMED_OUT, this);
+
+  LoadLog::EndEvent(load_log_, LoadLog::TYPE_SOCKET_POOL_CONNECT_JOB);
+
+  delegate->OnConnectJobComplete(rv, this);
+}
+
+void ConnectJob::OnTimeout() {
+  // Make sure the socket is NULL before calling into |delegate|.
+  set_socket(NULL);
+
+  LoadLog::AddEvent(load_log_,
+      LoadLog::TYPE_SOCKET_POOL_CONNECT_JOB_TIMED_OUT);
+
+  NotifyDelegateOfCompletion(ERR_TIMED_OUT);
 }
 
 namespace internal {
@@ -98,12 +129,28 @@ ClientSocketPoolBaseHelper::~ClientSocketPoolBaseHelper() {
 // static
 void ClientSocketPoolBaseHelper::InsertRequestIntoQueue(
     const Request* r, RequestQueue* pending_requests) {
+  LoadLog::BeginEvent(r->load_log(),
+      LoadLog::TYPE_SOCKET_POOL_WAITING_IN_QUEUE);
+
   RequestQueue::iterator it = pending_requests->begin();
   while (it != pending_requests->end() && r->priority() <= (*it)->priority())
     ++it;
   pending_requests->insert(it, r);
 }
 
+// static
+const ClientSocketPoolBaseHelper::Request*
+ClientSocketPoolBaseHelper::RemoveRequestFromQueue(
+    RequestQueue::iterator it, RequestQueue* pending_requests) {
+  const Request* req = *it;
+
+  LoadLog::EndEvent(req->load_log(),
+      LoadLog::TYPE_SOCKET_POOL_WAITING_IN_QUEUE);
+
+  pending_requests->erase(it);
+  return req;
+}
+
 int ClientSocketPoolBaseHelper::RequestSocket(
     const std::string& group_name,
     const Request* request) {
@@ -121,6 +168,12 @@ int ClientSocketPoolBaseHelper::RequestSocket(
       // We could check if we really have a stalled group here, but it requires
       // a scan of all groups, so just flip a flag here, and do the check later.
       may_have_stalled_group_ = true;
+
+      LoadLog::AddEvent(request->load_log(),
+          LoadLog::TYPE_SOCKET_POOL_STALLED_MAX_SOCKETS);
+    } else {
+      LoadLog::AddEvent(request->load_log(),
+          LoadLog::TYPE_SOCKET_POOL_STALLED_MAX_SOCKETS_PER_GROUP);
     }
     InsertRequestIntoQueue(request, &group.pending_requests);
     return ERR_IO_PENDING;
@@ -143,10 +196,20 @@ int ClientSocketPoolBaseHelper::RequestSocket(
 
   // We couldn't find a socket to reuse, so allocate and connect a new one.
 
+  // If we aren't using late binding, the job lines up with a request so
+  // just write directly into the request's LoadLog.
+  scoped_refptr<LoadLog> job_load_log = g_late_binding ?
+      new LoadLog : request->load_log();
+
   scoped_ptr<ConnectJob> connect_job(
-      connect_job_factory_->NewConnectJob(group_name, *request, this));
+      connect_job_factory_->NewConnectJob(group_name, *request, this,
+                                         job_load_log));
 
   int rv = connect_job->Connect();
+
+  if (g_late_binding && rv != ERR_IO_PENDING && request->load_log())
+    request->load_log()->Append(job_load_log);
+
   if (rv == OK) {
     HandOutSocket(connect_job->ReleaseSocket(), false /* not reused */,
                   handle, base::TimeDelta(), &group);
@@ -180,8 +243,10 @@ void ClientSocketPoolBaseHelper::CancelRequest(
   RequestQueue::iterator it = group.pending_requests.begin();
   for (; it != group.pending_requests.end(); ++it) {
     if ((*it)->handle() == handle) {
-      delete *it;
-      group.pending_requests.erase(it);
+      const Request* req = RemoveRequestFromQueue(it, &group.pending_requests);
+      LoadLog::AddEvent(req->load_log(), LoadLog::TYPE_CANCELLED);
+      LoadLog::EndEvent(req->load_log(), LoadLog::TYPE_SOCKET_POOL);
+      delete req;
       if (g_late_binding &&
           group.jobs.size() > group.pending_requests.size() + 1) {
         // TODO(willchan): Cancel the job in the earliest LoadState.
@@ -198,6 +263,9 @@ void ClientSocketPoolBaseHelper::CancelRequest(
 
     RequestMap::iterator map_it = group.connecting_requests.find(handle);
     if (map_it != group.connecting_requests.end()) {
+      scoped_refptr<LoadLog> log(map_it->second->load_log());
+      LoadLog::AddEvent(log, LoadLog::TYPE_CANCELLED);
+      LoadLog::EndEvent(log, LoadLog::TYPE_SOCKET_POOL);
       RemoveConnectJob(handle, NULL, &group);
       OnAvailableSocketSlot(group_name, &group);
     }
@@ -389,13 +457,23 @@ void ClientSocketPoolBaseHelper::OnConnectJobComplete(
   scoped_ptr<ClientSocket> socket(job->ReleaseSocket());
 
   if (g_late_binding) {
+    scoped_refptr<LoadLog> job_load_log(job->load_log());
     RemoveConnectJob(key_handle, job, &group);
 
+    scoped_ptr<const Request> r;
+    if (!group.pending_requests.empty()) {
+      r.reset(RemoveRequestFromQueue(
+          group.pending_requests.begin(), &group.pending_requests));
+
+      if (r->load_log())
+        r->load_log()->Append(job_load_log);
+
+      LoadLog::EndEvent(r->load_log(), LoadLog::TYPE_SOCKET_POOL);
+    }
+
     if (result == OK) {
       DCHECK(socket.get());
-      if (!group.pending_requests.empty()) {
-        scoped_ptr<const Request> r(group.pending_requests.front());
-        group.pending_requests.pop_front();
+      if (r.get()) {
         HandOutSocket(
             socket.release(), false /* unused socket */, r->handle(),
             base::TimeDelta(), &group);
@@ -406,11 +484,8 @@ void ClientSocketPoolBaseHelper::OnConnectJobComplete(
       }
     } else {
       DCHECK(!socket.get());
-      if (!group.pending_requests.empty()) {
-        scoped_ptr<const Request> r(group.pending_requests.front());
-        group.pending_requests.pop_front();
+      if (r.get())
         r->callback()->Run(result);
-      }
       MaybeOnAvailableSocketSlot(group_name);
     }
 
@@ -424,6 +499,8 @@ void ClientSocketPoolBaseHelper::OnConnectJobComplete(
   ClientSocketHandle* const handle = request->handle();
   CompletionCallback* const callback = request->callback();
 
+  LoadLog::EndEvent(request->load_log(), LoadLog::TYPE_SOCKET_POOL);
+
   RemoveConnectJob(key_handle, job, &group);
 
   if (result != OK) {
@@ -503,12 +580,13 @@ void ClientSocketPoolBaseHelper::OnAvailableSocketSlot(
 
 void ClientSocketPoolBaseHelper::ProcessPendingRequest(
     const std::string& group_name, Group* group) {
-  scoped_ptr<const Request> r(group->pending_requests.front());
-  group->pending_requests.pop_front();
+  scoped_ptr<const Request> r(RemoveRequestFromQueue(
+        group->pending_requests.begin(), &group->pending_requests));
 
   int rv = RequestSocket(group_name, r.get());
 
   if (rv != ERR_IO_PENDING) {
+    LoadLog::EndEvent(r->load_log(), LoadLog::TYPE_SOCKET_POOL);
     r->callback()->Run(rv);
     if (rv != OK) {
       // |group| may be invalid after the callback, we need to search
diff --git a/net/socket/client_socket_pool_base.h b/net/socket/client_socket_pool_base.h
index bdcee36d..e6368ca 100644
--- a/net/socket/client_socket_pool_base.h
+++ b/net/socket/client_socket_pool_base.h
@@ -64,7 +64,8 @@ class ConnectJob {
   ConnectJob(const std::string& group_name,
              const ClientSocketHandle* key_handle,
              base::TimeDelta timeout_duration,
-             Delegate* delegate);
+             Delegate* delegate,
+             LoadLog* load_log);
   virtual ~ConnectJob();
 
   // Accessors
@@ -84,11 +85,13 @@ class ConnectJob {
   // if it succeeded.
   int Connect();
 
+  LoadLog* load_log() { return load_log_; }
+
  protected:
   void set_load_state(LoadState load_state) { load_state_ = load_state; }
   void set_socket(ClientSocket* socket) { socket_.reset(socket); }
   ClientSocket* socket() { return socket_.get(); }
-  Delegate* delegate() { return delegate_; }
+  void NotifyDelegateOfCompletion(int rv);
 
  private:
   virtual int ConnectInternal() = 0;
@@ -105,6 +108,7 @@ class ConnectJob {
   Delegate* delegate_;
   LoadState load_state_;
   scoped_ptr<ClientSocket> socket_;
+  scoped_refptr<LoadLog> load_log_;
 
   DISALLOW_COPY_AND_ASSIGN(ConnectJob);
 };
@@ -126,7 +130,8 @@ class ClientSocketPoolBaseHelper
             CompletionCallback* callback,
             int priority,
             LoadLog* load_log)
-        : handle_(handle), callback_(callback), priority_(priority) {}
+        : handle_(handle), callback_(callback), priority_(priority),
+          load_log_(load_log) {}
 
     virtual ~Request() {}
 
@@ -152,7 +157,8 @@ class ClientSocketPoolBaseHelper
     virtual ConnectJob* NewConnectJob(
         const std::string& group_name,
         const Request& request,
-        ConnectJob::Delegate* delegate) const = 0;
+        ConnectJob::Delegate* delegate,
+        LoadLog* load_log) const = 0;
 
    private:
     DISALLOW_COPY_AND_ASSIGN(ConnectJobFactory);
@@ -265,6 +271,8 @@ class ClientSocketPoolBaseHelper
 
   static void InsertRequestIntoQueue(const Request* r,
                                      RequestQueue* pending_requests);
+  static const Request* RemoveRequestFromQueue(RequestQueue::iterator it,
+                                               RequestQueue* pending_requests);
 
   // Closes all idle sockets if |force| is true.  Else, only closes idle
   // sockets that timed out or can't be reused.
@@ -404,7 +412,8 @@ class ClientSocketPoolBase {
     virtual ConnectJob* NewConnectJob(
         const std::string& group_name,
         const Request& request,
-        ConnectJob::Delegate* delegate) const = 0;
+        ConnectJob::Delegate* delegate,
+        LoadLog* load_log) const = 0;
 
    private:
     DISALLOW_COPY_AND_ASSIGN(ConnectJobFactory);
@@ -432,9 +441,12 @@ class ClientSocketPoolBase {
                     LoadLog* load_log) {
     scoped_ptr<Request> request(
         new Request(handle, callback, priority, params, load_log));
+    LoadLog::BeginEvent(load_log, LoadLog::TYPE_SOCKET_POOL);
     int rv = helper_->RequestSocket(group_name, request.get());
     if (rv == ERR_IO_PENDING)
       request.release();
+    else
+      LoadLog::EndEvent(load_log, LoadLog::TYPE_SOCKET_POOL);
     return rv;
   }
 
@@ -493,10 +505,11 @@ class ClientSocketPoolBase {
     virtual ConnectJob* NewConnectJob(
         const std::string& group_name,
         const internal::ClientSocketPoolBaseHelper::Request& request,
-        ConnectJob::Delegate* delegate) const {
+        ConnectJob::Delegate* delegate,
+        LoadLog* load_log) const {
       const Request* casted_request = static_cast<const Request*>(&request);
       return connect_job_factory_->NewConnectJob(
-          group_name, *casted_request, delegate);
+          group_name, *casted_request, delegate, load_log);
     }
 
     const scoped_ptr<ConnectJobFactory> connect_job_factory_;
diff --git a/net/socket/client_socket_pool_base_unittest.cc b/net/socket/client_socket_pool_base_unittest.cc
index 93673c62..fff6869 100644
--- a/net/socket/client_socket_pool_base_unittest.cc
+++ b/net/socket/client_socket_pool_base_unittest.cc
@@ -8,6 +8,8 @@
 #include "base/message_loop.h"
 #include "base/platform_thread.h"
 #include "base/scoped_vector.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/socket/client_socket.h"
@@ -110,8 +112,10 @@ class TestConnectJob : public ConnectJob {
                  const TestClientSocketPoolBase::Request& request,
                  base::TimeDelta timeout_duration,
                  ConnectJob::Delegate* delegate,
-                 MockClientSocketFactory* client_socket_factory)
-      : ConnectJob(group_name, request.handle(), timeout_duration, delegate),
+                 MockClientSocketFactory* client_socket_factory,
+                 LoadLog* load_log)
+      : ConnectJob(group_name, request.handle(), timeout_duration,
+                   delegate, load_log),
         job_type_(job_type),
         client_socket_factory_(client_socket_factory),
         method_factory_(ALLOW_THIS_IN_INITIALIZER_LIST(this)) {}
@@ -177,7 +181,7 @@ class TestConnectJob : public ConnectJob {
     }
 
     if (was_async)
-      delegate()->OnConnectJobComplete(result, this);
+      NotifyDelegateOfCompletion(result);
     return result;
   }
 
@@ -222,13 +226,15 @@ class TestConnectJobFactory
   virtual ConnectJob* NewConnectJob(
       const std::string& group_name,
       const TestClientSocketPoolBase::Request& request,
-      ConnectJob::Delegate* delegate) const {
+      ConnectJob::Delegate* delegate,
+      LoadLog* load_log) const {
     return new TestConnectJob(job_type_,
                               group_name,
                               request,
                               timeout_duration_,
                               delegate,
-                              client_socket_factory_);
+                              client_socket_factory_,
+                              load_log);
   }
 
  private:
@@ -408,13 +414,15 @@ TEST_F(ClientSocketPoolBaseTest, ConnectJob_NoTimeoutOnSynchronousCompletion) {
                          request,
                          base::TimeDelta::FromMicroseconds(1),
                          &delegate,
-                         &client_socket_factory_));
+                         &client_socket_factory_,
+                         NULL));
   EXPECT_EQ(OK, job->Connect());
 }
 
 TEST_F(ClientSocketPoolBaseTest, ConnectJob_TimedOut) {
   TestConnectJobDelegate delegate;
   ClientSocketHandle ignored;
+  scoped_refptr<LoadLog> log(new LoadLog);
   TestClientSocketPoolBase::Request request(
       &ignored, NULL, kDefaultPriority, NULL, NULL);
   // Deleted by TestConnectJobDelegate.
@@ -424,10 +432,19 @@ TEST_F(ClientSocketPoolBaseTest, ConnectJob_TimedOut) {
                          request,
                          base::TimeDelta::FromMicroseconds(1),
                          &delegate,
-                         &client_socket_factory_);
+                         &client_socket_factory_,
+                         log);
   ASSERT_EQ(ERR_IO_PENDING, job->Connect());
   PlatformThread::Sleep(1);
   EXPECT_EQ(ERR_TIMED_OUT, delegate.WaitForResult());
+
+  EXPECT_EQ(3u, log->events().size());
+  ExpectLogContains(log, 0, LoadLog::TYPE_SOCKET_POOL_CONNECT_JOB,
+                    LoadLog::PHASE_BEGIN);
+  ExpectLogContains(log, 1, LoadLog::TYPE_SOCKET_POOL_CONNECT_JOB_TIMED_OUT,
+                    LoadLog::PHASE_NONE);
+  ExpectLogContains(log, 2, LoadLog::TYPE_SOCKET_POOL_CONNECT_JOB,
+                    LoadLog::PHASE_END);
 }
 
 TEST_F(ClientSocketPoolBaseTest, BasicSynchronous) {
@@ -435,52 +452,90 @@ TEST_F(ClientSocketPoolBaseTest, BasicSynchronous) {
 
   TestCompletionCallback callback;
   ClientSocketHandle handle;
+  scoped_refptr<LoadLog> log(new LoadLog);
   EXPECT_EQ(OK, InitHandle(&handle, "a", kDefaultPriority,
-                           &callback, pool_.get(), NULL));
+                           &callback, pool_.get(), log));
   EXPECT_TRUE(handle.is_initialized());
   EXPECT_TRUE(handle.socket());
   handle.Reset();
+
+  EXPECT_EQ(4u, log->events().size());
+  ExpectLogContains(log, 0, LoadLog::TYPE_SOCKET_POOL, LoadLog::PHASE_BEGIN);
+  ExpectLogContains(log, 1, LoadLog::TYPE_SOCKET_POOL_CONNECT_JOB,
+                    LoadLog::PHASE_BEGIN);
+  ExpectLogContains(log, 2, LoadLog::TYPE_SOCKET_POOL_CONNECT_JOB,
+                    LoadLog::PHASE_END);
+  ExpectLogContains(log, 3, LoadLog::TYPE_SOCKET_POOL, LoadLog::PHASE_END);
 }
 
 TEST_F(ClientSocketPoolBaseTest, BasicAsynchronous) {
   CreatePool(kDefaultMaxSockets, kDefaultMaxSocketsPerGroup);
 
   connect_job_factory_->set_job_type(TestConnectJob::kMockPendingJob);
+  scoped_refptr<LoadLog> log(new LoadLog);
   TestSocketRequest req(&request_order_, &completion_count_);
-  int rv = InitHandle(req.handle(), "a", 0, &req, pool_.get(), NULL);
+  int rv = InitHandle(req.handle(), "a", 0, &req, pool_.get(), log);
   EXPECT_EQ(ERR_IO_PENDING, rv);
   EXPECT_EQ(LOAD_STATE_CONNECTING, pool_->GetLoadState("a", req.handle()));
   EXPECT_EQ(OK, req.WaitForResult());
   EXPECT_TRUE(req.handle()->is_initialized());
   EXPECT_TRUE(req.handle()->socket());
   req.handle()->Reset();
+
+  EXPECT_EQ(4u, log->events().size());
+  ExpectLogContains(log, 0, LoadLog::TYPE_SOCKET_POOL, LoadLog::PHASE_BEGIN);
+  ExpectLogContains(log, 1, LoadLog::TYPE_SOCKET_POOL_CONNECT_JOB,
+                    LoadLog::PHASE_BEGIN);
+  ExpectLogContains(log, 2, LoadLog::TYPE_SOCKET_POOL_CONNECT_JOB,
+                    LoadLog::PHASE_END);
+  ExpectLogContains(log, 3, LoadLog::TYPE_SOCKET_POOL, LoadLog::PHASE_END);
 }
 
 TEST_F(ClientSocketPoolBaseTest, InitConnectionFailure) {
   CreatePool(kDefaultMaxSockets, kDefaultMaxSocketsPerGroup);
 
   connect_job_factory_->set_job_type(TestConnectJob::kMockFailingJob);
+  scoped_refptr<LoadLog> log(new LoadLog);
   TestSocketRequest req(&request_order_, &completion_count_);
   EXPECT_EQ(ERR_CONNECTION_FAILED,
             InitHandle(req.handle(), "a", kDefaultPriority, &req,
-                       pool_.get(), NULL));
+                       pool_.get(), log));
+
+  EXPECT_EQ(4u, log->events().size());
+  ExpectLogContains(log, 0, LoadLog::TYPE_SOCKET_POOL, LoadLog::PHASE_BEGIN);
+  ExpectLogContains(log, 1, LoadLog::TYPE_SOCKET_POOL_CONNECT_JOB,
+                    LoadLog::PHASE_BEGIN);
+  ExpectLogContains(log, 2, LoadLog::TYPE_SOCKET_POOL_CONNECT_JOB,
+                    LoadLog::PHASE_END);
+  ExpectLogContains(log, 3, LoadLog::TYPE_SOCKET_POOL, LoadLog::PHASE_END);
 }
 
 TEST_F(ClientSocketPoolBaseTest, InitConnectionAsynchronousFailure) {
   CreatePool(kDefaultMaxSockets, kDefaultMaxSocketsPerGroup);
 
   connect_job_factory_->set_job_type(TestConnectJob::kMockPendingFailingJob);
+  scoped_refptr<LoadLog> log(new LoadLog);
   TestSocketRequest req(&request_order_, &completion_count_);
   EXPECT_EQ(ERR_IO_PENDING,
             InitHandle(req.handle(), "a", kDefaultPriority, &req,
-                       pool_.get(), NULL));
+                       pool_.get(), log));
   EXPECT_EQ(LOAD_STATE_CONNECTING, pool_->GetLoadState("a", req.handle()));
   EXPECT_EQ(ERR_CONNECTION_FAILED, req.WaitForResult());
+
+  EXPECT_EQ(4u, log->events().size());
+  ExpectLogContains(log, 0, LoadLog::TYPE_SOCKET_POOL, LoadLog::PHASE_BEGIN);
+  ExpectLogContains(log, 1, LoadLog::TYPE_SOCKET_POOL_CONNECT_JOB,
+                    LoadLog::PHASE_BEGIN);
+  ExpectLogContains(log, 2, LoadLog::TYPE_SOCKET_POOL_CONNECT_JOB,
+                    LoadLog::PHASE_END);
+  ExpectLogContains(log, 3, LoadLog::TYPE_SOCKET_POOL, LoadLog::PHASE_END);
 }
 
 TEST_F(ClientSocketPoolBaseTest, TotalLimit) {
   CreatePool(kDefaultMaxSockets, kDefaultMaxSocketsPerGroup);
 
+  // TODO(eroman): Check that the LoadLog contains this event.
+
   EXPECT_EQ(OK, StartRequest("a", kDefaultPriority));
   EXPECT_EQ(OK, StartRequest("b", kDefaultPriority));
   EXPECT_EQ(OK, StartRequest("c", kDefaultPriority));
@@ -515,6 +570,8 @@ TEST_F(ClientSocketPoolBaseTest, TotalLimit) {
 TEST_F(ClientSocketPoolBaseTest, TotalLimitReachedNewGroup) {
   CreatePool(kDefaultMaxSockets, kDefaultMaxSocketsPerGroup);
 
+  // TODO(eroman): Check that the LoadLog contains this event.
+
   // Reach all limits: max total sockets, and max sockets per group.
   EXPECT_EQ(OK, StartRequest("a", kDefaultPriority));
   EXPECT_EQ(OK, StartRequest("a", kDefaultPriority));
@@ -1144,7 +1201,8 @@ TEST_F(ClientSocketPoolBaseTest_LateBinding,
                          request,
                          base::TimeDelta::FromMicroseconds(1),
                          &delegate,
-                         &client_socket_factory_));
+                         &client_socket_factory_,
+                         NULL));
   EXPECT_EQ(OK, job->Connect());
 }
 
@@ -1159,7 +1217,8 @@ TEST_F(ClientSocketPoolBaseTest_LateBinding, ConnectJob_TimedOut) {
                          request,
                          base::TimeDelta::FromMicroseconds(1),
                          &delegate,
-                         &client_socket_factory_);
+                         &client_socket_factory_,
+                         NULL);
   ASSERT_EQ(ERR_IO_PENDING, job->Connect());
   PlatformThread::Sleep(1);
   EXPECT_EQ(ERR_TIMED_OUT, delegate.WaitForResult());
@@ -1170,11 +1229,20 @@ TEST_F(ClientSocketPoolBaseTest_LateBinding, BasicSynchronous) {
 
   TestCompletionCallback callback;
   ClientSocketHandle handle;
+  scoped_refptr<LoadLog> log(new LoadLog);
   EXPECT_EQ(OK, InitHandle(&handle, "a", kDefaultPriority, &callback,
-                           pool_.get(), NULL));
+                           pool_.get(), log));
   EXPECT_TRUE(handle.is_initialized());
   EXPECT_TRUE(handle.socket());
   handle.Reset();
+
+  EXPECT_EQ(4u, log->events().size());
+  ExpectLogContains(log, 0, LoadLog::TYPE_SOCKET_POOL, LoadLog::PHASE_BEGIN);
+  ExpectLogContains(log, 1, LoadLog::TYPE_SOCKET_POOL_CONNECT_JOB,
+                    LoadLog::PHASE_BEGIN);
+  ExpectLogContains(log, 2, LoadLog::TYPE_SOCKET_POOL_CONNECT_JOB,
+                    LoadLog::PHASE_END);
+  ExpectLogContains(log, 3, LoadLog::TYPE_SOCKET_POOL, LoadLog::PHASE_END);
 }
 
 TEST_F(ClientSocketPoolBaseTest_LateBinding, BasicAsynchronous) {
@@ -1182,13 +1250,26 @@ TEST_F(ClientSocketPoolBaseTest_LateBinding, BasicAsynchronous) {
 
   connect_job_factory_->set_job_type(TestConnectJob::kMockPendingJob);
   TestSocketRequest req(&request_order_, &completion_count_);
-  int rv = InitHandle(req.handle(), "a", 0, &req, pool_.get(), NULL);
+  scoped_refptr<LoadLog> log(new LoadLog);
+  int rv = InitHandle(req.handle(), "a", 0, &req, pool_.get(), log);
   EXPECT_EQ(ERR_IO_PENDING, rv);
   EXPECT_EQ(LOAD_STATE_CONNECTING, pool_->GetLoadState("a", req.handle()));
   EXPECT_EQ(OK, req.WaitForResult());
   EXPECT_TRUE(req.handle()->is_initialized());
   EXPECT_TRUE(req.handle()->socket());
   req.handle()->Reset();
+
+  EXPECT_EQ(6u, log->events().size());
+  ExpectLogContains(log, 0, LoadLog::TYPE_SOCKET_POOL, LoadLog::PHASE_BEGIN);
+  ExpectLogContains(log, 1, LoadLog::TYPE_SOCKET_POOL_WAITING_IN_QUEUE,
+                    LoadLog::PHASE_BEGIN);
+  ExpectLogContains(log, 2, LoadLog::TYPE_SOCKET_POOL_WAITING_IN_QUEUE,
+                    LoadLog::PHASE_END);
+  ExpectLogContains(log, 3, LoadLog::TYPE_SOCKET_POOL_CONNECT_JOB,
+                    LoadLog::PHASE_BEGIN);
+  ExpectLogContains(log, 4, LoadLog::TYPE_SOCKET_POOL_CONNECT_JOB,
+                    LoadLog::PHASE_END);
+  ExpectLogContains(log, 5, LoadLog::TYPE_SOCKET_POOL, LoadLog::PHASE_END);
 }
 
 TEST_F(ClientSocketPoolBaseTest_LateBinding, InitConnectionFailure) {
@@ -1196,9 +1277,18 @@ TEST_F(ClientSocketPoolBaseTest_LateBinding, InitConnectionFailure) {
 
   connect_job_factory_->set_job_type(TestConnectJob::kMockFailingJob);
   TestSocketRequest req(&request_order_, &completion_count_);
+  scoped_refptr<LoadLog> log(new LoadLog);
   EXPECT_EQ(ERR_CONNECTION_FAILED,
             InitHandle(req.handle(), "a", kDefaultPriority, &req,
-                       pool_.get(), NULL));
+                       pool_.get(), log));
+
+  EXPECT_EQ(4u, log->events().size());
+  ExpectLogContains(log, 0, LoadLog::TYPE_SOCKET_POOL, LoadLog::PHASE_BEGIN);
+  ExpectLogContains(log, 1, LoadLog::TYPE_SOCKET_POOL_CONNECT_JOB,
+                    LoadLog::PHASE_BEGIN);
+  ExpectLogContains(log, 2, LoadLog::TYPE_SOCKET_POOL_CONNECT_JOB,
+                    LoadLog::PHASE_END);
+  ExpectLogContains(log, 3, LoadLog::TYPE_SOCKET_POOL, LoadLog::PHASE_END);
 }
 
 TEST_F(ClientSocketPoolBaseTest_LateBinding,
@@ -1207,11 +1297,24 @@ TEST_F(ClientSocketPoolBaseTest_LateBinding,
 
   connect_job_factory_->set_job_type(TestConnectJob::kMockPendingFailingJob);
   TestSocketRequest req(&request_order_, &completion_count_);
+  scoped_refptr<LoadLog> log(new LoadLog);
   EXPECT_EQ(ERR_IO_PENDING,
             InitHandle(req.handle(), "a", kDefaultPriority, &req,
-                       pool_.get(), NULL));
+                       pool_.get(), log));
   EXPECT_EQ(LOAD_STATE_CONNECTING, pool_->GetLoadState("a", req.handle()));
   EXPECT_EQ(ERR_CONNECTION_FAILED, req.WaitForResult());
+
+  EXPECT_EQ(6u, log->events().size());
+  ExpectLogContains(log, 0, LoadLog::TYPE_SOCKET_POOL, LoadLog::PHASE_BEGIN);
+  ExpectLogContains(log, 1, LoadLog::TYPE_SOCKET_POOL_WAITING_IN_QUEUE,
+                    LoadLog::PHASE_BEGIN);
+  ExpectLogContains(log, 2, LoadLog::TYPE_SOCKET_POOL_WAITING_IN_QUEUE,
+                    LoadLog::PHASE_END);
+  ExpectLogContains(log, 3, LoadLog::TYPE_SOCKET_POOL_CONNECT_JOB,
+                    LoadLog::PHASE_BEGIN);
+  ExpectLogContains(log, 4, LoadLog::TYPE_SOCKET_POOL_CONNECT_JOB,
+                    LoadLog::PHASE_END);
+  ExpectLogContains(log, 5, LoadLog::TYPE_SOCKET_POOL, LoadLog::PHASE_END);
 }
 
 TEST_F(ClientSocketPoolBaseTest_LateBinding, PendingRequests) {
@@ -1285,17 +1388,48 @@ TEST_F(ClientSocketPoolBaseTest_LateBinding, TwoRequestsCancelOne) {
   TestSocketRequest req(&request_order_, &completion_count_);
   TestSocketRequest req2(&request_order_, &completion_count_);
 
+  scoped_refptr<LoadLog> log1(new LoadLog);
   EXPECT_EQ(ERR_IO_PENDING,
             InitHandle(req.handle(), "a", kDefaultPriority, &req,
-                       pool_.get(), NULL));
+                       pool_.get(), log1));
+  scoped_refptr<LoadLog> log2(new LoadLog);
   EXPECT_EQ(ERR_IO_PENDING,
             InitHandle(req2.handle(), "a", kDefaultPriority, &req2,
-                       pool_.get(), NULL));
+                       pool_.get(), log2));
 
   req.handle()->Reset();
 
+  EXPECT_EQ(5u, log1->events().size());
+  ExpectLogContains(log1, 0, LoadLog::TYPE_SOCKET_POOL, LoadLog::PHASE_BEGIN);
+  ExpectLogContains(log1, 1, LoadLog::TYPE_SOCKET_POOL_WAITING_IN_QUEUE,
+                    LoadLog::PHASE_BEGIN);
+  ExpectLogContains(log1, 2, LoadLog::TYPE_SOCKET_POOL_WAITING_IN_QUEUE,
+                    LoadLog::PHASE_END);
+  ExpectLogContains(log1, 3, LoadLog::TYPE_CANCELLED, LoadLog::PHASE_NONE);
+  ExpectLogContains(log1, 4, LoadLog::TYPE_SOCKET_POOL, LoadLog::PHASE_END);
+
+  // At this point, request 2 is just waiting for the connect job to finish.
+  EXPECT_EQ(2u, log2->events().size());
+  ExpectLogContains(log2, 0, LoadLog::TYPE_SOCKET_POOL, LoadLog::PHASE_BEGIN);
+  ExpectLogContains(log2, 1, LoadLog::TYPE_SOCKET_POOL_WAITING_IN_QUEUE,
+                    LoadLog::PHASE_BEGIN);
+
   EXPECT_EQ(OK, req2.WaitForResult());
   req2.handle()->Reset();
+
+  // Now request 2 has actually finished.
+  EXPECT_EQ(6u, log2->events().size());
+  ExpectLogContains(log2, 0, LoadLog::TYPE_SOCKET_POOL, LoadLog::PHASE_BEGIN);
+  ExpectLogContains(log2, 1, LoadLog::TYPE_SOCKET_POOL_WAITING_IN_QUEUE,
+                    LoadLog::PHASE_BEGIN);
+  ExpectLogContains(log1, 2, LoadLog::TYPE_SOCKET_POOL_WAITING_IN_QUEUE,
+                    LoadLog::PHASE_END);
+  ExpectLogContains(log2, 3, LoadLog::TYPE_SOCKET_POOL_CONNECT_JOB,
+                    LoadLog::PHASE_BEGIN);
+  ExpectLogContains(log2, 4, LoadLog::TYPE_SOCKET_POOL_CONNECT_JOB,
+                    LoadLog::PHASE_END);
+  ExpectLogContains(log2, 5, LoadLog::TYPE_SOCKET_POOL, LoadLog::PHASE_END);
+
 }
 
 TEST_F(ClientSocketPoolBaseTest_LateBinding, ConnectCancelConnect) {
diff --git a/net/socket/tcp_client_socket_pool.cc b/net/socket/tcp_client_socket_pool.cc
index 2a23e55..77a5fad 100644
--- a/net/socket/tcp_client_socket_pool.cc
+++ b/net/socket/tcp_client_socket_pool.cc
@@ -29,8 +29,9 @@ TCPConnectJob::TCPConnectJob(
     base::TimeDelta timeout_duration,
     ClientSocketFactory* client_socket_factory,
     HostResolver* host_resolver,
-    Delegate* delegate)
-    : ConnectJob(group_name, handle, timeout_duration, delegate),
+    Delegate* delegate,
+    LoadLog* load_log)
+    : ConnectJob(group_name, handle, timeout_duration, delegate, load_log),
       resolve_info_(resolve_info),
       client_socket_factory_(client_socket_factory),
       ALLOW_THIS_IN_INITIALIZER_LIST(
@@ -51,7 +52,7 @@ int TCPConnectJob::ConnectInternal() {
 void TCPConnectJob::OnIOComplete(int result) {
   int rv = DoLoop(result);
   if (rv != ERR_IO_PENDING)
-    delegate()->OnConnectJobComplete(rv, this);  // Deletes |this|
+    NotifyDelegateOfCompletion(rv);  // Deletes |this|
 }
 
 int TCPConnectJob::DoLoop(int result) {
@@ -89,7 +90,7 @@ int TCPConnectJob::DoLoop(int result) {
 int TCPConnectJob::DoResolveHost() {
   set_load_state(LOAD_STATE_RESOLVING_HOST);
   next_state_ = kStateResolveHostComplete;
-  return resolver_.Resolve(resolve_info_, &addresses_, &callback_, NULL);
+  return resolver_.Resolve(resolve_info_, &addresses_, &callback_, load_log());
 }
 
 int TCPConnectJob::DoResolveHostComplete(int result) {
@@ -104,6 +105,7 @@ int TCPConnectJob::DoTCPConnect() {
   set_load_state(LOAD_STATE_CONNECTING);
   set_socket(client_socket_factory_->CreateTCPClientSocket(addresses_));
   connect_start_time_ = base::TimeTicks::Now();
+  // TODO(eroman): Socket::Connect() should take a LoadLog.
   return socket()->Connect(&callback_);
 }
 
@@ -130,11 +132,12 @@ int TCPConnectJob::DoTCPConnectComplete(int result) {
 ConnectJob* TCPClientSocketPool::TCPConnectJobFactory::NewConnectJob(
     const std::string& group_name,
     const PoolBase::Request& request,
-    ConnectJob::Delegate* delegate) const {
+    ConnectJob::Delegate* delegate,
+    LoadLog* load_log) const {
   return new TCPConnectJob(
       group_name, request.params(), request.handle(),
       base::TimeDelta::FromSeconds(kTCPConnectJobTimeoutInSeconds),
-      client_socket_factory_, host_resolver_, delegate);
+      client_socket_factory_, host_resolver_, delegate, load_log);
 }
 
 TCPClientSocketPool::TCPClientSocketPool(
diff --git a/net/socket/tcp_client_socket_pool.h b/net/socket/tcp_client_socket_pool.h
index 1437225..03d9178 100644
--- a/net/socket/tcp_client_socket_pool.h
+++ b/net/socket/tcp_client_socket_pool.h
@@ -30,7 +30,8 @@ class TCPConnectJob : public ConnectJob {
                 base::TimeDelta timeout_duration,
                 ClientSocketFactory* client_socket_factory,
                 HostResolver* host_resolver,
-                Delegate* delegate);
+                Delegate* delegate,
+                LoadLog* load_log);
   virtual ~TCPConnectJob();
 
   // ConnectJob methods.
@@ -126,7 +127,8 @@ class TCPClientSocketPool : public ClientSocketPool {
     virtual ConnectJob* NewConnectJob(
         const std::string& group_name,
         const PoolBase::Request& request,
-        ConnectJob::Delegate* delegate) const;
+        ConnectJob::Delegate* delegate,
+        LoadLog* load_log) const;
 
    private:
     ClientSocketFactory* const client_socket_factory_;