LoadTiming implementation in net, part 1.

net/socket/transport_client_socket_pool.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/transport_client_socket_pool.h"
 
 #include <algorithm>
 
 #include "base/compiler_specific.h"
 #include "base/logging.h"
@@ skipping 145 matching lines @@
         rv = ERR_FAILED;
         break;
     }
   } while (rv != ERR_IO_PENDING && next_state_ != STATE_NONE);
 
   return rv;
 }
 
 int TransportConnectJob::DoResolveHost() {
   next_state_ = STATE_RESOLVE_HOST_COMPLETE;
+  connect_timing_.dns_start = base::TimeTicks::Now();
+
   return resolver_.Resolve(
       params_->destination(), &addresses_,
       base::Bind(&TransportConnectJob::OnIOComplete, base::Unretained(this)),
       net_log());
 }
 
 int TransportConnectJob::DoResolveHostComplete(int result) {
+  connect_timing_.dns_end = base::TimeTicks::Now();
+  // Overwrite connection start time, since for connections that do not go
+  // through proxies, |connect_start| should not include dns lookup time.
+  connect_timing_.connect_start = connect_timing_.dns_end;
+
   if (result == OK) {
     // Invoke callback, and abort if it fails.
     if (!params_->host_resolution_callback().is_null())
       result = params_->host_resolution_callback().Run(addresses_, net_log());
 
     if (result == OK)
       next_state_ = STATE_TRANSPORT_CONNECT;
   }
   return result;
 }
 
 int TransportConnectJob::DoTransportConnect() {
   next_state_ = STATE_TRANSPORT_CONNECT_COMPLETE;
   transport_socket_.reset(client_socket_factory_->CreateTransportClientSocket(
         addresses_, net_log().net_log(), net_log().source()));
-  connect_start_time_ = base::TimeTicks::Now();
   int rv = transport_socket_->Connect(
       base::Bind(&TransportConnectJob::OnIOComplete, base::Unretained(this)));
   if (rv == ERR_IO_PENDING &&
       addresses_.front().GetFamily() == ADDRESS_FAMILY_IPV6 &&
       !AddressListOnlyContainsIPv6(addresses_)) {
     fallback_timer_.Start(FROM_HERE,
         base::TimeDelta::FromMilliseconds(kIPv6FallbackTimerInMs),
         this, &TransportConnectJob::DoIPv6FallbackTransportConnect);
   }
   return rv;
 }
 
 int TransportConnectJob::DoTransportConnectComplete(int result) {
   if (result == OK) {
     bool is_ipv4 = addresses_.front().GetFamily() == ADDRESS_FAMILY_IPV4;
-    DCHECK(connect_start_time_ != base::TimeTicks());
-    DCHECK(start_time_ != base::TimeTicks());
+    DCHECK(!connect_timing_.connect_start.is_null());
+    DCHECK(!connect_timing_.dns_start.is_null());
     base::TimeTicks now = base::TimeTicks::Now();
-    base::TimeDelta total_duration = now - start_time_;
+    base::TimeDelta total_duration = now - connect_timing_.dns_start;
     UMA_HISTOGRAM_CUSTOM_TIMES(
         "Net.DNS_Resolution_And_TCP_Connection_Latency2",
         total_duration,
         base::TimeDelta::FromMilliseconds(1),
         base::TimeDelta::FromMinutes(10),
         100);
 
-    base::TimeDelta connect_duration = now - connect_start_time_;
+    base::TimeDelta connect_duration = now - connect_timing_.connect_start;
     UMA_HISTOGRAM_CUSTOM_TIMES("Net.TCP_Connection_Latency",
         connect_duration,
         base::TimeDelta::FromMilliseconds(1),
         base::TimeDelta::FromMinutes(10),
         100);
 
     if (is_ipv4) {
       UMA_HISTOGRAM_CUSTOM_TIMES("Net.TCP_Connection_Latency_IPv4_No_Race",
                                  connect_duration,
                                  base::TimeDelta::FromMilliseconds(1),
@@ skipping 55 matching lines @@
   if (next_state_ != STATE_TRANSPORT_CONNECT_COMPLETE) {
     NOTREACHED();
     return;
   }
 
   DCHECK_NE(ERR_IO_PENDING, result);
   DCHECK(fallback_transport_socket_.get());
   DCHECK(fallback_addresses_.get());
 
   if (result == OK) {
-    DCHECK(fallback_connect_start_time_ != base::TimeTicks());
-    DCHECK(start_time_ != base::TimeTicks());
+    DCHECK(!fallback_connect_start_time_.is_null());
+    DCHECK(!connect_timing_.dns_start.is_null());
     base::TimeTicks now = base::TimeTicks::Now();
-    base::TimeDelta total_duration = now - start_time_;
+    base::TimeDelta total_duration = now - connect_timing_.dns_start;
     UMA_HISTOGRAM_CUSTOM_TIMES(
         "Net.DNS_Resolution_And_TCP_Connection_Latency2",
         total_duration,
         base::TimeDelta::FromMilliseconds(1),
         base::TimeDelta::FromMinutes(10),
         100);
 
     base::TimeDelta connect_duration = now - fallback_connect_start_time_;
     UMA_HISTOGRAM_CUSTOM_TIMES("Net.TCP_Connection_Latency",
         connect_duration,
@@ skipping 12 matching lines @@
   } else {
     // Be a bit paranoid and kill off the fallback members to prevent reuse.
     fallback_transport_socket_.reset();
     fallback_addresses_.reset();
   }
   NotifyDelegateOfCompletion(result);  // Deletes |this|
 }
 
 int TransportConnectJob::ConnectInternal() {
   next_state_ = STATE_RESOLVE_HOST;
-  start_time_ = base::TimeTicks::Now();
   return DoLoop(OK);
 }
 
 ConnectJob*
     TransportClientSocketPool::TransportConnectJobFactory::NewConnectJob(
     const std::string& group_name,
     const PoolBase::Request& request,
     ConnectJob::Delegate* delegate) const {
   return new TransportConnectJob(group_name,
                                  request.params(),
@@ skipping 124 matching lines @@
 
 base::TimeDelta TransportClientSocketPool::ConnectionTimeout() const {
   return base_.ConnectionTimeout();
 }
 
 ClientSocketPoolHistograms* TransportClientSocketPool::histograms() const {
   return base_.histograms();
 }
 
 }  // namespace net