First pass at adding http/backend cache to NetLog

net/http/http_cache_transaction.cc

 // Copyright (c) 2010 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_transaction.h"
 
 #include "build/build_config.h"
 
 #if defined(OS_POSIX)
 #include <unistd.h>
 #endif
 
 #include <string>
 
 #include "base/compiler_specific.h"
 #include "base/metrics/field_trial.h"
 #include "base/metrics/histogram.h"
 #include "base/ref_counted.h"
 #include "base/string_util.h"
 #include "base/time.h"
+#include "base/values.h"
 #include "net/base/cert_status_flags.h"
 #include "net/base/io_buffer.h"
 #include "net/base/load_flags.h"
 #include "net/base/net_errors.h"
 #include "net/base/net_log.h"
 #include "net/base/ssl_cert_request_info.h"
 #include "net/base/ssl_config_service.h"
 #include "net/disk_cache/disk_cache.h"
 #include "net/http/disk_cache_based_ssl_host_info.h"
 #include "net/http/http_request_info.h"
@@ skipping 347 matching lines @@
 }
 
 LoadState HttpCache::Transaction::GetWriterLoadState() const {
   if (network_trans_.get())
     return network_trans_->GetLoadState();
   if (entry_ || !request_)
     return LOAD_STATE_IDLE;
   return LOAD_STATE_WAITING_FOR_CACHE;
 }
 
+const BoundNetLog& HttpCache::Transaction::net_log() const {
+  return net_log_;
+}
+
 //-----------------------------------------------------------------------------
 
 void HttpCache::Transaction::DoCallback(int rv) {
   DCHECK(rv != ERR_IO_PENDING);
   DCHECK(callback_);
 
   // Since Run may result in Read being called, clear callback_ up front.
   CompletionCallback* c = callback_;
   callback_ = NULL;
   c->Run(rv);
@@ skipping 161 matching lines @@
 
   if (rv != ERR_IO_PENDING)
     HandleResult(rv);
 
   return rv;
 }
 
 int HttpCache::Transaction::DoGetBackend() {
   cache_pending_ = true;
   next_state_ = STATE_GET_BACKEND_COMPLETE;
-  net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_WAITING, NULL);
+  net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_GET_BACKEND, NULL);
   return cache_->GetBackendForTransaction(this);
 }
 
 int HttpCache::Transaction::DoGetBackendComplete(int result) {
   DCHECK(result == OK || result == ERR_FAILED);
-  net_log_.EndEvent(NetLog::TYPE_HTTP_CACHE_WAITING, NULL);
+  net_log_.EndEventWithErrorCode(NetLog::TYPE_HTTP_CACHE_GET_BACKEND, result);
   cache_pending_ = false;
 
   if (!ShouldPassThrough()) {
     cache_key_ = cache_->GenerateCacheKey(request_);
 
     // Requested cache access mode.
     if (effective_load_flags_ & LOAD_ONLY_FROM_CACHE) {
       mode_ = READ;
     } else if (effective_load_flags_ & LOAD_BYPASS_CACHE) {
       mode_ = WRITE;
@@ skipping 153 matching lines @@
   next_state_ = STATE_OPEN_ENTRY_COMPLETE;
   cache_pending_ = true;
   net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_OPEN_ENTRY, NULL);
   return cache_->OpenEntry(cache_key_, &new_entry_, this);
 }
 
 int HttpCache::Transaction::DoOpenEntryComplete(int result) {
   // It is important that we go to STATE_ADD_TO_ENTRY whenever the result is
   // OK, otherwise the cache will end up with an active entry without any
   // transaction attached.
-  net_log_.EndEvent(NetLog::TYPE_HTTP_CACHE_OPEN_ENTRY, NULL);
+  net_log_.EndEventWithErrorCode(NetLog::TYPE_HTTP_CACHE_OPEN_ENTRY, result);
   cache_pending_ = false;
   if (result == OK) {
     next_state_ = STATE_ADD_TO_ENTRY;
     return OK;
   }
 
   if (result == ERR_CACHE_RACE) {
     next_state_ = STATE_INIT_ENTRY;
     return OK;
   }
@@ skipping 22 matching lines @@
   next_state_ = STATE_CREATE_ENTRY_COMPLETE;
   cache_pending_ = true;
   net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_CREATE_ENTRY, NULL);
   return cache_->CreateEntry(cache_key_, &new_entry_, this);
 }
 
 int HttpCache::Transaction::DoCreateEntryComplete(int result) {
   // It is important that we go to STATE_ADD_TO_ENTRY whenever the result is
   // OK, otherwise the cache will end up with an active entry without any
   // transaction attached.
-  net_log_.EndEvent(NetLog::TYPE_HTTP_CACHE_CREATE_ENTRY, NULL);
+  net_log_.EndEventWithErrorCode(NetLog::TYPE_HTTP_CACHE_CREATE_ENTRY, result);
   cache_pending_ = false;
   next_state_ = STATE_ADD_TO_ENTRY;
 
   if (result == ERR_CACHE_RACE) {
     next_state_ = STATE_INIT_ENTRY;
     return OK;
   }
 
   if (result != OK) {
     // We have a race here: Maybe we failed to open the entry and decided to
@@ skipping 10 matching lines @@
 }
 
 int HttpCache::Transaction::DoDoomEntry() {
   next_state_ = STATE_DOOM_ENTRY_COMPLETE;
   cache_pending_ = true;
   net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_DOOM_ENTRY, NULL);
   return cache_->DoomEntry(cache_key_, this);
 }
 
 int HttpCache::Transaction::DoDoomEntryComplete(int result) {
-  net_log_.EndEvent(NetLog::TYPE_HTTP_CACHE_DOOM_ENTRY, NULL);
+  net_log_.EndEventWithErrorCode(NetLog::TYPE_HTTP_CACHE_DOOM_ENTRY, result);
   next_state_ = STATE_CREATE_ENTRY;
   cache_pending_ = false;
   if (result == ERR_CACHE_RACE)
     next_state_ = STATE_INIT_ENTRY;
 
   return OK;
 }
 
 int HttpCache::Transaction::DoAddToEntry() {
   DCHECK(new_entry_);
   cache_pending_ = true;
   next_state_ = STATE_ADD_TO_ENTRY_COMPLETE;
-  net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_WAITING, NULL);
+  net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_ADD_TO_ENTRY,
+                      new NetLogSourceParameter("source_dependency",
+                                                new_entry_->net_log.source()));
   DCHECK(entry_lock_waiting_since_.is_null());
   entry_lock_waiting_since_ = base::TimeTicks::Now();
   return cache_->AddTransactionToEntry(new_entry_, this);
 }
 
 int HttpCache::Transaction::DoAddToEntryComplete(int result) {
-  net_log_.EndEvent(NetLog::TYPE_HTTP_CACHE_WAITING, NULL);
-
+  net_log_.EndEventWithErrorCode(NetLog::TYPE_HTTP_CACHE_ADD_TO_ENTRY, result);
   const base::TimeDelta entry_lock_wait =
       base::TimeTicks::Now() - entry_lock_waiting_since_;
   UMA_HISTOGRAM_TIMES("HttpCache.EntryLockWait", entry_lock_wait);
   static const bool prefetching_fieldtrial =
       base::FieldTrialList::Find("Prefetch") &&
       !base::FieldTrialList::Find("Prefetch")->group_name().empty();
   if (prefetching_fieldtrial) {
     UMA_HISTOGRAM_TIMES(
         base::FieldTrial::MakeName("HttpCache.EntryLockWait", "Prefetch"),
         entry_lock_wait);
@@ skipping 129 matching lines @@
   next_state_ = truncated_ ? STATE_CACHE_WRITE_TRUNCATED_RESPONSE :
                              STATE_CACHE_WRITE_RESPONSE;
   return OK;
 }
 
 int HttpCache::Transaction::DoTruncateCachedData() {
   next_state_ = STATE_TRUNCATE_CACHED_DATA_COMPLETE;
   cache_callback_->AddRef();  // Balanced in DoTruncateCachedDataComplete.
   if (!entry_)
     return OK;
+  if (net_log_.IsLoggingAllEvents())
+    net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_WRITE_DATA, NULL);
 
   // Truncate the stream.
   return WriteToEntry(kResponseContentIndex, 0, NULL, 0, cache_callback_);
 }
 
 int HttpCache::Transaction::DoTruncateCachedDataComplete(int result) {
+  if (net_log_.IsLoggingAllEvents() && entry_)
+    net_log_.EndEventWithErrorCode(NetLog::TYPE_HTTP_CACHE_WRITE_DATA, result);
+
   // Balance the AddRef from DoTruncateCachedData.
   cache_callback_->Release();
   next_state_ = STATE_TRUNCATE_CACHED_METADATA;
   return OK;
 }
 
 int HttpCache::Transaction::DoTruncateCachedMetadata() {
   next_state_ = STATE_TRUNCATE_CACHED_METADATA_COMPLETE;
   cache_callback_->AddRef();  // Balanced in DoTruncateCachedMetadataComplete.
   if (!entry_)
     return OK;
 
+  if (net_log_.IsLoggingAllEvents())
+    net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_WRITE_INFO, NULL);

[rvargas (doing something else), 2010/12/11 00:29:01]

This one is most likely redundant.

   return WriteToEntry(kMetadataIndex, 0, NULL, 0, cache_callback_);
 }
 
 int HttpCache::Transaction::DoTruncateCachedMetadataComplete(int result) {
+  if (net_log_.IsLoggingAllEvents() && entry_)
+    net_log_.EndEventWithErrorCode(NetLog::TYPE_HTTP_CACHE_WRITE_INFO, result);
+
   // Balance the AddRef from DoTruncateCachedMetadata.
   cache_callback_->Release();
 
   // If this response is a redirect, then we can stop writing now.  (We don't
   // need to cache the response body of a redirect.)
   if (response_.headers->IsRedirect(NULL))
     DoneWritingToEntry(true);
   next_state_ = STATE_PARTIAL_HEADERS_RECEIVED;
   return OK;
 }
@@ skipping 29 matching lines @@
   read_buf_ = new IOBuffer(io_buf_len_);
 
   net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_READ_INFO, NULL);
   cache_callback_->AddRef();  // Balanced in DoCacheReadResponseComplete.
   return entry_->disk_entry->ReadData(kResponseInfoIndex, 0, read_buf_,
                                       io_buf_len_, cache_callback_);
 }
 
 int HttpCache::Transaction::DoCacheReadResponseComplete(int result) {
   cache_callback_->Release();  // Balance the AddRef from DoCacheReadResponse.
-  net_log_.EndEvent(NetLog::TYPE_HTTP_CACHE_READ_INFO, NULL);
+  net_log_.EndEventWithErrorCode(NetLog::TYPE_HTTP_CACHE_READ_INFO, result);
   if (result != io_buf_len_ ||
       !HttpCache::ParseResponseInfo(read_buf_->data(), io_buf_len_,
                                     &response_, &truncated_)) {
     DLOG(ERROR) << "ReadData failed: " << result;
     return ERR_CACHE_READ_FAILURE;
   }
 
   // We now have access to the cache entry.
   //
   //  o if we are a reader for the transaction, then we can start reading the
@@ skipping 19 matching lines @@
       break;
     case WRITE:
     default:
       NOTREACHED();
       result = ERR_FAILED;
   }
   return result;
 }
 
 int HttpCache::Transaction::DoCacheWriteResponse() {
+  if (net_log_.IsLoggingAllEvents() && entry_)
+    net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_WRITE_INFO, NULL);
   return WriteResponseInfoToEntry(false);
 }
 
 int HttpCache::Transaction::DoCacheWriteTruncatedResponse() {
+  if (net_log_.IsLoggingAllEvents() && entry_)
+    net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_WRITE_INFO, NULL);
   return WriteResponseInfoToEntry(true);
 }
 
 int HttpCache::Transaction::DoCacheWriteResponseComplete(int result) {
   next_state_ = target_state_;
   target_state_ = STATE_NONE;
   if (!entry_)
     return OK;
+  if (net_log_.IsLoggingAllEvents())

[rvargas (doing something else), 2010/12/11 00:29:01]

You should probably move this before the previous test so that the begin is
always paired with an end.

[mmenke, 2010/12/11 01:51:05]

Both write events check for entry_'s existence before logging, and I don't
believe it can be destroyed between the two events.  Figure when nothing's
written, probably shouldn't log anything.

[rvargas (doing something else), 2010/12/13 23:34:38]

DoCacheWriteResponse and DoCacheWriteTruncatedResponse log fist and then check
to see if entry_ is null (inside WriteResponseInfoToEntry())

[mmenke, 2010/12/14 00:04:43]

Which is why in DoCacheWriteResponse and DoCacheWriteTruncatedResponse I use:

if (net_log_.IsLoggingAllEvents() && entry_)

[rvargas (doing something else), 2010/12/14 00:14:26]

And that just shows how blind I am!

+    net_log_.EndEventWithErrorCode(NetLog::TYPE_HTTP_CACHE_WRITE_INFO, result);
 
   // Balance the AddRef from WriteResponseInfoToEntry.
   write_headers_callback_->Release();
   if (result != io_buf_len_) {
     DLOG(ERROR) << "failed to write response info to cache";
     DoneWritingToEntry(false);
   }
   return OK;
 }
 
 int HttpCache::Transaction::DoCacheReadMetadata() {
   DCHECK(entry_);
   DCHECK(!response_.metadata);
   next_state_ = STATE_CACHE_READ_METADATA_COMPLETE;
 
   response_.metadata =
       new IOBufferWithSize(entry_->disk_entry->GetDataSize(kMetadataIndex));
 
   net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_READ_INFO, NULL);
   cache_callback_->AddRef();  // Balanced in DoCacheReadMetadataComplete.
   return entry_->disk_entry->ReadData(kMetadataIndex, 0, response_.metadata,
                                       response_.metadata->size(),
                                       cache_callback_);
 }
 
 int HttpCache::Transaction::DoCacheReadMetadataComplete(int result) {
   cache_callback_->Release();  // Balance the AddRef from DoCacheReadMetadata.
-  net_log_.EndEvent(NetLog::TYPE_HTTP_CACHE_READ_INFO, NULL);
+  net_log_.EndEventWithErrorCode(NetLog::TYPE_HTTP_CACHE_READ_INFO, result);
   if (result != response_.metadata->size()) {
     DLOG(ERROR) << "ReadData failed: " << result;
     return ERR_CACHE_READ_FAILURE;
   }
 
   return OK;
 }
 
 int HttpCache::Transaction::DoCacheQueryData() {
   next_state_ = STATE_CACHE_QUERY_DATA_COMPLETE;
@@ skipping 10 matching lines @@
   if (!cache_)
     return ERR_UNEXPECTED;
 
   return ValidateEntryHeadersAndContinue(true);
 }
 
 int HttpCache::Transaction::DoCacheReadData() {
   DCHECK(entry_);
   next_state_ = STATE_CACHE_READ_DATA_COMPLETE;
   cache_callback_->AddRef();  // Balanced in DoCacheReadDataComplete.
+
+  if (net_log_.IsLoggingAllEvents())
+    net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_READ_DATA, NULL);

[rvargas (doing something else), 2010/12/11 00:29:01]

Isn't this a little excessive? I'd expect a lot of noise from this one.

[mmenke, 2010/12/11 01:51:05]

There is indeed a lot of noise, but it all ends up at the bottom, when nothing
else is happening (And nothing too useful is logged afterwards).  Part of the
purpose behind NetLog is to locate performance issues, and I thought this might
be a useful indicator of cache contention issues.  The same goes for the
WRITE_DATA events.  On the other hand, timings of other events and the disk
cache entries may be enough.

We log equivalent events when we receive data, rather than reading from the
cache.

I'm not sure you're wrong about this, but feel I should explain before removing
it.  If you feel it's not worth it effort, I'm happy to remove it (Also, I'm not
sure how familiar you are with the NetLog, but IsLoggingAllEvents() is only true
when about:net-internals is currently open, so shouldn't have much performance
impact, normally).

[rvargas (doing something else), 2010/12/13 23:34:38]

OK, I didn't notice before that we log bytes received at the socket layer. This
seems equivalent.

On 2010/12/11 01:51:05, Matt Menke wrote:

   if (partial_.get()) {
     return partial_->CacheRead(entry_->disk_entry, read_buf_, io_buf_len_,
                                cache_callback_);
   }
 
   return entry_->disk_entry->ReadData(kResponseContentIndex, read_offset_,
                                       read_buf_, io_buf_len_, cache_callback_);
 }
 
 int HttpCache::Transaction::DoCacheReadDataComplete(int result) {
   cache_callback_->Release();  // Balance the AddRef from DoCacheReadData.
+  if (net_log_.IsLoggingAllEvents())
+    net_log_.EndEventWithErrorCode(NetLog::TYPE_HTTP_CACHE_READ_DATA, result);
 
   if (!cache_)
     return ERR_UNEXPECTED;
 
   if (partial_.get())
     return DoPartialCacheReadCompleted(result);
 
   if (result > 0) {
     read_offset_ += result;
   } else if (result == 0) {  // End of file.
     cache_->DoneReadingFromEntry(entry_, this);
     entry_ = NULL;
   }
   return result;
 }
 
 int HttpCache::Transaction::DoCacheWriteData(int num_bytes) {
   next_state_ = STATE_CACHE_WRITE_DATA_COMPLETE;
   write_len_ = num_bytes;
+  if (net_log_.IsLoggingAllEvents())
+    net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_WRITE_DATA, NULL);

[rvargas (doing something else), 2010/12/11 00:29:01]

same here.

   cache_callback_->AddRef();  // Balanced in DoCacheWriteDataComplete.
 
   return AppendResponseDataToEntry(read_buf_, num_bytes, cache_callback_);
 }
 
 int HttpCache::Transaction::DoCacheWriteDataComplete(int result) {
+  if (net_log_.IsLoggingAllEvents() && entry_)
+    net_log_.EndEventWithErrorCode(NetLog::TYPE_HTTP_CACHE_WRITE_DATA, result);
   // Balance the AddRef from DoCacheWriteData.
   cache_callback_->Release();
   if (!cache_)
     return ERR_UNEXPECTED;
 
   if (result != write_len_) {
     DLOG(ERROR) << "failed to write response data to cache";
     DoneWritingToEntry(false);
 
     // We want to ignore errors writing to disk and just keep reading from
@@ skipping 675 matching lines @@
   // |value| goes from 0 to 63. Actually, the max value should be 47 (0x2f)
   // but we'll see.
   UMA_HISTOGRAM_ENUMERATION("HttpCache.ResponseHeaders", value, 65);
 }
 
 void HttpCache::Transaction::OnIOComplete(int result) {
   DoLoop(result);
 }
 
 }  // namespace net