Record the time duration for establishing proxy connection

net/http/http_proxy_client_socket_wrapper.cc

 // Copyright 2015 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/http/http_proxy_client_socket_wrapper.h"
 
 #include <utility>
 
 #include "base/bind.h"
 #include "base/bind_helpers.h"
 #include "base/callback_helpers.h"
 #include "base/memory/weak_ptr.h"
+#include "base/metrics/histogram_macros.h"
 #include "base/profiler/scoped_tracker.h"
 #include "base/values.h"
 #include "net/base/proxy_delegate.h"
 #include "net/http/http_proxy_client_socket.h"
 #include "net/http/http_response_info.h"
 #include "net/log/net_log_event_type.h"
 #include "net/log/net_log_source.h"
 #include "net/log/net_log_source_type.h"
 #include "net/socket/client_socket_handle.h"
 #include "net/spdy/spdy_proxy_client_socket.h"
@@ skipping 357 matching lines @@
         NOTREACHED() << "bad state";
         rv = ERR_FAILED;
         break;
     }
   } while (rv != ERR_IO_PENDING && next_state_ != STATE_NONE);
 
   return rv;
 }
 
 int HttpProxyClientSocketWrapper::DoBeginConnect() {
+  connect_start_time_ = base::TimeTicks::Now();
   SetConnectTimer(connect_timeout_duration_);
   if (transport_params_) {
     next_state_ = STATE_TCP_CONNECT;
   } else {
     next_state_ = STATE_SSL_CONNECT;
   }
 
   return OK;
 }
 
 int HttpProxyClientSocketWrapper::DoTransportConnect() {
   next_state_ = STATE_TCP_CONNECT_COMPLETE;
   transport_socket_handle_.reset(new ClientSocketHandle());
   return transport_socket_handle_->Init(
       group_name_, transport_params_, priority_, respect_limits_,
       base::Bind(&HttpProxyClientSocketWrapper::OnIOComplete,
                  base::Unretained(this)),
       transport_pool_, net_log_);
 }
 
 int HttpProxyClientSocketWrapper::DoTransportConnectComplete(int result) {
-  if (result != OK)
+  if (result != OK) {
+    UMA_HISTOGRAM_MEDIUM_TIMES("Net.HttpProxy.ConnectLatency.Insecure.Error",
+                               base::TimeTicks::Now() - connect_start_time_);
     return ERR_PROXY_CONNECTION_FAILED;
+  }
 
   // Reset the timer to just the length of time allowed for HttpProxy handshake
   // so that a fast TCP connection plus a slow HttpProxy failure doesn't take
   // longer to timeout than it should.
   SetConnectTimer(proxy_negotiation_timeout_duration_);
 
   next_state_ = STATE_HTTP_PROXY_CONNECT;
   return result;
 }
 
@@ skipping 15 matching lines @@
       group_name_, ssl_params_, priority_, respect_limits_,
       base::Bind(&HttpProxyClientSocketWrapper::OnIOComplete,
                  base::Unretained(this)),
       ssl_pool_, net_log_);
 }
 
 int HttpProxyClientSocketWrapper::DoSSLConnectComplete(int result) {
   if (result == ERR_SSL_CLIENT_AUTH_CERT_NEEDED) {
     DCHECK(
         transport_socket_handle_->ssl_error_response_info().cert_request_info);
+    UMA_HISTOGRAM_MEDIUM_TIMES("Net.HttpProxy.ConnectLatency.Secure.Error",
+                               base::TimeTicks::Now() - connect_start_time_);
     error_response_info_.reset(new HttpResponseInfo(
         transport_socket_handle_->ssl_error_response_info()));
     error_response_info_->cert_request_info->is_proxy = true;
     return result;
   }
 
   if (IsCertificateError(result)) {
+    UMA_HISTOGRAM_MEDIUM_TIMES("Net.HttpProxy.ConnectLatency.Secure.Error",
+                               base::TimeTicks::Now() - connect_start_time_);
     if (ssl_params_->load_flags() & LOAD_IGNORE_ALL_CERT_ERRORS) {
       result = OK;
     } else {
       // TODO(rch): allow the user to deal with proxy cert errors in the
       // same way as server cert errors.
       transport_socket_handle_->socket()->Disconnect();
       return ERR_PROXY_CERTIFICATE_INVALID;
     }
   }
   // A SPDY session to the proxy completed prior to resolving the proxy
   // hostname. Surface this error, and allow the delegate to retry.
   // See crbug.com/334413.
   if (result == ERR_SPDY_SESSION_ALREADY_EXISTS) {
     DCHECK(!transport_socket_handle_->socket());
     return ERR_SPDY_SESSION_ALREADY_EXISTS;
   }
   if (result < 0) {
+    UMA_HISTOGRAM_MEDIUM_TIMES("Net.HttpProxy.ConnectLatency.Secure.Error",
+                               base::TimeTicks::Now() - connect_start_time_);
     if (transport_socket_handle_->socket())
       transport_socket_handle_->socket()->Disconnect();
     return ERR_PROXY_CONNECTION_FAILED;
   }
 
   SSLClientSocket* ssl =
       static_cast<SSLClientSocket*>(transport_socket_handle_->socket());
   negotiated_protocol_ = ssl->GetNegotiatedProtocol();
   using_spdy_ = negotiated_protocol_ == kProtoHTTP2;
 
@@ skipping 12 matching lines @@
     next_state_ = STATE_SPDY_PROXY_CREATE_STREAM;
   } else {
     next_state_ = STATE_HTTP_PROXY_CONNECT;
   }
   return result;
 }
 
 int HttpProxyClientSocketWrapper::DoHttpProxyConnect() {
   next_state_ = STATE_HTTP_PROXY_CONNECT_COMPLETE;
 
+  if (transport_params_) {
+    UMA_HISTOGRAM_MEDIUM_TIMES("Net.HttpProxy.ConnectLatency.Insecure.Success",
+                               base::TimeTicks::Now() - connect_start_time_);
+  } else {
+    UMA_HISTOGRAM_MEDIUM_TIMES("Net.HttpProxy.ConnectLatency.Secure.Success",
+                               base::TimeTicks::Now() - connect_start_time_);
+  }
+
   // Add a HttpProxy connection on top of the tcp socket.
   transport_socket_.reset(new HttpProxyClientSocket(
       transport_socket_handle_.release(), user_agent_, endpoint_,
       GetDestination().host_port_pair(), http_auth_controller_.get(), tunnel_,
       using_spdy_, negotiated_protocol_, proxy_delegate_,
       ssl_params_.get() != nullptr));
   return transport_socket_->Connect(base::Bind(
       &HttpProxyClientSocketWrapper::OnIOComplete, base::Unretained(this)));
 }
 
@@ skipping 97 matching lines @@
   connect_timer_.Stop();
   connect_timer_.Start(FROM_HERE, delay, this,
                        &HttpProxyClientSocketWrapper::ConnectTimeout);
 }
 
 void HttpProxyClientSocketWrapper::ConnectTimeout() {
   // Timer shouldn't be running if next_state_ is STATE_NONE.
   DCHECK_NE(STATE_NONE, next_state_);
   DCHECK(!connect_callback_.is_null());
 
+  if (next_state_ == STATE_TCP_CONNECT_COMPLETE ||
+      next_state_ == STATE_SSL_CONNECT_COMPLETE) {
+    if (transport_params_) {
+      UMA_HISTOGRAM_MEDIUM_TIMES(
+          "Net.HttpProxy.ConnectLatency.Insecure.TimedOut",
+          base::TimeTicks::Now() - connect_start_time_);
+    } else {
+      UMA_HISTOGRAM_MEDIUM_TIMES("Net.HttpProxy.ConnectLatency.Secure.TimedOut",
+                                 base::TimeTicks::Now() - connect_start_time_);
+    }
+  }
+
   NotifyProxyDelegateOfCompletion(ERR_CONNECTION_TIMED_OUT);
 
   CompletionCallback callback = connect_callback_;
   Disconnect();
   callback.Run(ERR_CONNECTION_TIMED_OUT);
 }
 
 const HostResolver::RequestInfo&
 HttpProxyClientSocketWrapper::GetDestination() {
   if (transport_params_) {
     return transport_params_->destination();
   } else {
     return ssl_params_->GetDirectConnectionParams()->destination();
   }
 }
 
 }  // namespace net