Fix ClientSocketPoolBaseHelper to maintain order properly.

It used to be the case that when a disconnected socket is released, it would pop the front of the queue, and since it was a disconnected socket, would kick off another ConnectJob and then append the request to the back to the queue.
While doing this, I cleaned up the TYPE_SOCKET_WAITING_IN_QUEUE since it doesn't make sense.  You're always waiting in a queue, unless the request gets fulfilled immediately.  I've added strings to the LoadLog to distinguish this situation and also identify when the socket has been reused.

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

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

3 files changed, 113 insertions, 64 deletions

diff --git a/net/socket/client_socket_pool_base.cc b/net/socket/client_socket_pool_base.cc
index 4a5c88c..75081a2 100644
--- a/net/socket/client_socket_pool_base.cc
+++ b/net/socket/client_socket_pool_base.cc
@@ -5,8 +5,10 @@
 #include "net/socket/client_socket_pool_base.h"
 
 #include "base/compiler_specific.h"
+#include "base/format_macros.h"
 #include "base/message_loop.h"
 #include "base/stl_util-inl.h"
+#include "base/string_util.h"
 #include "base/time.h"
 #include "net/base/load_log.h"
 #include "net/base/net_errors.h"
@@ -90,6 +92,16 @@ void ConnectJob::OnTimeout() {
 
 namespace internal {
 
+ClientSocketPoolBaseHelper::Request::Request(
+    ClientSocketHandle* handle,
+    CompletionCallback* callback,
+    RequestPriority priority,
+    LoadLog* load_log)
+    : handle_(handle), callback_(callback), priority_(priority),
+      load_log_(load_log) {}
+
+ClientSocketPoolBaseHelper::Request::~Request() {}
+
 ClientSocketPoolBaseHelper::ClientSocketPoolBaseHelper(
     int max_sockets,
     int max_sockets_per_group,
@@ -135,9 +147,6 @@ ClientSocketPoolBaseHelper::~ClientSocketPoolBaseHelper() {
 // static
 void ClientSocketPoolBaseHelper::InsertRequestIntoQueue(
     const Request* r, RequestQueue* pending_requests) {
-  LoadLog::BeginEvent(r->load_log(),
-      LoadLog::TYPE_SOCKET_POOL_WAITING_IN_QUEUE);
-
   RequestQueue::iterator it = pending_requests->begin();
   while (it != pending_requests->end() && r->priority() >= (*it)->priority())
     ++it;
@@ -149,10 +158,6 @@ const ClientSocketPoolBaseHelper::Request*
 ClientSocketPoolBaseHelper::RemoveRequestFromQueue(
     RequestQueue::iterator it, RequestQueue* pending_requests) {
   const Request* req = *it;
-
-  LoadLog::EndEvent(req->load_log(),
-                    LoadLog::TYPE_SOCKET_POOL_WAITING_IN_QUEUE);
-
   pending_requests->erase(it);
   return req;
 }
@@ -160,6 +165,19 @@ ClientSocketPoolBaseHelper::RemoveRequestFromQueue(
 int ClientSocketPoolBaseHelper::RequestSocket(
     const std::string& group_name,
     const Request* request) {
+  LoadLog::BeginEvent(request->load_log(), LoadLog::TYPE_SOCKET_POOL);
+  Group& group = group_map_[group_name];
+  int rv = RequestSocketInternal(group_name, request);
+  if (rv != ERR_IO_PENDING)
+    LoadLog::EndEvent(request->load_log(), LoadLog::TYPE_SOCKET_POOL);
+  else
+    InsertRequestIntoQueue(request, &group.pending_requests);
+  return rv;
+}
+
+int ClientSocketPoolBaseHelper::RequestSocketInternal(
+    const std::string& group_name,
+    const Request* request) {
   DCHECK_GE(request->priority(), 0);
   CompletionCallback* const callback = request->callback();
   CHECK(callback);
@@ -175,13 +193,14 @@ int ClientSocketPoolBaseHelper::RequestSocket(
       // a scan of all groups, so just flip a flag here, and do the check later.
       may_have_stalled_group_ = true;
 
-      LoadLog::AddEvent(request->load_log(),
+      LoadLog::AddEvent(
+          request->load_log(),
           LoadLog::TYPE_SOCKET_POOL_STALLED_MAX_SOCKETS);
     } else {
-      LoadLog::AddEvent(request->load_log(),
+      LoadLog::AddEvent(
+          request->load_log(),
           LoadLog::TYPE_SOCKET_POOL_STALLED_MAX_SOCKETS_PER_GROUP);
     }
-    InsertRequestIntoQueue(request, &group.pending_requests);
     return ERR_IO_PENDING;
   }
 
@@ -195,7 +214,8 @@ int ClientSocketPoolBaseHelper::RequestSocket(
       base::TimeDelta idle_time =
           base::TimeTicks::Now() - idle_socket.start_time;
       HandOutSocket(
-          idle_socket.socket, idle_socket.used, handle, idle_time, &group);
+          idle_socket.socket, idle_socket.used, handle, idle_time, &group,
+          request->load_log());
       return OK;
     }
     delete idle_socket.socket;
@@ -204,7 +224,6 @@ int ClientSocketPoolBaseHelper::RequestSocket(
   // See if we already have enough connect jobs or sockets that will be released
   // soon.
   if (group.HasReleasingSockets()) {
-    InsertRequestIntoQueue(request, &group.pending_requests);
     return ERR_IO_PENDING;
   }
 
@@ -222,12 +241,11 @@ int ClientSocketPoolBaseHelper::RequestSocket(
 
   if (rv == OK) {
     HandOutSocket(connect_job->ReleaseSocket(), false /* not reused */,
-                  handle, base::TimeDelta(), &group);
+                  handle, base::TimeDelta(), &group, request->load_log());
   } else if (rv == ERR_IO_PENDING) {
     connecting_socket_count_++;
 
     ConnectJob* job = connect_job.release();
-    InsertRequestIntoQueue(request, &group.pending_requests);
     group.jobs.insert(job);
   } else if (group.IsEmpty()) {
     group_map_.erase(group_name);
@@ -485,7 +503,7 @@ void ClientSocketPoolBaseHelper::OnConnectJobComplete(
         r->load_log()->Append(job_load_log);
       HandOutSocket(
           socket.release(), false /* unused socket */, r->handle(),
-          base::TimeDelta(), &group);
+          base::TimeDelta(), &group, r->load_log());
       r->callback()->Run(result);
     } else {
       AddIdleSocket(socket.release(), false /* unused socket */, &group);
@@ -554,13 +572,13 @@ void ClientSocketPoolBaseHelper::OnAvailableSocketSlot(
 
 void ClientSocketPoolBaseHelper::ProcessPendingRequest(
     const std::string& group_name, Group* group) {
-  scoped_ptr<const Request> r(RemoveRequestFromQueue(
-        group->pending_requests.begin(), &group->pending_requests));
-
-  int rv = RequestSocket(group_name, r.get());
+  scoped_ptr<const Request> r(*group->pending_requests.begin());
+  int rv = RequestSocketInternal(group_name, r.get());
 
   if (rv != ERR_IO_PENDING) {
     LoadLog::EndEvent(r->load_log(), LoadLog::TYPE_SOCKET_POOL);
+    RemoveRequestFromQueue(group->pending_requests.begin(),
+                           &group->pending_requests);
     r->callback()->Run(rv);
     if (rv != OK) {
       // |group| may be invalid after the callback, we need to search
@@ -577,12 +595,22 @@ void ClientSocketPoolBaseHelper::HandOutSocket(
     bool reused,
     ClientSocketHandle* handle,
     base::TimeDelta idle_time,
-    Group* group) {
+    Group* group,
+    LoadLog* load_log) {
   DCHECK(socket);
   handle->set_socket(socket);
   handle->set_is_reused(reused);
   handle->set_idle_time(idle_time);
 
+  if (reused)
+    LoadLog::AddStringLiteral(load_log, "Reusing socket.");
+  if (idle_time != base::TimeDelta()) {
+    LoadLog::AddString(
+        load_log,
+        StringPrintf("Socket sat idle for %" PRId64 " milliseconds",
+                     idle_time.InMilliseconds()));
+  }
+
   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 d4e9deb..3f400da 100644
--- a/net/socket/client_socket_pool_base.h
+++ b/net/socket/client_socket_pool_base.h
@@ -34,7 +34,6 @@
 #include "base/timer.h"
 #include "net/base/address_list.h"
 #include "net/base/completion_callback.h"
-#include "net/base/load_log.h"
 #include "net/base/load_states.h"
 #include "net/base/net_errors.h"
 #include "net/base/network_change_notifier.h"
@@ -45,6 +44,7 @@
 namespace net {
 
 class ClientSocketHandle;
+class LoadLog;
 
 // ConnectJob provides an abstract interface for "connecting" a socket.
 // The connection may involve host resolution, tcp connection, ssl connection,
@@ -127,11 +127,9 @@ class ClientSocketPoolBaseHelper
     Request(ClientSocketHandle* handle,
             CompletionCallback* callback,
             RequestPriority priority,
-            LoadLog* load_log)
-        : handle_(handle), callback_(callback), priority_(priority),
-          load_log_(load_log) {}
+            LoadLog* load_log);
 
-    virtual ~Request() {}
+    virtual ~Request();
 
     ClientSocketHandle* handle() const { return handle_; }
     CompletionCallback* callback() const { return callback_; }
@@ -325,7 +323,8 @@ class ClientSocketPoolBaseHelper
                      bool reused,
                      ClientSocketHandle* handle,
                      base::TimeDelta time_idle,
-                     Group* group);
+                     Group* group,
+                     LoadLog* load_log);
 
   // Adds |socket| to the list of idle sockets for |group|.  |used| indicates
   // whether or not the socket has previously been used.
@@ -340,6 +339,12 @@ class ClientSocketPoolBaseHelper
   // TODO(phajdan.jr): Also take idle sockets into account.
   bool ReachedMaxSocketsLimit() const;
 
+  // This is the internal implementation of RequestSocket().  It differs in that
+  // it does not handle logging into LoadLog of the queueing status of
+  // |request|.
+  int RequestSocketInternal(const std::string& group_name,
+                            const Request* request);
+
   GroupMap group_map_;
 
   // Timer used to periodically prune idle sockets that timed out or can't be
@@ -465,12 +470,9 @@ class ClientSocketPoolBase {
                     LoadLog* load_log) {
     scoped_ptr<Request> request(
         new Request(handle, callback, priority, params, load_log));
-    LoadLog::BeginEvent(load_log, LoadLog::TYPE_SOCKET_POOL);
     int rv = helper_->RequestSocket(group_name, request.get());
     if (rv == ERR_IO_PENDING)
       request.release();
-    else
-      LoadLog::EndEvent(load_log, LoadLog::TYPE_SOCKET_POOL);
     return rv;
   }
 
diff --git a/net/socket/client_socket_pool_base_unittest.cc b/net/socket/client_socket_pool_base_unittest.cc
index 9f875ad..ad87903 100644
--- a/net/socket/client_socket_pool_base_unittest.cc
+++ b/net/socket/client_socket_pool_base_unittest.cc
@@ -10,6 +10,7 @@
 #include "base/scoped_vector.h"
 #include "net/base/load_log.h"
 #include "net/base/load_log_unittest.h"
+#include "net/base/load_log_util.h"
 #include "net/base/net_errors.h"
 #include "net/base/request_priority.h"
 #include "net/base/test_completion_callback.h"
@@ -1125,18 +1126,14 @@ TEST_F(ClientSocketPoolBaseTest, BasicAsynchronous) {
   EXPECT_TRUE(req.handle()->socket());
   req.handle()->Reset();
 
-  EXPECT_EQ(6u, log->entries().size());
+  EXPECT_EQ(4u, log->entries().size());
   EXPECT_TRUE(LogContainsBeginEvent(*log, 0, LoadLog::TYPE_SOCKET_POOL));
   EXPECT_TRUE(LogContainsBeginEvent(
-      *log, 1, LoadLog::TYPE_SOCKET_POOL_WAITING_IN_QUEUE));
-  EXPECT_TRUE(LogContainsEndEvent(
-      *log, 2, LoadLog::TYPE_SOCKET_POOL_WAITING_IN_QUEUE));
-  EXPECT_TRUE(LogContainsBeginEvent(
-      *log, 3, LoadLog::TYPE_SOCKET_POOL_CONNECT_JOB));
+      *log, 1, LoadLog::TYPE_SOCKET_POOL_CONNECT_JOB));
   EXPECT_TRUE(LogContainsEndEvent(
-      *log, 4, LoadLog::TYPE_SOCKET_POOL_CONNECT_JOB));
+      *log, 2, LoadLog::TYPE_SOCKET_POOL_CONNECT_JOB));
   EXPECT_TRUE(LogContainsEndEvent(
-      *log, 5, LoadLog::TYPE_SOCKET_POOL));
+      *log, 3, LoadLog::TYPE_SOCKET_POOL));
 }
 
 TEST_F(ClientSocketPoolBaseTest,
@@ -1152,17 +1149,13 @@ TEST_F(ClientSocketPoolBaseTest,
   EXPECT_EQ(LOAD_STATE_CONNECTING, pool_->GetLoadState("a", req.handle()));
   EXPECT_EQ(ERR_CONNECTION_FAILED, req.WaitForResult());
 
-  EXPECT_EQ(6u, log->entries().size());
+  EXPECT_EQ(4u, log->entries().size());
   EXPECT_TRUE(LogContainsBeginEvent(*log, 0, LoadLog::TYPE_SOCKET_POOL));
   EXPECT_TRUE(LogContainsBeginEvent(
-      *log, 1, LoadLog::TYPE_SOCKET_POOL_WAITING_IN_QUEUE));
-  EXPECT_TRUE(LogContainsEndEvent(
-      *log, 2, LoadLog::TYPE_SOCKET_POOL_WAITING_IN_QUEUE));
-  EXPECT_TRUE(LogContainsBeginEvent(
-      *log, 3, LoadLog::TYPE_SOCKET_POOL_CONNECT_JOB));
+      *log, 1, LoadLog::TYPE_SOCKET_POOL_CONNECT_JOB));
   EXPECT_TRUE(LogContainsEndEvent(
-      *log, 4, LoadLog::TYPE_SOCKET_POOL_CONNECT_JOB));
-  EXPECT_TRUE(LogContainsEndEvent(*log, 5, LoadLog::TYPE_SOCKET_POOL));
+      *log, 2, LoadLog::TYPE_SOCKET_POOL_CONNECT_JOB));
+  EXPECT_TRUE(LogContainsEndEvent(*log, 3, LoadLog::TYPE_SOCKET_POOL));
 }
 
 TEST_F(ClientSocketPoolBaseTest, TwoRequestsCancelOne) {
@@ -1183,37 +1176,27 @@ TEST_F(ClientSocketPoolBaseTest, TwoRequestsCancelOne) {
 
   req.handle()->Reset();
 
-  EXPECT_EQ(5u, log1->entries().size());
+  EXPECT_EQ(3u, log1->entries().size());
   EXPECT_TRUE(LogContainsBeginEvent(*log1, 0, LoadLog::TYPE_SOCKET_POOL));
-  EXPECT_TRUE(LogContainsBeginEvent(
-      *log1, 1, LoadLog::TYPE_SOCKET_POOL_WAITING_IN_QUEUE));
-  EXPECT_TRUE(LogContainsEndEvent(
-      *log1, 2, LoadLog::TYPE_SOCKET_POOL_WAITING_IN_QUEUE));
   EXPECT_TRUE(LogContainsEvent(
-      *log1, 3, LoadLog::TYPE_CANCELLED, LoadLog::PHASE_NONE));
-  EXPECT_TRUE(LogContainsEndEvent(*log1, 4, LoadLog::TYPE_SOCKET_POOL));
+      *log1, 1, LoadLog::TYPE_CANCELLED, LoadLog::PHASE_NONE));
+  EXPECT_TRUE(LogContainsEndEvent(*log1, 2, LoadLog::TYPE_SOCKET_POOL));
 
   // At this point, request 2 is just waiting for the connect job to finish.
-  EXPECT_EQ(2u, log2->entries().size());
+  EXPECT_EQ(1u, log2->entries().size());
   EXPECT_TRUE(LogContainsBeginEvent(*log2, 0, LoadLog::TYPE_SOCKET_POOL));
-  EXPECT_TRUE(LogContainsBeginEvent(
-      *log2, 1, LoadLog::TYPE_SOCKET_POOL_WAITING_IN_QUEUE));
 
   EXPECT_EQ(OK, req2.WaitForResult());
   req2.handle()->Reset();
 
   // Now request 2 has actually finished.
-  EXPECT_EQ(6u, log2->entries().size());
+  EXPECT_EQ(4u, log2->entries().size());
   EXPECT_TRUE(LogContainsBeginEvent(*log2, 0, LoadLog::TYPE_SOCKET_POOL));
   EXPECT_TRUE(LogContainsBeginEvent(
-      *log2, 1, LoadLog::TYPE_SOCKET_POOL_WAITING_IN_QUEUE));
+      *log2, 1, LoadLog::TYPE_SOCKET_POOL_CONNECT_JOB));
   EXPECT_TRUE(LogContainsEndEvent(
-      *log1, 2, LoadLog::TYPE_SOCKET_POOL_WAITING_IN_QUEUE));
-  EXPECT_TRUE(LogContainsBeginEvent(
-      *log2, 3, LoadLog::TYPE_SOCKET_POOL_CONNECT_JOB));
-  EXPECT_TRUE(LogContainsEndEvent(
-      *log2, 4, LoadLog::TYPE_SOCKET_POOL_CONNECT_JOB));
-  EXPECT_TRUE(LogContainsEndEvent(*log2, 5, LoadLog::TYPE_SOCKET_POOL));
+      *log2, 2, LoadLog::TYPE_SOCKET_POOL_CONNECT_JOB));
+  EXPECT_TRUE(LogContainsEndEvent(*log2, 3, LoadLog::TYPE_SOCKET_POOL));
 
 }
 
@@ -1384,9 +1367,13 @@ TEST_F(ClientSocketPoolBaseTest, CleanupTimedOutIdleSockets) {
   // used socket.  Request it to make sure that it's used.
 
   pool_->CleanupTimedOutIdleSockets();
-  rv = InitHandle(req.handle(), "a", LOWEST, &req, pool_.get(), NULL);
+  scoped_refptr<LoadLog> log(new LoadLog(LoadLog::kUnbounded));
+  rv = InitHandle(req.handle(), "a", LOWEST, &req, pool_.get(), log);
   EXPECT_EQ(OK, rv);
   EXPECT_TRUE(req.handle()->is_reused());
+  EXPECT_TRUE(LogContainsEntryWithType(
+      *log, 1, LoadLog::Entry::TYPE_STRING_LITERAL))
+      << LoadLogUtil::PrettyPrintAsEventTree(log);
 }
 
 // Make sure that we process all pending requests even when we're stalling 
@@ -1430,6 +1417,38 @@ TEST_F(ClientSocketPoolBaseTest, MultipleReleasingDisconnectedSockets) {
   EXPECT_FALSE(req4.handle()->is_reused());
 }
 
+TEST_F(ClientSocketPoolBaseTest,
+       ReleasingDisconnectedSocketsMaintainsPriorityOrder) {
+  CreatePool(kDefaultMaxSockets, kDefaultMaxSocketsPerGroup);
+
+  connect_job_factory_->set_job_type(TestConnectJob::kMockPendingJob);
+
+  EXPECT_EQ(ERR_IO_PENDING, StartRequest("a", kDefaultPriority));
+  EXPECT_EQ(ERR_IO_PENDING, StartRequest("a", kDefaultPriority));
+  EXPECT_EQ(ERR_IO_PENDING, StartRequest("a", kDefaultPriority));
+  EXPECT_EQ(ERR_IO_PENDING, StartRequest("a", kDefaultPriority));
+
+  EXPECT_EQ(OK, requests_[0]->WaitForResult());
+  EXPECT_EQ(OK, requests_[1]->WaitForResult());
+  EXPECT_EQ(2u, completion_count_);
+
+  // Releases one connection.
+  EXPECT_TRUE(ReleaseOneConnection(NO_KEEP_ALIVE));
+  EXPECT_EQ(OK, requests_[2]->WaitForResult());
+
+  EXPECT_TRUE(ReleaseOneConnection(NO_KEEP_ALIVE));
+  EXPECT_EQ(OK, requests_[3]->WaitForResult());
+  EXPECT_EQ(4u, completion_count_);
+
+  EXPECT_EQ(1, GetOrderOfRequest(1));
+  EXPECT_EQ(2, GetOrderOfRequest(2));
+  EXPECT_EQ(3, GetOrderOfRequest(3));
+  EXPECT_EQ(4, GetOrderOfRequest(4));
+
+  // Make sure we test order of all requests made.
+  EXPECT_EQ(kIndexOutOfBounds, GetOrderOfRequest(5));
+}
+
 }  // namespace
 
 }  // namespace net