net: Return LoadTiming information in the case of a cache hit

net/http/http_cache_unittest.cc

 // Copyright (c) 2012 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_cache.h"
 
 #include "base/bind.h"
 #include "base/bind_helpers.h"
 #include "base/memory/scoped_vector.h"
 #include "base/message_loop.h"
 #include "base/string_util.h"
 #include "base/stringprintf.h"
 #include "net/base/cache_type.h"
 #include "net/base/host_port_pair.h"
 #include "net/base/load_flags.h"
+#include "net/base/load_timing_info.h"
+#include "net/base/load_timing_info_test_util.h"
 #include "net/base/net_errors.h"
 #include "net/base/net_log_unittest.h"
 #include "net/base/upload_bytes_element_reader.h"
 #include "net/base/upload_data_stream.h"
 #include "net/cert/cert_status_flags.h"
 #include "net/disk_cache/disk_cache.h"
 #include "net/http/http_byte_range.h"
 #include "net/http/http_request_headers.h"
 #include "net/http/http_request_info.h"
 #include "net/http/http_response_headers.h"
 #include "net/http/http_response_info.h"
 #include "net/http/http_transaction.h"
 #include "net/http/http_transaction_delegate.h"
 #include "net/http/http_transaction_unittest.h"
 #include "net/http/http_util.h"
 #include "net/http/mock_http_cache.h"
 #include "net/ssl/ssl_cert_request_info.h"
 #include "testing/gtest/include/gtest/gtest.h"
 
 using base::Time;
 
 namespace {
 
+// Tests the load timing values of a request that goes through a
+// MockNetworkTransaction.
+void TestLoadTimingNetworkRequest(const net::LoadTimingInfo& load_timing_info) {
+  EXPECT_FALSE(load_timing_info.socket_reused);
+  EXPECT_NE(net::NetLog::Source::kInvalidId, load_timing_info.socket_log_id);
+
+  EXPECT_TRUE(load_timing_info.proxy_resolve_start.is_null());
+  EXPECT_TRUE(load_timing_info.proxy_resolve_end.is_null());
+
+  net::ExpectConnectTimingHasTimes(load_timing_info.connect_timing,
+                                   net::CONNECT_TIMING_HAS_CONNECT_TIMES_ONLY);
+  EXPECT_LE(load_timing_info.connect_timing.connect_end,
+            load_timing_info.send_start);
+
+  EXPECT_LE(load_timing_info.send_start, load_timing_info.send_end);
+
+  // Set by URLRequest / URLRequestHttpJob, at a higher level.
+  EXPECT_TRUE(load_timing_info.request_start_time.is_null());
+  EXPECT_TRUE(load_timing_info.request_start.is_null());
+  EXPECT_TRUE(load_timing_info.receive_headers_end.is_null());
+}
+
+// Tests the load timing values of a request that receives a cached response.
+void TestLoadTimingCachedResponse(const net::LoadTimingInfo& load_timing_info) {
+  EXPECT_FALSE(load_timing_info.socket_reused);
+  EXPECT_EQ(net::NetLog::Source::kInvalidId, load_timing_info.socket_log_id);
+
+  EXPECT_TRUE(load_timing_info.proxy_resolve_start.is_null());
+  EXPECT_TRUE(load_timing_info.proxy_resolve_end.is_null());
+
+  net::ExpectConnectTimingHasNoTimes(load_timing_info.connect_timing);
+
+  // Only the send start / end times should be sent, and they should have the
+  // same value.
+  EXPECT_FALSE(load_timing_info.send_start.is_null());
+  EXPECT_EQ(load_timing_info.send_start, load_timing_info.send_end);
+
+  // Set by URLRequest / URLRequestHttpJob, at a higher level.
+  EXPECT_TRUE(load_timing_info.request_start_time.is_null());
+  EXPECT_TRUE(load_timing_info.request_start.is_null());
+  EXPECT_TRUE(load_timing_info.receive_headers_end.is_null());
+}
+
 class DeleteCacheCompletionCallback : public net::TestCompletionCallbackBase {
  public:
   explicit DeleteCacheCompletionCallback(MockHttpCache* cache)
       : cache_(cache),
         callback_(base::Bind(&DeleteCacheCompletionCallback::OnComplete,
                              base::Unretained(this))) {
   }
 
   const net::CompletionCallback& callback() const { return callback_; }
 
@@ skipping 71 matching lines @@
   std::string content;
   int rv = ReadTransaction(trans, &content);
 
   EXPECT_EQ(net::OK, rv);
   std::string expected(trans_info.data);
   EXPECT_EQ(expected, content);
 }
 
 const int kNoDelegateTransactionCheck = -1;
 
-void RunTransactionTestWithRequestAndLogAndDelegate(
+void RunTransactionTestWithRequestAndDelegateAndGetTiming(
     net::HttpCache* cache,
     const MockTransaction& trans_info,
     const MockHttpRequest& request,
     net::HttpResponseInfo* response_info,
+    int num_cache_delegate_actions,
+    int num_network_delegate_actions,
     const net::BoundNetLog& net_log,
-    int num_cache_delegate_actions,
-    int num_network_delegate_actions) {
+    net::LoadTimingInfo* load_timing_info) {
   net::TestCompletionCallback callback;
 
   // write to the cache
 
   scoped_ptr<TestHttpTransactionDelegate> delegate;
   if (num_cache_delegate_actions != kNoDelegateTransactionCheck &&
       num_network_delegate_actions != kNoDelegateTransactionCheck) {
     delegate.reset(
         new TestHttpTransactionDelegate(num_cache_delegate_actions,
                                         num_network_delegate_actions));
@@ skipping 11 matching lines @@
 
   if (net::OK != rv)
     return;
 
   const net::HttpResponseInfo* response = trans->GetResponseInfo();
   ASSERT_TRUE(response);
 
   if (response_info)
     *response_info = *response;
 
+  if (load_timing_info) {
+    // If a fake network connection is used, need a NetLog to get a fake socket
+    // ID.
+    EXPECT_TRUE(net_log.net_log());
+    *load_timing_info = net::LoadTimingInfo();
+    trans->GetLoadTimingInfo(load_timing_info);
+  }
+
   ReadAndVerifyTransaction(trans.get(), trans_info);
 }
 
+void RunTransactionTestWithRequestAndDelegate(
+    net::HttpCache* cache,
+    const MockTransaction& trans_info,
+    const MockHttpRequest& request,
+    net::HttpResponseInfo* response_info,
+    int num_cache_delegate_actions,
+    int num_network_delegate_actions) {
+  RunTransactionTestWithRequestAndDelegateAndGetTiming(
+      cache, trans_info, request, response_info, num_cache_delegate_actions,
+      num_network_delegate_actions, net::BoundNetLog(), NULL);
+}
+
 void RunTransactionTestWithRequest(net::HttpCache* cache,
                                    const MockTransaction& trans_info,
                                    const MockHttpRequest& request,
                                    net::HttpResponseInfo* response_info) {
-  RunTransactionTestWithRequestAndLogAndDelegate(
-      cache, trans_info, request, response_info, net::BoundNetLog(),
-      kNoDelegateTransactionCheck, kNoDelegateTransactionCheck);
+  RunTransactionTestWithRequestAndDelegate(
+      cache, trans_info, request, response_info, kNoDelegateTransactionCheck,
+      kNoDelegateTransactionCheck);
 }
 
-void RunTransactionTestWithLog(net::HttpCache* cache,
-                               const MockTransaction& trans_info,
-                               const net::BoundNetLog& log) {
-  RunTransactionTestWithRequestAndLogAndDelegate(
-      cache, trans_info, MockHttpRequest(trans_info), NULL, log,
-      kNoDelegateTransactionCheck, kNoDelegateTransactionCheck);
+void RunTransactionTestAndGetTiming(
+    net::HttpCache* cache,
+    const MockTransaction& trans_info,
+    const net::BoundNetLog& log,
+    net::LoadTimingInfo* load_timing_info) {
+  RunTransactionTestWithRequestAndDelegateAndGetTiming(
+      cache, trans_info, MockHttpRequest(trans_info), NULL,
+      kNoDelegateTransactionCheck, kNoDelegateTransactionCheck, log,
+      load_timing_info);
 }
 
 void RunTransactionTestWithDelegate(net::HttpCache* cache,
                                     const MockTransaction& trans_info,
                                     int num_cache_delegate_actions,
                                     int num_network_delegate_actions) {
-  RunTransactionTestWithRequestAndLogAndDelegate(
-      cache, trans_info, MockHttpRequest(trans_info), NULL, net::BoundNetLog(),
+  RunTransactionTestWithRequestAndDelegate(
+      cache, trans_info, MockHttpRequest(trans_info), NULL,
       num_cache_delegate_actions, num_network_delegate_actions);
 }
 
 void RunTransactionTest(net::HttpCache* cache,
                         const MockTransaction& trans_info) {
-  RunTransactionTestWithLog(cache, trans_info, net::BoundNetLog());
+  RunTransactionTestAndGetTiming(cache, trans_info, net::BoundNetLog(), NULL);
 }
 
 void RunTransactionTestWithResponseInfo(net::HttpCache* cache,
                                         const MockTransaction& trans_info,
                                         net::HttpResponseInfo* response) {
   RunTransactionTestWithRequest(
       cache, trans_info, MockHttpRequest(trans_info), response);
 }
 
+void RunTransactionTestWithResponseInfoAndGetTiming(
+    net::HttpCache* cache,
+    const MockTransaction& trans_info,
+    net::HttpResponseInfo* response,
+    const net::BoundNetLog& log,
+    net::LoadTimingInfo* load_timing_info) {
+  RunTransactionTestWithRequestAndDelegateAndGetTiming(
+      cache, trans_info, MockHttpRequest(trans_info), response,
+      kNoDelegateTransactionCheck, kNoDelegateTransactionCheck, log,
+      load_timing_info);
+}
+
 void RunTransactionTestWithResponse(net::HttpCache* cache,
                                     const MockTransaction& trans_info,
                                     std::string* response_headers) {
   net::HttpResponseInfo response;
   RunTransactionTestWithResponseInfo(cache, trans_info, &response);
   response.headers->GetNormalizedHeaders(response_headers);
 }
 
+void RunTransactionTestWithResponseAndGetTiming(
+    net::HttpCache* cache,
+    const MockTransaction& trans_info,
+    std::string* response_headers,
+    const net::BoundNetLog& log,
+    net::LoadTimingInfo* load_timing_info) {
+  net::HttpResponseInfo response;
+  RunTransactionTestWithRequestAndDelegateAndGetTiming(
+      cache, trans_info, MockHttpRequest(trans_info), &response,
+      kNoDelegateTransactionCheck, kNoDelegateTransactionCheck,
+      log, load_timing_info);
+  response.headers->GetNormalizedHeaders(response_headers);
+}
+
 // This class provides a handler for kFastNoStoreGET_Transaction so that the
 // no-store header can be included on demand.
 class FastTransactionServer {
  public:
   FastTransactionServer() {
     no_store = false;
   }
   ~FastTransactionServer() {}
 
   void set_no_store(bool value) { no_store = value; }
@@ skipping 272 matching lines @@
 
   disk_cache::Backend* backend;
   net::TestCompletionCallback cb;
   // This will lazily initialize the backend.
   int rv = cache.http_cache()->GetBackend(&backend, cb.callback());
   EXPECT_EQ(net::OK, cb.GetResult(rv));
 }
 
 TEST(HttpCache, SimpleGET) {
   MockHttpCache cache;
+  net::CapturingBoundNetLog log;
+  net::LoadTimingInfo load_timing_info;
 
-  // write to the cache
-  RunTransactionTest(cache.http_cache(), kSimpleGET_Transaction);
+  // Write to the cache.
+  RunTransactionTestAndGetTiming(cache.http_cache(), kSimpleGET_Transaction,
+                                 log.bound(), &load_timing_info);
 
   EXPECT_EQ(1, cache.network_layer()->transaction_count());
   EXPECT_EQ(0, cache.disk_cache()->open_count());
   EXPECT_EQ(1, cache.disk_cache()->create_count());
+  TestLoadTimingNetworkRequest(load_timing_info);
 }
 
 TEST(HttpCache, SimpleGETNoDiskCache) {
   MockHttpCache cache;
 
   cache.disk_cache()->set_fail_requests();
 
   net::CapturingBoundNetLog log;
   log.SetLogLevel(net::NetLog::LOG_BASIC);
+  net::LoadTimingInfo load_timing_info;
 
   // Read from the network, and don't use the cache.
-  RunTransactionTestWithLog(cache.http_cache(), kSimpleGET_Transaction,
-                            log.bound());
+  RunTransactionTestAndGetTiming(cache.http_cache(), kSimpleGET_Transaction,
+                                 log.bound(), &load_timing_info);
 
   // Check that the NetLog was filled as expected.
   // (We attempted to both Open and Create entries, but both failed).
   net::CapturingNetLog::CapturedEntryList entries;
   log.GetEntries(&entries);
 
   EXPECT_EQ(6u, entries.size());
   EXPECT_TRUE(net::LogContainsBeginEvent(
       entries, 0, net::NetLog::TYPE_HTTP_CACHE_GET_BACKEND));
   EXPECT_TRUE(net::LogContainsEndEvent(
       entries, 1, net::NetLog::TYPE_HTTP_CACHE_GET_BACKEND));
   EXPECT_TRUE(net::LogContainsBeginEvent(
       entries, 2, net::NetLog::TYPE_HTTP_CACHE_OPEN_ENTRY));
   EXPECT_TRUE(net::LogContainsEndEvent(
       entries, 3, net::NetLog::TYPE_HTTP_CACHE_OPEN_ENTRY));
   EXPECT_TRUE(net::LogContainsBeginEvent(
       entries, 4, net::NetLog::TYPE_HTTP_CACHE_CREATE_ENTRY));
   EXPECT_TRUE(net::LogContainsEndEvent(
       entries, 5, net::NetLog::TYPE_HTTP_CACHE_CREATE_ENTRY));
 
   EXPECT_EQ(1, cache.network_layer()->transaction_count());
   EXPECT_EQ(0, cache.disk_cache()->open_count());
   EXPECT_EQ(0, cache.disk_cache()->create_count());
+  TestLoadTimingNetworkRequest(load_timing_info);
 }
 
 TEST(HttpCache, SimpleGETNoDiskCache2) {
   // This will initialize a cache object with NULL backend.
   MockBlockingBackendFactory* factory = new MockBlockingBackendFactory();
   factory->set_fail(true);
   factory->FinishCreation();  // We'll complete synchronously.
   MockHttpCache cache(factory);
 
   // Read from the network, and don't use the cache.
@@ skipping 124 matching lines @@
 }
 
 TEST(HttpCache, SimpleGET_LoadOnlyFromCache_Hit) {
   MockHttpCache cache;
 
   net::CapturingBoundNetLog log;
 
   // This prevents a number of write events from being logged.
   log.SetLogLevel(net::NetLog::LOG_BASIC);
 
-  // write to the cache
-  RunTransactionTestWithLog(cache.http_cache(), kSimpleGET_Transaction,
-                            log.bound());
+  net::LoadTimingInfo load_timing_info;
+
+  // Write to the cache.
+  RunTransactionTestAndGetTiming(cache.http_cache(), kSimpleGET_Transaction,
+                                 log.bound(), &load_timing_info);
 
   // Check that the NetLog was filled as expected.
   net::CapturingNetLog::CapturedEntryList entries;
   log.GetEntries(&entries);
 
   EXPECT_EQ(8u, entries.size());
   EXPECT_TRUE(net::LogContainsBeginEvent(
       entries, 0, net::NetLog::TYPE_HTTP_CACHE_GET_BACKEND));
   EXPECT_TRUE(net::LogContainsEndEvent(
       entries, 1, net::NetLog::TYPE_HTTP_CACHE_GET_BACKEND));
   EXPECT_TRUE(net::LogContainsBeginEvent(
       entries, 2, net::NetLog::TYPE_HTTP_CACHE_OPEN_ENTRY));
   EXPECT_TRUE(net::LogContainsEndEvent(
       entries, 3, net::NetLog::TYPE_HTTP_CACHE_OPEN_ENTRY));
   EXPECT_TRUE(net::LogContainsBeginEvent(
       entries, 4, net::NetLog::TYPE_HTTP_CACHE_CREATE_ENTRY));
   EXPECT_TRUE(net::LogContainsEndEvent(
       entries, 5, net::NetLog::TYPE_HTTP_CACHE_CREATE_ENTRY));
   EXPECT_TRUE(net::LogContainsBeginEvent(
       entries, 6, net::NetLog::TYPE_HTTP_CACHE_ADD_TO_ENTRY));
   EXPECT_TRUE(net::LogContainsEndEvent(
       entries, 7, net::NetLog::TYPE_HTTP_CACHE_ADD_TO_ENTRY));
 
-  // force this transaction to read from the cache
+  TestLoadTimingNetworkRequest(load_timing_info);
+
+  // Force this transaction to read from the cache.
   MockTransaction transaction(kSimpleGET_Transaction);
   transaction.load_flags |= net::LOAD_ONLY_FROM_CACHE;
 
   log.Clear();
 
-  RunTransactionTestWithLog(cache.http_cache(), transaction, log.bound());
+  RunTransactionTestAndGetTiming(cache.http_cache(), transaction, log.bound(),
+                                 &load_timing_info);
 
   // Check that the NetLog was filled as expected.
   log.GetEntries(&entries);
 
   EXPECT_EQ(8u, entries.size());
   EXPECT_TRUE(net::LogContainsBeginEvent(
       entries, 0, net::NetLog::TYPE_HTTP_CACHE_GET_BACKEND));
   EXPECT_TRUE(net::LogContainsEndEvent(
       entries, 1, net::NetLog::TYPE_HTTP_CACHE_GET_BACKEND));
   EXPECT_TRUE(net::LogContainsBeginEvent(
       entries, 2, net::NetLog::TYPE_HTTP_CACHE_OPEN_ENTRY));
   EXPECT_TRUE(net::LogContainsEndEvent(
       entries, 3, net::NetLog::TYPE_HTTP_CACHE_OPEN_ENTRY));
   EXPECT_TRUE(net::LogContainsBeginEvent(
       entries, 4, net::NetLog::TYPE_HTTP_CACHE_ADD_TO_ENTRY));
   EXPECT_TRUE(net::LogContainsEndEvent(
       entries, 5, net::NetLog::TYPE_HTTP_CACHE_ADD_TO_ENTRY));
   EXPECT_TRUE(net::LogContainsBeginEvent(
       entries, 6, net::NetLog::TYPE_HTTP_CACHE_READ_INFO));
   EXPECT_TRUE(net::LogContainsEndEvent(
       entries, 7, net::NetLog::TYPE_HTTP_CACHE_READ_INFO));
 
   EXPECT_EQ(1, cache.network_layer()->transaction_count());
   EXPECT_EQ(1, cache.disk_cache()->open_count());
   EXPECT_EQ(1, cache.disk_cache()->create_count());
+  TestLoadTimingCachedResponse(load_timing_info);
 }
 
 TEST(HttpCache, SimpleGET_LoadOnlyFromCache_Miss) {
   MockHttpCache cache;
 
   // force this transaction to read from the cache
   MockTransaction transaction(kSimpleGET_Transaction);
   transaction.load_flags |= net::LOAD_ONLY_FROM_CACHE;
 
   MockHttpRequest request(transaction);
@@ skipping 79 matching lines @@
   transaction.request_headers = "Foo: bar\r\n";
   transaction.response_headers = "Cache-Control: max-age=10000\n"
                                  "Vary: Foo\n";
   AddMockTransaction(&transaction);
   RunTransactionTest(cache.http_cache(), transaction);
 
   // Attempt to read from the cache... this is a vary mismatch that must reach
   // the network again.
   transaction.load_flags |= net::LOAD_PREFERRING_CACHE;
   transaction.request_headers = "Foo: none\r\n";
-  RunTransactionTest(cache.http_cache(), transaction);
+  net::CapturingBoundNetLog log;
+  net::LoadTimingInfo load_timing_info;
+  RunTransactionTestAndGetTiming(cache.http_cache(), transaction, log.bound(),
+                                 &load_timing_info);
 
   EXPECT_EQ(2, cache.network_layer()->transaction_count());
   EXPECT_EQ(1, cache.disk_cache()->open_count());
   EXPECT_EQ(1, cache.disk_cache()->create_count());
+  TestLoadTimingNetworkRequest(load_timing_info);
   RemoveMockTransaction(&transaction);
 }
 
 // Tests that LOAD_FROM_CACHE_IF_OFFLINE returns proper response on
 // network success
 TEST(HttpCache, SimpleGET_CacheOverride_Network) {
   MockHttpCache cache;
 
   // Prime cache.
   MockTransaction transaction(kSimpleGET_Transaction);
@@ skipping 137 matching lines @@
   RunTransactionTest(cache.http_cache(), kSimpleGET_Transaction);
 
   // Force this transaction to write to the cache again.
   MockTransaction transaction(kSimpleGET_Transaction);
   transaction.load_flags |= net::LOAD_BYPASS_CACHE;
 
   net::CapturingBoundNetLog log;
 
   // This prevents a number of write events from being logged.
   log.SetLogLevel(net::NetLog::LOG_BASIC);
+  net::LoadTimingInfo load_timing_info;
 
-  RunTransactionTestWithLog(cache.http_cache(), transaction, log.bound());
+  // Write to the cache.
+  RunTransactionTestAndGetTiming(cache.http_cache(), transaction, log.bound(),
+                                 &load_timing_info);
 
   // Check that the NetLog was filled as expected.
   net::CapturingNetLog::CapturedEntryList entries;
   log.GetEntries(&entries);
 
   EXPECT_EQ(8u, entries.size());
   EXPECT_TRUE(net::LogContainsBeginEvent(
       entries, 0, net::NetLog::TYPE_HTTP_CACHE_GET_BACKEND));
   EXPECT_TRUE(net::LogContainsEndEvent(
       entries, 1, net::NetLog::TYPE_HTTP_CACHE_GET_BACKEND));
   EXPECT_TRUE(net::LogContainsBeginEvent(
       entries, 2, net::NetLog::TYPE_HTTP_CACHE_DOOM_ENTRY));
   EXPECT_TRUE(net::LogContainsEndEvent(
       entries, 3, net::NetLog::TYPE_HTTP_CACHE_DOOM_ENTRY));
   EXPECT_TRUE(net::LogContainsBeginEvent(
       entries, 4, net::NetLog::TYPE_HTTP_CACHE_CREATE_ENTRY));
   EXPECT_TRUE(net::LogContainsEndEvent(
       entries, 5, net::NetLog::TYPE_HTTP_CACHE_CREATE_ENTRY));
   EXPECT_TRUE(net::LogContainsBeginEvent(
       entries, 6, net::NetLog::TYPE_HTTP_CACHE_ADD_TO_ENTRY));
   EXPECT_TRUE(net::LogContainsEndEvent(
       entries, 7, net::NetLog::TYPE_HTTP_CACHE_ADD_TO_ENTRY));
 
   EXPECT_EQ(2, cache.network_layer()->transaction_count());
   EXPECT_EQ(0, cache.disk_cache()->open_count());
   EXPECT_EQ(2, cache.disk_cache()->create_count());
+  TestLoadTimingNetworkRequest(load_timing_info);
 }
 
 TEST(HttpCache, SimpleGET_LoadBypassCache_Implicit) {
   MockHttpCache cache;
 
   // write to the cache
   RunTransactionTest(cache.http_cache(), kSimpleGET_Transaction);
 
   // force this transaction to write to the cache again
   MockTransaction transaction(kSimpleGET_Transaction);
@@ skipping 19 matching lines @@
   RunTransactionTest(cache.http_cache(), transaction);
 
   EXPECT_EQ(2, cache.network_layer()->transaction_count());
   EXPECT_EQ(0, cache.disk_cache()->open_count());
   EXPECT_EQ(2, cache.disk_cache()->create_count());
 }
 
 TEST(HttpCache, SimpleGET_LoadValidateCache) {
   MockHttpCache cache;
 
-  // write to the cache
+  // Write to the cache.
   RunTransactionTest(cache.http_cache(), kSimpleGET_Transaction);
 
-  // read from the cache
+  // Read from the cache.
   RunTransactionTest(cache.http_cache(), kSimpleGET_Transaction);
 
-  // force this transaction to validate the cache
+  // Force this transaction to validate the cache.
   MockTransaction transaction(kSimpleGET_Transaction);
   transaction.load_flags |= net::LOAD_VALIDATE_CACHE;
 
   net::HttpResponseInfo response_info;
-  RunTransactionTestWithResponseInfo(cache.http_cache(), transaction,
-                                     &response_info);
+  net::CapturingBoundNetLog log;
+  net::LoadTimingInfo load_timing_info;
+  RunTransactionTestWithResponseInfoAndGetTiming(
+      cache.http_cache(), transaction, &response_info, log.bound(),
+      &load_timing_info);
 
   EXPECT_EQ(2, cache.network_layer()->transaction_count());
   EXPECT_EQ(1, cache.disk_cache()->open_count());
   EXPECT_EQ(1, cache.disk_cache()->create_count());
   EXPECT_TRUE(response_info.network_accessed);
+  TestLoadTimingNetworkRequest(load_timing_info);
 }
 
 TEST(HttpCache, SimpleGET_LoadValidateCache_Implicit) {
   MockHttpCache cache;
 
   // write to the cache
   RunTransactionTest(cache.http_cache(), kSimpleGET_Transaction);
 
   // read from the cache
   RunTransactionTest(cache.http_cache(), kSimpleGET_Transaction);
@@ skipping 748 matching lines @@
 TEST(HttpCache, TypicalGET_ConditionalRequest) {
   MockHttpCache cache;
 
   // write to the cache
   RunTransactionTest(cache.http_cache(), kTypicalGET_Transaction);
 
   EXPECT_EQ(1, cache.network_layer()->transaction_count());
   EXPECT_EQ(0, cache.disk_cache()->open_count());
   EXPECT_EQ(1, cache.disk_cache()->create_count());
 
-  // get the same URL again, but this time we expect it to result
+  // Get the same URL again, but this time we expect it to result

[gavinp, 2013/05/10 20:23:03]

Awesome!

[mmenke, 2013/05/10 20:44:00]

The fact that I capitalized Get, or the sheer number of tests I updated?

   // in a conditional request.
-  RunTransactionTest(cache.http_cache(), kTypicalGET_Transaction);
+  net::CapturingBoundNetLog log;
+  net::LoadTimingInfo load_timing_info;
+  RunTransactionTestAndGetTiming(cache.http_cache(), kTypicalGET_Transaction,
+                                 log.bound(), &load_timing_info);
 
   EXPECT_EQ(2, cache.network_layer()->transaction_count());
   EXPECT_EQ(1, cache.disk_cache()->open_count());
   EXPECT_EQ(1, cache.disk_cache()->create_count());
+  TestLoadTimingNetworkRequest(load_timing_info);
 }
 
 static void ETagGet_ConditionalRequest_Handler(
     const net::HttpRequestInfo* request,
     std::string* response_status,
     std::string* response_headers,
     std::string* response_data) {
   EXPECT_TRUE(
       request->extra_headers.HasHeader(net::HttpRequestHeaders::kIfNoneMatch));
   response_status->assign("HTTP/1.1 304 Not Modified");
   response_headers->assign(kETagGET_Transaction.response_headers);
   response_data->clear();
 }
 
 TEST(HttpCache, ETagGET_ConditionalRequest_304) {
   MockHttpCache cache;
 
   ScopedMockTransaction transaction(kETagGET_Transaction);
 
   // write to the cache
   RunTransactionTest(cache.http_cache(), transaction);
 
   EXPECT_EQ(1, cache.network_layer()->transaction_count());
   EXPECT_EQ(0, cache.disk_cache()->open_count());
   EXPECT_EQ(1, cache.disk_cache()->create_count());
 
-  // get the same URL again, but this time we expect it to result
+  // Get the same URL again, but this time we expect it to result
   // in a conditional request.
   transaction.load_flags = net::LOAD_VALIDATE_CACHE;
   transaction.handler = ETagGet_ConditionalRequest_Handler;
-  RunTransactionTest(cache.http_cache(), transaction);
+  net::CapturingBoundNetLog log;
+  net::LoadTimingInfo load_timing_info;
+  RunTransactionTestAndGetTiming(cache.http_cache(), transaction, log.bound(),
+                                 &load_timing_info);
 
   EXPECT_EQ(2, cache.network_layer()->transaction_count());
   EXPECT_EQ(1, cache.disk_cache()->open_count());
   EXPECT_EQ(1, cache.disk_cache()->create_count());
+  TestLoadTimingNetworkRequest(load_timing_info);
 }
 
 class RevalidationServer {
  public:
   RevalidationServer() {
     s_etag_used_ = false;
     s_last_modified_used_ = false;
   }
 
   bool EtagUsed() { return s_etag_used_; }
@@ skipping 46 matching lines @@
       "Last-Modified: Wed, 28 Nov 2007 00:40:09 GMT\n"
       "Etag: \"foopy\"\n"
       "Cache-Control: max-age=0\n"
       "Vary: Foo\n";
   AddMockTransaction(&transaction);
   RunTransactionTest(cache.http_cache(), transaction);
 
   // Read from the cache.
   RevalidationServer server;
   transaction.handler = server.Handler;
-  RunTransactionTest(cache.http_cache(), transaction);
+  net::CapturingBoundNetLog log;
+  net::LoadTimingInfo load_timing_info;
+  RunTransactionTestAndGetTiming(cache.http_cache(), transaction, log.bound(),
+                                 &load_timing_info);
 
   EXPECT_TRUE(server.EtagUsed());
   EXPECT_TRUE(server.LastModifiedUsed());
   EXPECT_EQ(2, cache.network_layer()->transaction_count());
   EXPECT_EQ(1, cache.disk_cache()->open_count());
   EXPECT_EQ(1, cache.disk_cache()->create_count());
+  TestLoadTimingNetworkRequest(load_timing_info);
   RemoveMockTransaction(&transaction);
 }
 
 // Tests revalidation after a vary mismatch if etag is present.
 TEST(HttpCache, SimpleGET_LoadValidateCache_VaryMismatch) {
   MockHttpCache cache;
 
   // Write to the cache.
   MockTransaction transaction(kTypicalGET_Transaction);
   transaction.request_headers = "Foo: bar\r\n";
   transaction.response_headers =
       "Date: Wed, 28 Nov 2007 09:40:09 GMT\n"
       "Last-Modified: Wed, 28 Nov 2007 00:40:09 GMT\n"
       "Etag: \"foopy\"\n"
       "Cache-Control: max-age=0\n"
       "Vary: Foo\n";
   AddMockTransaction(&transaction);
   RunTransactionTest(cache.http_cache(), transaction);
 
   // Read from the cache and revalidate the entry.
   RevalidationServer server;
   transaction.handler = server.Handler;
   transaction.request_headers = "Foo: none\r\n";
-  RunTransactionTest(cache.http_cache(), transaction);
+  net::CapturingBoundNetLog log;
+  net::LoadTimingInfo load_timing_info;
+  RunTransactionTestAndGetTiming(cache.http_cache(), transaction, log.bound(),
+                                 &load_timing_info);
 
   EXPECT_TRUE(server.EtagUsed());
   EXPECT_FALSE(server.LastModifiedUsed());
   EXPECT_EQ(2, cache.network_layer()->transaction_count());
   EXPECT_EQ(1, cache.disk_cache()->open_count());
   EXPECT_EQ(1, cache.disk_cache()->create_count());
+  TestLoadTimingNetworkRequest(load_timing_info);
   RemoveMockTransaction(&transaction);
 }
 
 // Tests lack of revalidation after a vary mismatch and no etag.
 TEST(HttpCache, SimpleGET_LoadDontValidateCache_VaryMismatch) {
   MockHttpCache cache;
 
   // Write to the cache.
   MockTransaction transaction(kTypicalGET_Transaction);
   transaction.request_headers = "Foo: bar\r\n";
   transaction.response_headers =
       "Date: Wed, 28 Nov 2007 09:40:09 GMT\n"
       "Last-Modified: Wed, 28 Nov 2007 00:40:09 GMT\n"
       "Cache-Control: max-age=0\n"
       "Vary: Foo\n";
   AddMockTransaction(&transaction);
   RunTransactionTest(cache.http_cache(), transaction);
 
   // Read from the cache and don't revalidate the entry.
   RevalidationServer server;
   transaction.handler = server.Handler;
   transaction.request_headers = "Foo: none\r\n";
-  RunTransactionTest(cache.http_cache(), transaction);
+  net::CapturingBoundNetLog log;
+  net::LoadTimingInfo load_timing_info;
+  RunTransactionTestAndGetTiming(cache.http_cache(), transaction, log.bound(),
+                                 &load_timing_info);
 
   EXPECT_FALSE(server.EtagUsed());
   EXPECT_FALSE(server.LastModifiedUsed());
   EXPECT_EQ(2, cache.network_layer()->transaction_count());
   EXPECT_EQ(1, cache.disk_cache()->open_count());
   EXPECT_EQ(1, cache.disk_cache()->create_count());
+  TestLoadTimingNetworkRequest(load_timing_info);
   RemoveMockTransaction(&transaction);
 }
 
 static void ETagGet_UnconditionalRequest_Handler(
     const net::HttpRequestInfo* request,
     std::string* response_status,
     std::string* response_headers,
     std::string* response_data) {
   EXPECT_FALSE(
       request->extra_headers.HasHeader(net::HttpRequestHeaders::kIfNoneMatch));
@@ skipping 1180 matching lines @@
   EXPECT_EQ(2, cache.network_layer()->transaction_count());
   EXPECT_EQ(2, cache.disk_cache()->open_count());
   EXPECT_EQ(1, cache.disk_cache()->create_count());
 
   // Make sure we are done with the previous transaction.
   MessageLoop::current()->RunUntilIdle();
 
   // Write and read from the cache (20-59).
   transaction.request_headers = "Range: bytes = 20-59\r\n" EXTRA_HEADER;
   transaction.data = "rg: 20-29 rg: 30-39 rg: 40-49 rg: 50-59 ";
-  RunTransactionTestWithResponse(cache.http_cache(), transaction, &headers);
+  net::CapturingBoundNetLog log;
+  net::LoadTimingInfo load_timing_info;
+  RunTransactionTestWithResponseAndGetTiming(
+      cache.http_cache(), transaction, &headers, log.bound(),
+      &load_timing_info);
 
   Verify206Response(headers, 20, 59);
+
   EXPECT_EQ(4, cache.network_layer()->transaction_count());
   EXPECT_EQ(3, cache.disk_cache()->open_count());
   EXPECT_EQ(1, cache.disk_cache()->create_count());
+  TestLoadTimingNetworkRequest(load_timing_info);
 
   RemoveMockTransaction(&kRangeGET_TransactionOK);
 }
 
 // Tests that we can cache range requests and fetch random blocks from the
 // cache and the network, with synchronous responses.
 TEST(HttpCache, RangeGET_SyncOK) {
   MockHttpCache cache;
 
   MockTransaction transaction(kRangeGET_TransactionOK);
@@ skipping 29 matching lines @@
   EXPECT_EQ(2, cache.network_layer()->transaction_count());
   EXPECT_EQ(1, cache.disk_cache()->open_count());
   EXPECT_EQ(1, cache.disk_cache()->create_count());
 
   // Make sure we are done with the previous transaction.
   MessageLoop::current()->RunUntilIdle();
 
   // Write and read from the cache (20-59).
   transaction.request_headers = "Range: bytes = 20-59\r\n" EXTRA_HEADER;
   transaction.data = "rg: 20-29 rg: 30-39 rg: 40-49 rg: 50-59 ";
-  RunTransactionTestWithResponse(cache.http_cache(), transaction, &headers);
+  net::CapturingBoundNetLog log;
+  net::LoadTimingInfo load_timing_info;
+  RunTransactionTestWithResponseAndGetTiming(
+      cache.http_cache(), transaction, &headers, log.bound(),
+      &load_timing_info);
 
   Verify206Response(headers, 20, 59);
   EXPECT_EQ(4, cache.network_layer()->transaction_count());
   EXPECT_EQ(2, cache.disk_cache()->open_count());
   EXPECT_EQ(1, cache.disk_cache()->create_count());
+  TestLoadTimingNetworkRequest(load_timing_info);
 
   RemoveMockTransaction(&transaction);
 }
 
 // Tests that we don't revalidate an entry unless we are required to do so.
 TEST(HttpCache, RangeGET_Revalidate1) {
   MockHttpCache cache;
   std::string headers;
 
   // Write to the cache (40-49).
   MockTransaction transaction(kRangeGET_TransactionOK);
   transaction.response_headers =
       "Last-Modified: Sat, 18 Apr 2009 01:10:43 GMT\n"
       "Expires: Wed, 7 Sep 2033 21:46:42 GMT\n"  // Should never expire.
       "ETag: \"foo\"\n"
       "Accept-Ranges: bytes\n"
       "Content-Length: 10\n";
   AddMockTransaction(&transaction);
   RunTransactionTestWithResponse(cache.http_cache(), transaction, &headers);
 
   Verify206Response(headers, 40, 49);
   EXPECT_EQ(1, cache.network_layer()->transaction_count());
   EXPECT_EQ(0, cache.disk_cache()->open_count());
   EXPECT_EQ(1, cache.disk_cache()->create_count());
 
   // Read from the cache (40-49).
-  RunTransactionTestWithResponse(cache.http_cache(), transaction, &headers);
+  net::CapturingBoundNetLog log;
+  net::LoadTimingInfo load_timing_info;
+  RunTransactionTestWithResponseAndGetTiming(
+      cache.http_cache(), transaction, &headers, log.bound(),
+      &load_timing_info);
+
   Verify206Response(headers, 40, 49);
-
   EXPECT_EQ(1, cache.network_layer()->transaction_count());
   EXPECT_EQ(1, cache.disk_cache()->open_count());
   EXPECT_EQ(1, cache.disk_cache()->create_count());
+  TestLoadTimingCachedResponse(load_timing_info);
 
   // Read again forcing the revalidation.
   transaction.load_flags |= net::LOAD_VALIDATE_CACHE;
-  RunTransactionTestWithResponse(cache.http_cache(), transaction, &headers);
+  RunTransactionTestWithResponseAndGetTiming(
+      cache.http_cache(), transaction, &headers, log.bound(),
+      &load_timing_info);
 
   Verify206Response(headers, 40, 49);
   EXPECT_EQ(2, cache.network_layer()->transaction_count());
   EXPECT_EQ(1, cache.disk_cache()->open_count());
   EXPECT_EQ(1, cache.disk_cache()->create_count());
+  TestLoadTimingNetworkRequest(load_timing_info);
 
   RemoveMockTransaction(&transaction);
 }
 
 // Checks that we revalidate an entry when the headers say so.
 TEST(HttpCache, RangeGET_Revalidate2) {
   MockHttpCache cache;
   std::string headers;
 
   // Write to the cache (40-49).
@@ skipping 214 matching lines @@
   EXPECT_EQ(2, cache.disk_cache()->create_count());
 
   RemoveMockTransaction(&transaction);
 }
 
 // Tests that we can handle non-range requests when we have cached a range.
 TEST(HttpCache, GET_Previous206) {
   MockHttpCache cache;
   AddMockTransaction(&kRangeGET_TransactionOK);
   std::string headers;
+  net::CapturingBoundNetLog log;
+  net::LoadTimingInfo load_timing_info;
 
   // Write to the cache (40-49).
-  RunTransactionTestWithResponse(cache.http_cache(), kRangeGET_TransactionOK,
-                                 &headers);
+  RunTransactionTestWithResponseAndGetTiming(
+      cache.http_cache(), kRangeGET_TransactionOK, &headers, log.bound(),
+      &load_timing_info);
 
   Verify206Response(headers, 40, 49);
+
   EXPECT_EQ(1, cache.network_layer()->transaction_count());
   EXPECT_EQ(0, cache.disk_cache()->open_count());
   EXPECT_EQ(1, cache.disk_cache()->create_count());
+  TestLoadTimingNetworkRequest(load_timing_info);
 
   // Write and read from the cache (0-79), when not asked for a range.
   MockTransaction transaction(kRangeGET_TransactionOK);
   transaction.request_headers = EXTRA_HEADER;
   transaction.data = "rg: 00-09 rg: 10-19 rg: 20-29 rg: 30-39 rg: 40-49 "
                      "rg: 50-59 rg: 60-69 rg: 70-79 ";
-  RunTransactionTestWithResponse(cache.http_cache(), transaction, &headers);
+  RunTransactionTestWithResponseAndGetTiming(
+      cache.http_cache(), transaction, &headers, log.bound(),
+      &load_timing_info);
 
   EXPECT_EQ(0U, headers.find("HTTP/1.1 200 OK\n"));
   EXPECT_EQ(3, cache.network_layer()->transaction_count());
   EXPECT_EQ(1, cache.disk_cache()->open_count());
   EXPECT_EQ(1, cache.disk_cache()->create_count());
+  TestLoadTimingNetworkRequest(load_timing_info);
 
   RemoveMockTransaction(&kRangeGET_TransactionOK);
 }
 
 // Tests that we can handle non-range requests when we have cached the first
 // part of the object and the server replies with 304 (Not Modified).
 TEST(HttpCache, GET_Previous206_NotModified) {
   MockHttpCache cache;
 
   MockTransaction transaction(kRangeGET_TransactionOK);
   AddMockTransaction(&transaction);
   std::string headers;
+  net::CapturingBoundNetLog log;
+  net::LoadTimingInfo load_timing_info;
 
   // Write to the cache (0-9).
   transaction.request_headers = "Range: bytes = 0-9\r\n" EXTRA_HEADER;
   transaction.data = "rg: 00-09 ";
-  RunTransactionTestWithResponse(cache.http_cache(), transaction, &headers);
+  RunTransactionTestWithResponseAndGetTiming(
+      cache.http_cache(), transaction, &headers, log.bound(),
+      &load_timing_info);
   Verify206Response(headers, 0, 9);
+  TestLoadTimingNetworkRequest(load_timing_info);
 
   // Write to the cache (70-79).
   transaction.request_headers = "Range: bytes = 70-79\r\n" EXTRA_HEADER;
   transaction.data = "rg: 70-79 ";
-  RunTransactionTestWithResponse(cache.http_cache(), transaction, &headers);
+  RunTransactionTestWithResponseAndGetTiming(
+      cache.http_cache(), transaction, &headers, log.bound(),
+      &load_timing_info);
   Verify206Response(headers, 70, 79);
 
   EXPECT_EQ(2, cache.network_layer()->transaction_count());
   EXPECT_EQ(1, cache.disk_cache()->open_count());
   EXPECT_EQ(1, cache.disk_cache()->create_count());
+  TestLoadTimingNetworkRequest(load_timing_info);
 
   // Read from the cache (0-9), write and read from cache (10 - 79).
   transaction.load_flags |= net::LOAD_VALIDATE_CACHE;
   transaction.request_headers = "Foo: bar\r\n" EXTRA_HEADER;
   transaction.data = "rg: 00-09 rg: 10-19 rg: 20-29 rg: 30-39 rg: 40-49 "
-                      "rg: 50-59 rg: 60-69 rg: 70-79 ";
-  RunTransactionTestWithResponse(cache.http_cache(), transaction, &headers);
+                     "rg: 50-59 rg: 60-69 rg: 70-79 ";
+  RunTransactionTestWithResponseAndGetTiming(
+      cache.http_cache(), transaction, &headers, log.bound(),
+      &load_timing_info);
 
   EXPECT_EQ(0U, headers.find("HTTP/1.1 200 OK\n"));
+
   EXPECT_EQ(4, cache.network_layer()->transaction_count());
   EXPECT_EQ(2, cache.disk_cache()->open_count());
   EXPECT_EQ(1, cache.disk_cache()->create_count());
+  TestLoadTimingNetworkRequest(load_timing_info);
 
   RemoveMockTransaction(&transaction);
 }
 
 // Tests that we can handle a regular request to a sparse entry, that results in
 // new content provided by the server (206).
 TEST(HttpCache, GET_Previous206_NewContent) {
   MockHttpCache cache;
   AddMockTransaction(&kRangeGET_TransactionOK);
   std::string headers;
@@ skipping 12 matching lines @@
   // Now we'll issue a request without any range that should result first in a
   // 206 (when revalidating), and then in a weird standard answer: the test
   // server will not modify the response so we'll get the default range... a
   // real server will answer with 200.
   MockTransaction transaction2(kRangeGET_TransactionOK);
   transaction2.request_headers = EXTRA_HEADER;
   transaction2.load_flags |= net::LOAD_VALIDATE_CACHE;
   transaction2.data = "Not a range";
   RangeTransactionServer handler;
   handler.set_modified(true);
-  RunTransactionTestWithResponse(cache.http_cache(), transaction2, &headers);
+  net::CapturingBoundNetLog log;
+  net::LoadTimingInfo load_timing_info;
+  RunTransactionTestWithResponseAndGetTiming(
+      cache.http_cache(), transaction2, &headers, log.bound(),
+      &load_timing_info);
 
   EXPECT_EQ(0U, headers.find("HTTP/1.1 200 OK\n"));
   EXPECT_EQ(3, cache.network_layer()->transaction_count());
   EXPECT_EQ(1, cache.disk_cache()->open_count());
   EXPECT_EQ(1, cache.disk_cache()->create_count());
+  TestLoadTimingNetworkRequest(load_timing_info);
 
   // Verify that the previous request deleted the entry.
   RunTransactionTest(cache.http_cache(), transaction);
   EXPECT_EQ(2, cache.disk_cache()->create_count());
 
   RemoveMockTransaction(&transaction);
 }
 
 // Tests that we can handle cached 206 responses that are not sparse.
 TEST(HttpCache, GET_Previous206_NotSparse) {
@@ skipping 17 matching lines @@
   scoped_refptr<net::IOBuffer> buf(new net::IOBuffer(500));
   int len = static_cast<int>(base::strlcpy(buf->data(),
                                            kRangeGET_TransactionOK.data, 500));
   net::TestCompletionCallback cb;
   int rv = entry->WriteData(1, 0, buf, len, cb.callback(), true);
   EXPECT_EQ(len, cb.GetResult(rv));
   entry->Close();
 
   // Now see that we don't use the stored entry.
   std::string headers;
-  RunTransactionTestWithResponse(cache.http_cache(), kSimpleGET_Transaction,
-                                 &headers);
+  net::CapturingBoundNetLog log;
+  net::LoadTimingInfo load_timing_info;
+  RunTransactionTestWithResponseAndGetTiming(
+      cache.http_cache(), kSimpleGET_Transaction, &headers, log.bound(),
+      &load_timing_info);
 
   // We are expecting a 200.
   std::string expected_headers(kSimpleGET_Transaction.status);
   expected_headers.append("\n");
   expected_headers.append(kSimpleGET_Transaction.response_headers);
   EXPECT_EQ(expected_headers, headers);
   EXPECT_EQ(1, cache.network_layer()->transaction_count());
   EXPECT_EQ(1, cache.disk_cache()->open_count());
   EXPECT_EQ(2, cache.disk_cache()->create_count());
+  TestLoadTimingNetworkRequest(load_timing_info);
 }
 
 // Tests that we can handle cached 206 responses that are not sparse. This time
 // we issue a range request and expect to receive a range.
 TEST(HttpCache, RangeGET_Previous206_NotSparse_2) {
   MockHttpCache cache;
   AddMockTransaction(&kRangeGET_TransactionOK);
 
   // Create a disk cache entry that stores 206 headers while not being sparse.
   disk_cache::Entry* entry;
@@ skipping 2063 matching lines @@
   trans->SetPriority(net::HIGHEST);
   // Should trigger a new network transaction and pick up the new
   // priority.
   ReadAndVerifyTransaction(trans.get(), transaction);
 
   EXPECT_EQ(net::HIGHEST,
             cache.network_layer()->last_create_transaction_priority());
 
   RemoveMockTransaction(&kRangeGET_TransactionOK);
 }