Add histograms for tracking the unused/unused_idle/reused socket states from TCPClientSocketPool.

Tracks the number of each socket type returned by the TCPClientSocketPool.
Also tracks the number of recoverable IO errors (resets, aborts, closes) per socket type.
Also tracks the idle time of a socket before a recoverable IO happens.

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

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

2 files changed, 76 insertions, 18 deletions

diff --git a/net/http/http_network_transaction.cc b/net/http/http_network_transaction.cc
index 0c0bc48..631fe00 100644
--- a/net/http/http_network_transaction.cc
+++ b/net/http/http_network_transaction.cc
@@ -627,8 +627,6 @@ int HttpNetworkTransaction::DoInitConnection() {
     resolve_info.set_allow_cached_response(false);
   }
 
-  transport_socket_request_time_ = base::TimeTicks::Now();
-
   int rv = connection_.Init(connection_group, resolve_info,
                             request_->priority, &io_callback_, NULL);
   return rv;
@@ -640,11 +638,12 @@ int HttpNetworkTransaction::DoInitConnectionComplete(int result) {
 
   DCHECK(connection_.is_initialized());
 
+  LogTCPConnectedMetrics(connection_);
+
   // Set the reused_socket_ flag to indicate that we are using a keep-alive
   // connection.  This flag is used to handle errors that occur while we are
   // trying to reuse a keep-alive connection.
   reused_socket_ = connection_.is_reused();
-  LogTCPConnectedMetrics(reused_socket_);
   if (reused_socket_) {
     next_state_ = STATE_WRITE_HEADERS;
   } else {
@@ -1097,21 +1096,34 @@ int HttpNetworkTransaction::DoDrainBodyForAuthRestartComplete(int result) {
   return OK;
 }
 
-void HttpNetworkTransaction::LogTCPConnectedMetrics(bool reused_socket) const {
-  base::TimeDelta time_to_obtain_connected_socket =
-      base::TimeTicks::Now() - transport_socket_request_time_;
+void HttpNetworkTransaction::LogTCPConnectedMetrics(
+    const ClientSocketHandle& handle) {
+  const base::TimeDelta time_to_obtain_connected_socket =
+      base::TimeTicks::Now() - handle.init_time();
+
+  static const bool use_late_binding_histogram =
+      !FieldTrial::MakeName("", "SocketLateBinding").empty();
 
-  if (!reused_socket) {
+  if (handle.reuse_type() == ClientSocketHandle::UNUSED) {
     UMA_HISTOGRAM_CLIPPED_TIMES(
         "Net.Dns_Resolution_And_TCP_Connection_Latency",
         time_to_obtain_connected_socket,
         base::TimeDelta::FromMilliseconds(1), base::TimeDelta::FromMinutes(10),
         100);
+  }
 
-    UMA_HISTOGRAM_COUNTS_100(
-        "Net.TCP_Connection_Idle_Sockets",
-        session_->connection_pool()->IdleSocketCountInGroup(
-            connection_.group_name()));
+  static LinearHistogram tcp_socket_type_counter(
+      "Net.TCPSocketType",
+      0, ClientSocketHandle::NUM_TYPES, ClientSocketHandle::NUM_TYPES + 1);
+  tcp_socket_type_counter.SetFlags(kUmaTargetedHistogramFlag);
+  tcp_socket_type_counter.Add(handle.reuse_type());
+
+  if (use_late_binding_histogram) {
+    static LinearHistogram tcp_socket_type_counter2(
+        FieldTrial::MakeName("Net.TCPSocketType", "SocketLateBinding").data(),
+        0, ClientSocketHandle::NUM_TYPES, ClientSocketHandle::NUM_TYPES + 1);
+    tcp_socket_type_counter2.SetFlags(kUmaTargetedHistogramFlag);
+    tcp_socket_type_counter2.Add(handle.reuse_type());
   }
 
   UMA_HISTOGRAM_CLIPPED_TIMES(
@@ -1120,9 +1132,6 @@ void HttpNetworkTransaction::LogTCPConnectedMetrics(bool reused_socket) const {
       base::TimeDelta::FromMilliseconds(1), base::TimeDelta::FromMinutes(10),
       100);
 
-  static const bool use_late_binding_histogram =
-      !FieldTrial::MakeName("", "SocketLateBinding").empty();
-
   if (use_late_binding_histogram) {
     UMA_HISTOGRAM_CUSTOM_TIMES(
         FieldTrial::MakeName("Net.TransportSocketRequestTime",
@@ -1133,6 +1142,55 @@ void HttpNetworkTransaction::LogTCPConnectedMetrics(bool reused_socket) const {
   }
 }
 
+void HttpNetworkTransaction::LogIOErrorMetrics(
+    const ClientSocketHandle& handle) {
+  static const bool use_late_binding_histogram =
+      !FieldTrial::MakeName("", "SocketLateBinding").empty();
+
+  static LinearHistogram io_error_socket_type_counter(
+      "Net.IOError_SocketReuseType",
+      0, ClientSocketHandle::NUM_TYPES, ClientSocketHandle::NUM_TYPES + 1);
+  io_error_socket_type_counter.SetFlags(kUmaTargetedHistogramFlag);
+  io_error_socket_type_counter.Add(handle.reuse_type());
+
+  if (use_late_binding_histogram) {
+    static LinearHistogram io_error_socket_type_counter(
+        FieldTrial::MakeName("Net.IOError_SocketReuseType",
+                             "SocketLateBinding").data(),
+        0, ClientSocketHandle::NUM_TYPES, ClientSocketHandle::NUM_TYPES + 1);
+    io_error_socket_type_counter.SetFlags(kUmaTargetedHistogramFlag);
+    io_error_socket_type_counter.Add(handle.reuse_type());
+  }
+
+  switch (handle.reuse_type()) {
+    case ClientSocketHandle::UNUSED:
+      break;
+    case ClientSocketHandle::UNUSED_IDLE:
+      UMA_HISTOGRAM_TIMES("Net.SocketIdleTimeOnIOError_UnusedSocket",
+                          handle.idle_time());
+      if (use_late_binding_histogram) {
+        UMA_HISTOGRAM_TIMES(
+            FieldTrial::MakeName("Net.SocketIdleTimeOnIOError_UnusedSocket",
+                                 "SocketLateBinding").data(),
+            handle.idle_time());
+      }
+      break;
+    case ClientSocketHandle::REUSED_IDLE:
+      UMA_HISTOGRAM_TIMES("Net.SocketIdleTimeOnIOError_ReusedSocket",
+                          handle.idle_time());
+      if (use_late_binding_histogram) {
+        UMA_HISTOGRAM_TIMES(
+            FieldTrial::MakeName("Net.SocketIdleTimeOnIOError_ReusedSocket",
+                                 "SocketLateBinding").data(),
+            handle.idle_time());
+      }
+      break;
+    default:
+      NOTREACHED();
+      break;
+  }
+}
+
 void HttpNetworkTransaction::LogTransactionConnectedMetrics() const {
   base::TimeDelta total_duration = response_.response_time - start_time_;
 
@@ -1466,6 +1524,7 @@ int HttpNetworkTransaction::HandleIOError(int error) {
     case ERR_CONNECTION_RESET:
     case ERR_CONNECTION_CLOSED:
     case ERR_CONNECTION_ABORTED:
+      LogIOErrorMetrics(connection_);
       if (ShouldResendRequest()) {
         ResetConnectionAndRequestForResend();
         error = OK;
diff --git a/net/http/http_network_transaction.h b/net/http/http_network_transaction.h
index 0c5f014..b201aa1 100644
--- a/net/http/http_network_transaction.h
+++ b/net/http/http_network_transaction.h
@@ -156,7 +156,7 @@ class HttpNetworkTransaction : public HttpTransaction {
   int DoDrainBodyForAuthRestartComplete(int result);
 
   // Record histograms of latency until Connect() completes.
-  void LogTCPConnectedMetrics(bool reused_socket) const;
+  static void LogTCPConnectedMetrics(const ClientSocketHandle& handle);
 
   // Record histogram of time until first byte of header is received.
   void LogTransactionConnectedMetrics() const;
@@ -168,6 +168,8 @@ class HttpNetworkTransaction : public HttpTransaction {
   // response to a CONNECT request.
   void LogBlockedTunnelResponse(int response_code) const;
 
+  static void LogIOErrorMetrics(const ClientSocketHandle& handle);
+
   // Called when header_buf_ contains the complete response headers.
   int DidReadResponseHeaders();
 
@@ -404,9 +406,6 @@ class HttpNetworkTransaction : public HttpTransaction {
   // The time the Connect() method was called (if it got called).
   base::Time connect_start_time_;
 
-  // The time that we request the ClientSocketPool for a connected socket.
-  base::TimeTicks transport_socket_request_time_;
-
   // The next state in the state machine.
   State next_state_;
 };