LoadTiming implementation in net, part 1.

net/socket/client_socket_pool_base.cc

 // Copyright (c) 2012 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 "net/socket/client_socket_pool_base.h"
 
 #include <math.h>
 #include "base/compiler_specific.h"
 #include "base/format_macros.h"
 #include "base/logging.h"
@@ skipping 107 matching lines @@
   LogConnectCompletion(rv);
   delegate->OnConnectJobComplete(rv, this);
 }
 
 void ConnectJob::ResetTimer(base::TimeDelta remaining_time) {
   timer_.Stop();
   timer_.Start(FROM_HERE, remaining_time, this, &ConnectJob::OnTimeout);
 }
 
 void ConnectJob::LogConnectStart() {
+  connect_timing_.connect_start = base::TimeTicks::Now();
   net_log().BeginEvent(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_CONNECT,
                        NetLog::StringCallback("group_name", &group_name_));
 }
 
 void ConnectJob::LogConnectCompletion(int net_error) {
+  connect_timing_.connect_end = base::TimeTicks::Now();
   net_log().EndEventWithNetErrorCode(
       NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_CONNECT, net_error);
 }
 
 void ConnectJob::OnTimeout() {
   // Make sure the socket is NULL before calling into |delegate|.
   set_socket(NULL);
 
   net_log_.AddEvent(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_TIMED_OUT);
 
@@ skipping 233 matching lines @@
   // We couldn't find a socket to reuse, and there's space to allocate one,
   // so allocate and connect a new one.
   scoped_ptr<ConnectJob> connect_job(
       connect_job_factory_->NewConnectJob(group_name, *request, this));
 
   int rv = connect_job->Connect();
   if (rv == OK) {
     LogBoundConnectJobToRequest(connect_job->net_log().source(), request);
     if (!preconnecting) {
       HandOutSocket(connect_job->ReleaseSocket(), false /* not reused */,
-                    handle, base::TimeDelta(), group, request->net_log());
+                    connect_job->connect_timing(), handle, base::TimeDelta(),
+                    group, request->net_log());
     } else {
       AddIdleSocket(connect_job->ReleaseSocket(), group);
     }
   } else if (rv == ERR_IO_PENDING) {
     // If we don't have any sockets in this group, set a timer for potentially
     // creating a new one.  If the SYN is lost, this backup socket may complete
     // before the slow socket, improving end user latency.
     if (connect_backup_jobs_enabled_ &&
         group->IsEmpty() && !group->HasBackupJob()) {
       group->StartBackupSocketTimer(group_name, this);
     }
 
     connecting_socket_count_++;
 
     group->AddJob(connect_job.release(), preconnecting);
   } else {
     LogBoundConnectJobToRequest(connect_job->net_log().source(), request);
     StreamSocket* error_socket = NULL;
     if (!preconnecting) {
       DCHECK(handle);
       connect_job->GetAdditionalErrorState(handle);
       error_socket = connect_job->ReleaseSocket();
     }
     if (error_socket) {
-      HandOutSocket(error_socket, false /* not reused */, handle,
-                    base::TimeDelta(), group, request->net_log());
+      HandOutSocket(error_socket, false /* not reused */,
+                    connect_job->connect_timing(), handle, base::TimeDelta(),
+                    group, request->net_log());
     } else if (group->IsEmpty()) {
       RemoveGroup(group_name);
     }
   }
 
   return rv;
 }
 
 bool ClientSocketPoolBaseHelper::AssignIdleSocketToRequest(
     const Request* request, Group* group) {
@@ skipping 45 matching lines @@
 
   if (idle_socket_it != idle_sockets->end()) {
     DecrementIdleCount();
     base::TimeDelta idle_time =
         base::TimeTicks::Now() - idle_socket_it->start_time;
     IdleSocket idle_socket = *idle_socket_it;
     idle_sockets->erase(idle_socket_it);
     HandOutSocket(
         idle_socket.socket,
         idle_socket.socket->WasEverUsed(),
+        ConnectTiming(),
         request->handle(),
         idle_time,
         group,
         request->net_log());
     return true;
   }
 
   return false;
 }
 
@@ skipping 360 matching lines @@
 void ClientSocketPoolBaseHelper::OnConnectJobComplete(
     int result, ConnectJob* job) {
   DCHECK_NE(ERR_IO_PENDING, result);
   const std::string group_name = job->group_name();
   GroupMap::iterator group_it = group_map_.find(group_name);
   CHECK(group_it != group_map_.end());
   Group* group = group_it->second;
 
   scoped_ptr<StreamSocket> socket(job->ReleaseSocket());
 
+  // Copies of these are needed because |job| may be deleted before they are
+  // accessed.
   BoundNetLog job_log = job->net_log();
+  ConnectTiming connect_timing = job->connect_timing();
 
   if (result == OK) {
     DCHECK(socket.get());
     RemoveConnectJob(job, group);
     if (!group->pending_requests().empty()) {
       scoped_ptr<const Request> r(RemoveRequestFromQueue(
           group->mutable_pending_requests()->begin(), group));
       LogBoundConnectJobToRequest(job_log.source(), r.get());
       HandOutSocket(
-          socket.release(), false /* unused socket */, r->handle(),
-          base::TimeDelta(), group, r->net_log());
+          socket.release(), false /* unused socket */, connect_timing,
+          r->handle(), base::TimeDelta(), group, r->net_log());
       r->net_log().EndEvent(NetLog::TYPE_SOCKET_POOL);
       InvokeUserCallbackLater(r->handle(), r->callback(), result);
     } else {
       AddIdleSocket(socket.release(), group);
       OnAvailableSocketSlot(group_name, group);
       CheckForStalledSocketGroups();
     }
   } else {
     // If we got a socket, it must contain error information so pass that
     // up so that the caller can retrieve it.
     bool handed_out_socket = false;
     if (!group->pending_requests().empty()) {
       scoped_ptr<const Request> r(RemoveRequestFromQueue(
           group->mutable_pending_requests()->begin(), group));
       LogBoundConnectJobToRequest(job_log.source(), r.get());
       job->GetAdditionalErrorState(r->handle());
       RemoveConnectJob(job, group);
       if (socket.get()) {
         handed_out_socket = true;
-        HandOutSocket(socket.release(), false /* unused socket */, r->handle(),
-                      base::TimeDelta(), group, r->net_log());
+        HandOutSocket(socket.release(), false /* unused socket */,
+                      connect_timing, r->handle(), base::TimeDelta(), group,
+                      r->net_log());
       }
-      r->net_log().EndEventWithNetErrorCode(NetLog::TYPE_SOCKET_POOL,
-                                            result);
+      r->net_log().EndEventWithNetErrorCode(NetLog::TYPE_SOCKET_POOL, result);
       InvokeUserCallbackLater(r->handle(), r->callback(), result);
     } else {
       RemoveConnectJob(job, group);
     }
     if (!handed_out_socket) {
       OnAvailableSocketSlot(group_name, group);
       CheckForStalledSocketGroups();
     }
   }
 }
@@ skipping 66 matching lines @@
       RemoveGroup(group_name);
 
     request->net_log().EndEventWithNetErrorCode(NetLog::TYPE_SOCKET_POOL, rv);
     InvokeUserCallbackLater(request->handle(), request->callback(), rv);
   }
 }
 
 void ClientSocketPoolBaseHelper::HandOutSocket(
     StreamSocket* socket,
     bool reused,
+    const ConnectTiming& connect_timing,
     ClientSocketHandle* handle,
     base::TimeDelta idle_time,
     Group* group,
     const BoundNetLog& net_log) {
   DCHECK(socket);
   handle->set_socket(socket);
   handle->set_is_reused(reused);
   handle->set_idle_time(idle_time);
   handle->set_pool_id(pool_generation_number_);
+  handle->set_connect_timing(connect_timing);
 
   if (reused) {
     net_log.AddEvent(
         NetLog::TYPE_SOCKET_POOL_REUSED_AN_EXISTING_SOCKET,
         NetLog::IntegerCallback(
             "idle_ms", static_cast<int>(idle_time.InMilliseconds())));
   }
 
   net_log.AddEvent(NetLog::TYPE_SOCKET_POOL_BOUND_TO_SOCKET,
                    socket->NetLog().source().ToEventParametersCallback());
@@ skipping 230 matching lines @@
   STLDeleteElements(&jobs_);
   unassigned_job_count_ = 0;
 
   // Cancel pending backup job.
   weak_factory_.InvalidateWeakPtrs();
 }
 
 }  // namespace internal
 
 }  // namespace net