Add some trace-points to HttpCache for request profiling (cache entry "open",...

net/http/http_cache_unittest.cc

 // Copyright (c) 2006-2009 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/hash_tables.h"
 #include "base/message_loop.h"
 #include "base/string_util.h"
 #include "net/base/net_errors.h"
 #include "net/base/load_flags.h"
+#include "net/base/load_log_unittest.h"
 #include "net/base/ssl_cert_request_info.h"
 #include "net/disk_cache/disk_cache.h"
 #include "net/http/http_byte_range.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_unittest.h"
 #include "net/http/http_util.h"
 #include "testing/gtest/include/gtest/gtest.h"
@@ skipping 355 matching lines @@
 void ReadAndVerifyTransaction(net::HttpTransaction* trans,
                               const MockTransaction& trans_info) {
   std::string content;
   int rv = ReadTransaction(trans, &content);
 
   EXPECT_EQ(net::OK, rv);
   std::string expected(trans_info.data);
   EXPECT_EQ(expected, content);
 }
 
-void RunTransactionTestWithRequest(net::HttpCache* cache,
-                                   const MockTransaction& trans_info,
-                                   const MockHttpRequest& request,
-                                   net::HttpResponseInfo* response_info) {
+void RunTransactionTestWithRequestAndLog(net::HttpCache* cache,
+                                         const MockTransaction& trans_info,
+                                         const MockHttpRequest& request,
+                                         net::HttpResponseInfo* response_info,
+                                         net::LoadLog* load_log) {
   TestCompletionCallback callback;
 
   // write to the cache
 
   scoped_ptr<net::HttpTransaction> trans(cache->CreateTransaction());
   ASSERT_TRUE(trans.get());
 
-  int rv = trans->Start(&request, &callback, NULL);
+  int rv = trans->Start(&request, &callback, load_log);
   if (rv == net::ERR_IO_PENDING)
     rv = callback.WaitForResult();
   ASSERT_EQ(net::OK, rv);
 
   const net::HttpResponseInfo* response = trans->GetResponseInfo();
   ASSERT_TRUE(response);
 
   if (response_info)
     *response_info = *response;
 
   ReadAndVerifyTransaction(trans.get(), trans_info);
 }
 
+void RunTransactionTestWithRequest(net::HttpCache* cache,
+                                   const MockTransaction& trans_info,
+                                   const MockHttpRequest& request,
+                                   net::HttpResponseInfo* response_info) {
+  RunTransactionTestWithRequestAndLog(cache, trans_info, request,
+                                      response_info, NULL);
+}
+
+void RunTransactionTestWithLog(net::HttpCache* cache,
+                               const MockTransaction& trans_info,
+                               net::LoadLog* log) {
+  RunTransactionTestWithRequestAndLog(
+      cache, trans_info, MockHttpRequest(trans_info), NULL, log);
+}
+
 void RunTransactionTest(net::HttpCache* cache,
                         const MockTransaction& trans_info) {
-  RunTransactionTestWithRequest(
-      cache, trans_info, MockHttpRequest(trans_info), NULL);
+  RunTransactionTestWithLog(cache, trans_info, NULL);
 }
 
 void RunTransactionTestWithResponseInfo(net::HttpCache* cache,
                                         const MockTransaction& trans_info,
                                         net::HttpResponseInfo* response) {
   RunTransactionTestWithRequest(
       cache, trans_info, MockHttpRequest(trans_info), response);
 }
 
 void RunTransactionTestWithResponse(net::HttpCache* cache,
@@ skipping 223 matching lines @@
   EXPECT_EQ(1, cache.network_layer()->transaction_count());
   EXPECT_EQ(0, cache.disk_cache()->open_count());
   EXPECT_EQ(1, cache.disk_cache()->create_count());
 }
 
 TEST(HttpCache, SimpleGETNoDiskCache) {
   MockHttpCache cache;
 
   cache.disk_cache()->set_fail_requests();
 
+  scoped_refptr<net::LoadLog> log(new net::LoadLog);
+
   // Read from the network, and don't use the cache.
-  RunTransactionTest(cache.http_cache(), kSimpleGET_Transaction);
+  RunTransactionTestWithLog(cache.http_cache(), kSimpleGET_Transaction, log);
+
+  // Check that the LoadLog was filled as expected.
+  // (We attempted to both Open and Create entries, but both failed).
+  EXPECT_EQ(4u, log->events().size());
+  net::ExpectLogContains(log, 0, net::LoadLog::TYPE_HTTP_CACHE_OPEN_ENTRY,
+                         net::LoadLog::PHASE_BEGIN);
+  net::ExpectLogContains(log, 1, net::LoadLog::TYPE_HTTP_CACHE_OPEN_ENTRY,
+                         net::LoadLog::PHASE_END);
+  net::ExpectLogContains(log, 2, net::LoadLog::TYPE_HTTP_CACHE_CREATE_ENTRY,
+                         net::LoadLog::PHASE_BEGIN);
+  net::ExpectLogContains(log, 3, net::LoadLog::TYPE_HTTP_CACHE_CREATE_ENTRY,
+                         net::LoadLog::PHASE_END);
 
   EXPECT_EQ(1, cache.network_layer()->transaction_count());
   EXPECT_EQ(0, cache.disk_cache()->open_count());
   EXPECT_EQ(0, cache.disk_cache()->create_count());
 }
 
 TEST(HttpCache, SimpleGETWithDiskFailures) {
   MockHttpCache cache;
 
   cache.disk_cache()->set_soft_failures(true);
 
   // Read from the network, and fail to write to the cache.
   RunTransactionTest(cache.http_cache(), kSimpleGET_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());
 
   // This one should see an empty cache again.
   RunTransactionTest(cache.http_cache(), kSimpleGET_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_LoadOnlyFromCache_Hit) {
   MockHttpCache cache;
 
+  scoped_refptr<net::LoadLog> log(new net::LoadLog);
+
   // write to the cache
-  RunTransactionTest(cache.http_cache(), kSimpleGET_Transaction);
+  RunTransactionTestWithLog(cache.http_cache(), kSimpleGET_Transaction, log);
+
+  // Check that the LoadLog was filled as expected.
+  EXPECT_EQ(6u, log->events().size());
+  net::ExpectLogContains(log, 0, net::LoadLog::TYPE_HTTP_CACHE_OPEN_ENTRY,
+                         net::LoadLog::PHASE_BEGIN);
+  net::ExpectLogContains(log, 1, net::LoadLog::TYPE_HTTP_CACHE_OPEN_ENTRY,
+                         net::LoadLog::PHASE_END);
+  net::ExpectLogContains(log, 2, net::LoadLog::TYPE_HTTP_CACHE_CREATE_ENTRY,
+                         net::LoadLog::PHASE_BEGIN);
+  net::ExpectLogContains(log, 3, net::LoadLog::TYPE_HTTP_CACHE_CREATE_ENTRY,
+                         net::LoadLog::PHASE_END);
+  net::ExpectLogContains(log, 4, net::LoadLog::TYPE_HTTP_CACHE_WAITING,
+                         net::LoadLog::PHASE_BEGIN);
+  net::ExpectLogContains(log, 5, net::LoadLog::TYPE_HTTP_CACHE_WAITING,
+                         net::LoadLog::PHASE_END);
 
   // force this transaction to read from the cache
   MockTransaction transaction(kSimpleGET_Transaction);
   transaction.load_flags |= net::LOAD_ONLY_FROM_CACHE;
 
-  RunTransactionTest(cache.http_cache(), transaction);
+  log = new net::LoadLog;
+
+  RunTransactionTestWithLog(cache.http_cache(), transaction, log);
+
+  // Check that the LoadLog was filled as expected.
+  EXPECT_EQ(6u, log->events().size());
+  net::ExpectLogContains(log, 0, net::LoadLog::TYPE_HTTP_CACHE_OPEN_ENTRY,
+                         net::LoadLog::PHASE_BEGIN);
+  net::ExpectLogContains(log, 1, net::LoadLog::TYPE_HTTP_CACHE_OPEN_ENTRY,
+                         net::LoadLog::PHASE_END);
+  net::ExpectLogContains(log, 2, net::LoadLog::TYPE_HTTP_CACHE_WAITING,
+                         net::LoadLog::PHASE_BEGIN);
+  net::ExpectLogContains(log, 3, net::LoadLog::TYPE_HTTP_CACHE_WAITING,
+                         net::LoadLog::PHASE_END);
+  net::ExpectLogContains(log, 4, net::LoadLog::TYPE_HTTP_CACHE_READ_INFO,
+                         net::LoadLog::PHASE_BEGIN);
+  net::ExpectLogContains(log, 5, net::LoadLog::TYPE_HTTP_CACHE_READ_INFO,
+                         net::LoadLog::PHASE_END);
 
   EXPECT_EQ(1, cache.network_layer()->transaction_count());
   EXPECT_EQ(1, cache.disk_cache()->open_count());
   EXPECT_EQ(1, cache.disk_cache()->create_count());
 }
 
 TEST(HttpCache, SimpleGET_LoadOnlyFromCache_Miss) {
   MockHttpCache cache;
 
   // force this transaction to read from the cache
@@ skipping 2044 matching lines @@
   std::string headers;
   response.headers->GetNormalizedHeaders(&headers);
 
   EXPECT_EQ("HTTP/1.1 200 OK\n"
             "Date: Wed, 22 Jul 2009 03:15:26 GMT\n"
             "Last-Modified: Wed, 06 Feb 2008 22:38:21 GMT\n",
             headers);
 
   RemoveMockTransaction(&mock_network_response);
 }