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

6 files changed, 114 insertions, 22 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_;
 };
diff --git a/net/socket/client_socket_handle.cc b/net/socket/client_socket_handle.cc
index 66ca4ab..6e6310d 100644
--- a/net/socket/client_socket_handle.cc
+++ b/net/socket/client_socket_handle.cc
@@ -41,6 +41,8 @@ void ClientSocketHandle::ResetInternal(bool cancel) {
   group_name_.clear();
   is_reused_ = false;
   user_callback_ = NULL;
+  idle_time_ = base::TimeDelta();
+  init_time_ = base::TimeTicks();
 }
 
 LoadState ClientSocketHandle::GetLoadState() const {
diff --git a/net/socket/client_socket_handle.h b/net/socket/client_socket_handle.h
index 67c6cb8..9d63a41 100644
--- a/net/socket/client_socket_handle.h
+++ b/net/socket/client_socket_handle.h
@@ -10,6 +10,7 @@
 #include "base/logging.h"
 #include "base/ref_counted.h"
 #include "base/scoped_ptr.h"
+#include "base/time.h"
 #include "net/base/completion_callback.h"
 #include "net/base/load_states.h"
 #include "net/base/net_errors.h"
@@ -26,6 +27,13 @@ namespace net {
 //
 class ClientSocketHandle {
  public:
+  typedef enum {
+    UNUSED = 0,
+    UNUSED_IDLE,
+    REUSED_IDLE,
+    NUM_TYPES,
+  } SocketReuseType;
+
   explicit ClientSocketHandle(ClientSocketPool* pool);
   ~ClientSocketHandle();
 
@@ -72,15 +80,29 @@ class ClientSocketHandle {
   // Returns true when Init() has completed successfully.
   bool is_initialized() const { return socket_ != NULL; }
 
+  // Returns the time tick when Init() was called.
+  base::TimeTicks init_time() const { return init_time_; }
+
   // Used by ClientSocketPool to initialize the ClientSocketHandle.
   void set_is_reused(bool is_reused) { is_reused_ = is_reused; }
   void set_socket(ClientSocket* s) { socket_.reset(s); }
+  void set_idle_time(base::TimeDelta idle_time) { idle_time_ = idle_time; }
 
   // These may only be used if is_initialized() is true.
   const std::string& group_name() const { return group_name_; }
   ClientSocket* socket() { return socket_.get(); }
   ClientSocket* release_socket() { return socket_.release(); }
   bool is_reused() const { return is_reused_; }
+  base::TimeDelta idle_time() const { return idle_time_; }
+  SocketReuseType reuse_type() const {
+    if (is_reused()) {
+      return REUSED_IDLE;
+    } else if (idle_time() == base::TimeDelta()) {
+      return UNUSED;
+    } else {
+      return UNUSED_IDLE;
+    }
+  }
 
  private:
   // Called on asynchronous completion of an Init() request.
@@ -100,6 +122,8 @@ class ClientSocketHandle {
   bool is_reused_;
   CompletionCallbackImpl<ClientSocketHandle> callback_;
   CompletionCallback* user_callback_;
+  base::TimeDelta idle_time_;
+  base::TimeTicks init_time_;
 
   DISALLOW_COPY_AND_ASSIGN(ClientSocketHandle);
 };
@@ -114,6 +138,7 @@ int ClientSocketHandle::Init(const std::string& group_name,
   CHECK(!group_name.empty());
   ResetInternal(true);
   group_name_ = group_name;
+  init_time_ = base::TimeTicks::Now();
   int rv = pool_->RequestSocket(
       group_name, &socket_params, priority, this, &callback_, load_log);
   if (rv == ERR_IO_PENDING) {
diff --git a/net/socket/client_socket_pool_base.cc b/net/socket/client_socket_pool_base.cc
index bfe8405..d966555 100644
--- a/net/socket/client_socket_pool_base.cc
+++ b/net/socket/client_socket_pool_base.cc
@@ -132,8 +132,10 @@ int ClientSocketPoolBaseHelper::RequestSocket(
     DecrementIdleCount();
     if (idle_socket.socket->IsConnectedAndIdle()) {
       // We found one we can reuse!
+      base::TimeDelta idle_time =
+          base::TimeTicks::Now() - idle_socket.start_time;
       HandOutSocket(
-          idle_socket.socket, idle_socket.used, handle, &group);
+          idle_socket.socket, idle_socket.used, handle, idle_time, &group);
       return OK;
     }
     delete idle_socket.socket;
@@ -147,7 +149,7 @@ int ClientSocketPoolBaseHelper::RequestSocket(
   int rv = connect_job->Connect();
   if (rv == OK) {
     HandOutSocket(connect_job->ReleaseSocket(), false /* not reused */,
-                  handle, &group);
+                  handle, base::TimeDelta(), &group);
   } else if (rv == ERR_IO_PENDING) {
     connecting_socket_count_++;
 
@@ -395,7 +397,8 @@ void ClientSocketPoolBaseHelper::OnConnectJobComplete(
         scoped_ptr<const Request> r(group.pending_requests.front());
         group.pending_requests.pop_front();
         HandOutSocket(
-            socket.release(), false /* unused socket */, r->handle(), &group);
+            socket.release(), false /* unused socket */, r->handle(),
+            base::TimeDelta(), &group);
         r->callback()->Run(result);
       } else {
         AddIdleSocket(socket.release(), false /* unused socket */, &group);
@@ -431,7 +434,8 @@ void ClientSocketPoolBaseHelper::OnConnectJobComplete(
     MaybeOnAvailableSocketSlot(group_name);
   } else {
     DCHECK(socket.get());
-    HandOutSocket(socket.release(), false /* not reused */, handle, &group);
+    HandOutSocket(socket.release(), false /* not reused */, handle,
+                  base::TimeDelta(), &group);
     callback->Run(result);
   }
 }
@@ -520,10 +524,12 @@ void ClientSocketPoolBaseHelper::HandOutSocket(
     ClientSocket* socket,
     bool reused,
     ClientSocketHandle* handle,
+    base::TimeDelta idle_time,
     Group* group) {
   DCHECK(socket);
   handle->set_socket(socket);
   handle->set_is_reused(reused);
+  handle->set_idle_time(idle_time);
 
   handed_out_socket_count_++;
   group->active_socket_count++;
diff --git a/net/socket/client_socket_pool_base.h b/net/socket/client_socket_pool_base.h
index bae88b7..bdcee36d 100644
--- a/net/socket/client_socket_pool_base.h
+++ b/net/socket/client_socket_pool_base.h
@@ -312,6 +312,7 @@ class ClientSocketPoolBaseHelper
   void HandOutSocket(ClientSocket* socket,
                      bool reused,
                      ClientSocketHandle* handle,
+                     base::TimeDelta time_idle,
                      Group* group);
 
   // Adds |socket| to the list of idle sockets for |group|.  |used| indicates