Add some trace-points to HttpCache for request profiling (cache entry "open", "create", "waiting" and "read_info").

BUG=http://crbug.com/14478
TEST=HttpCache unittests.

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

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

3 files changed, 107 insertions, 13 deletions

diff --git a/net/base/load_log_event_type_list.h b/net/base/load_log_event_type_list.h
index 28cfc03..46d52de 100644
--- a/net/base/load_log_event_type_list.h
+++ b/net/base/load_log_event_type_list.h
@@ -95,3 +95,21 @@ EVENT_TYPE(SOCKET_POOL_STALLED_MAX_SOCKETS_PER_GROUP)
 // URLRequest::ResponseStarted().
 EVENT_TYPE(URL_REQUEST_START)
 
+// ------------------------------------------------------------------------
+// HttpCache
+// ------------------------------------------------------------------------
+
+// Measures the time while opening a disk cache entry.
+EVENT_TYPE(HTTP_CACHE_OPEN_ENTRY)
+
+// Measures the time while creating a disk cache entry.
+EVENT_TYPE(HTTP_CACHE_CREATE_ENTRY)
+
+// Measures the time while reading the response info from a disk cache entry.
+EVENT_TYPE(HTTP_CACHE_READ_INFO)
+
+// Measures the time that an HttpCache::Transaction is stalled waiting for
+// the cache entry to become available (for example if we are waiting for
+// exclusive access to an existing entry).
+EVENT_TYPE(HTTP_CACHE_WAITING)
+
diff --git a/net/http/http_cache.cc b/net/http/http_cache.cc
index 855c7e8..35d51478 100644
--- a/net/http/http_cache.cc
+++ b/net/http/http_cache.cc
@@ -20,6 +20,7 @@
 #include "base/time.h"
 #include "net/base/io_buffer.h"
 #include "net/base/load_flags.h"
+#include "net/base/load_log.h"
 #include "net/base/net_errors.h"
 #include "net/base/ssl_cert_request_info.h"
 #include "net/disk_cache/disk_cache.h"
@@ -635,7 +636,9 @@ int HttpCache::Transaction::AddToEntry() {
   } else {
     entry = cache_->FindActiveEntry(cache_key_);
     if (!entry) {
+      LoadLog::BeginEvent(load_log_, LoadLog::TYPE_HTTP_CACHE_OPEN_ENTRY);
       entry = cache_->OpenEntry(cache_key_);
+      LoadLog::EndEvent(load_log_, LoadLog::TYPE_HTTP_CACHE_OPEN_ENTRY);
       if (!entry) {
         if (mode_ == READ_WRITE) {
           mode_ = WRITE;
@@ -657,7 +660,9 @@ int HttpCache::Transaction::AddToEntry() {
 
   if (mode_ == WRITE) {
     DCHECK(!entry);
+    LoadLog::BeginEvent(load_log_, LoadLog::TYPE_HTTP_CACHE_CREATE_ENTRY);
     entry = cache_->CreateEntry(cache_key_);
+    LoadLog::EndEvent(load_log_, LoadLog::TYPE_HTTP_CACHE_CREATE_ENTRY);
     if (!entry) {
       DLOG(WARNING) << "unable to create cache entry";
       mode_ = NONE;
@@ -665,10 +670,14 @@ int HttpCache::Transaction::AddToEntry() {
     }
   }
 
+
+  LoadLog::BeginEvent(load_log_, LoadLog::TYPE_HTTP_CACHE_WAITING);
   return cache_->AddTransactionToEntry(entry, this);
 }
 
 int HttpCache::Transaction::EntryAvailable(ActiveEntry* entry) {
+  LoadLog::EndEvent(load_log_, LoadLog::TYPE_HTTP_CACHE_WAITING);
+
   // We now have access to the cache entry.
   //
   //  o if we are the writer for the transaction, then we can start the network
@@ -1273,9 +1282,12 @@ int HttpCache::Transaction::ReadFromEntry(IOBuffer* data, int data_len) {
 int HttpCache::Transaction::ReadResponseInfoFromEntry() {
   DCHECK(entry_);
 
-  if (!HttpCache::ReadResponseInfo(entry_->disk_entry, &response_, &truncated_))
-    return ERR_CACHE_READ_FAILURE;
-  return OK;
+  LoadLog::BeginEvent(load_log_, LoadLog::TYPE_HTTP_CACHE_READ_INFO);
+  bool read_ok =
+      HttpCache::ReadResponseInfo(entry_->disk_entry, &response_, &truncated_);
+  LoadLog::EndEvent(load_log_, LoadLog::TYPE_HTTP_CACHE_READ_INFO);
+
+  return read_ok ? OK : ERR_CACHE_READ_FAILURE;
 }
 
 void HttpCache::Transaction::WriteToEntry(int index, int offset,
diff --git a/net/http/http_cache_unittest.cc b/net/http/http_cache_unittest.cc
index 674d8fd..f2acda9 100644
--- a/net/http/http_cache_unittest.cc
+++ b/net/http/http_cache_unittest.cc
@@ -9,6 +9,7 @@
 #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"
@@ -384,10 +385,11 @@ void ReadAndVerifyTransaction(net::HttpTransaction* trans,
   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
@@ -395,7 +397,7 @@ void RunTransactionTestWithRequest(net::HttpCache* 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);
@@ -409,10 +411,24 @@ void RunTransactionTestWithRequest(net::HttpCache* cache,
   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,
@@ -656,8 +672,22 @@ TEST(HttpCache, SimpleGETNoDiskCache) {
 
   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());
@@ -687,14 +717,48 @@ TEST(HttpCache, SimpleGETWithDiskFailures) {
 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());