Add LoadLog instrumentation to HttpNetworkTransaction, to tell how much time was spent reading/writing headers and reading/writing body.

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

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

3 files changed, 53 insertions, 8 deletions

diff --git a/net/base/load_log_event_type_list.h b/net/base/load_log_event_type_list.h
index 2fcf294..da15647 100644
--- a/net/base/load_log_event_type_list.h
+++ b/net/base/load_log_event_type_list.h
@@ -140,3 +140,20 @@ EVENT_TYPE(HTTP_CACHE_READ_INFO)
 // the cache entry to become available (for example if we are waiting for
 // exclusive access to an existing entry).
 EVENT_TYPE(HTTP_CACHE_WAITING)
+
+// ------------------------------------------------------------------------
+// HttpNetworkTransaction
+// ------------------------------------------------------------------------
+
+// Measures the time taken to send the request to the server.
+EVENT_TYPE(HTTP_TRANSACTION_SEND_REQUEST)
+
+// Measures the time to read HTTP response headers from the server.
+EVENT_TYPE(HTTP_TRANSACTION_READ_HEADERS)
+
+// Measures the time to read the entity body from the server.
+EVENT_TYPE(HTTP_TRANSACTION_READ_BODY)
+
+// Measures the time taken to read the response out of the socket before
+// restarting for authentication, on keep alive connections.
+EVENT_TYPE(HTTP_TRANSACTION_DRAIN_BODY_FOR_AUTH_RESTART)
diff --git a/net/http/http_network_transaction.cc b/net/http/http_network_transaction.cc
index 58dd97f..2dd0c70 100644
--- a/net/http/http_network_transaction.cc
+++ b/net/http/http_network_transaction.cc
@@ -435,40 +435,58 @@ int HttpNetworkTransaction::DoLoop(int result) {
       case STATE_SEND_REQUEST:
         DCHECK_EQ(OK, rv);
         TRACE_EVENT_BEGIN("http.send_request", request_, request_->url.spec());
+        LoadLog::BeginEvent(load_log_,
+                            LoadLog::TYPE_HTTP_TRANSACTION_SEND_REQUEST);
         rv = DoSendRequest();
         break;
       case STATE_SEND_REQUEST_COMPLETE:
         rv = DoSendRequestComplete(rv);
         TRACE_EVENT_END("http.send_request", request_, request_->url.spec());
+        LoadLog::EndEvent(load_log_,
+                          LoadLog::TYPE_HTTP_TRANSACTION_SEND_REQUEST);
         break;
       case STATE_READ_HEADERS:
         DCHECK_EQ(OK, rv);
         TRACE_EVENT_BEGIN("http.read_headers", request_, request_->url.spec());
+        LoadLog::BeginEvent(load_log_,
+                            LoadLog::TYPE_HTTP_TRANSACTION_READ_HEADERS);
         rv = DoReadHeaders();
         break;
       case STATE_READ_HEADERS_COMPLETE:
         rv = DoReadHeadersComplete(rv);
         TRACE_EVENT_END("http.read_headers", request_, request_->url.spec());
+        LoadLog::EndEvent(load_log_,
+                          LoadLog::TYPE_HTTP_TRANSACTION_READ_HEADERS);
         break;
       case STATE_READ_BODY:
         DCHECK_EQ(OK, rv);
         TRACE_EVENT_BEGIN("http.read_body", request_, request_->url.spec());
+        LoadLog::BeginEvent(load_log_,
+                            LoadLog::TYPE_HTTP_TRANSACTION_READ_BODY);
         rv = DoReadBody();
         break;
       case STATE_READ_BODY_COMPLETE:
         rv = DoReadBodyComplete(rv);
         TRACE_EVENT_END("http.read_body", request_, request_->url.spec());
+        LoadLog::EndEvent(load_log_,
+                          LoadLog::TYPE_HTTP_TRANSACTION_READ_BODY);
         break;
       case STATE_DRAIN_BODY_FOR_AUTH_RESTART:
         DCHECK_EQ(OK, rv);
         TRACE_EVENT_BEGIN("http.drain_body_for_auth_restart",
                           request_, request_->url.spec());
+        LoadLog::BeginEvent(
+            load_log_,
+            LoadLog::TYPE_HTTP_TRANSACTION_DRAIN_BODY_FOR_AUTH_RESTART);
         rv = DoDrainBodyForAuthRestart();
         break;
       case STATE_DRAIN_BODY_FOR_AUTH_RESTART_COMPLETE:
         rv = DoDrainBodyForAuthRestartComplete(rv);
         TRACE_EVENT_END("http.drain_body_for_auth_restart",
                         request_, request_->url.spec());
+        LoadLog::EndEvent(
+            load_log_,
+            LoadLog::TYPE_HTTP_TRANSACTION_DRAIN_BODY_FOR_AUTH_RESTART);
         break;
       default:
         NOTREACHED() << "bad state";
diff --git a/net/url_request/url_request_unittest.cc b/net/url_request/url_request_unittest.cc
index a8b47d2..0877768 100644
--- a/net/url_request/url_request_unittest.cc
+++ b/net/url_request/url_request_unittest.cc
@@ -203,14 +203,24 @@ TEST_F(URLRequestTestHTTP, GetTest_NoCache) {
     EXPECT_FALSE(d.received_data_before_response());
     EXPECT_NE(0, d.bytes_received());
 
-    // The first and last entries of the LoadLog should be for
-    // TYPE_URL_REQUEST_START.
-    net::ExpectLogContains(r.load_log(), 0,
-                           net::LoadLog::TYPE_URL_REQUEST_START,
-                           net::LoadLog::PHASE_BEGIN);
-    net::ExpectLogContains(r.load_log(), r.load_log()->events().size() - 1,
-                           net::LoadLog::TYPE_URL_REQUEST_START,
-                           net::LoadLog::PHASE_END);
+    // The first part of the log will be for URL_REQUEST_START.
+    // After that, there should be an HTTP_TRANSACTION_READ_BODY
+    EXPECT_TRUE(
+        net::LogContains(*r.load_log(), 0,
+                         net::LoadLog::TYPE_URL_REQUEST_START,
+                         net::LoadLog::PHASE_BEGIN));
+    EXPECT_TRUE(
+        net::LogContains(*r.load_log(), -3,
+                         net::LoadLog::TYPE_URL_REQUEST_START,
+                         net::LoadLog::PHASE_END));
+    EXPECT_TRUE(
+        net::LogContains(*r.load_log(), -2,
+                         net::LoadLog::TYPE_HTTP_TRANSACTION_READ_BODY,
+                         net::LoadLog::PHASE_BEGIN));
+    EXPECT_TRUE(
+        net::LogContains(*r.load_log(), -1,
+                         net::LoadLog::TYPE_HTTP_TRANSACTION_READ_BODY,
+                         net::LoadLog::PHASE_END));
   }
 }