First pass at adding http/backend cache to NetLog

net/http/http_cache_transaction.cc

Index: net/http/http_cache_transaction.cc
===================================================================
--- net/http/http_cache_transaction.cc	(revision 68857)
+++ net/http/http_cache_transaction.cc	(working copy)
@@ -18,6 +18,7 @@
 #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"
@@ -385,6 +386,10 @@
   return LOAD_STATE_WAITING_FOR_CACHE;
 }
 
+const BoundNetLog& HttpCache::Transaction::net_log() const {
+  return net_log_;
+}
+
 //-----------------------------------------------------------------------------
 
 void HttpCache::Transaction::DoCallback(int rv) {
@@ -566,13 +571,13 @@
 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()) {
@@ -746,7 +751,7 @@
   // 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;
@@ -789,7 +794,7 @@
   // 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;
 
@@ -820,7 +825,7 @@
 }
 
 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)
@@ -833,15 +838,16 @@
   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);
@@ -991,12 +997,17 @@
   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;
@@ -1009,10 +1020,15 @@
   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();
 
@@ -1062,7 +1078,7 @@
 
 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_)) {
@@ -1102,10 +1118,14 @@
 }
 
 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);
 }
 
@@ -1114,6 +1134,8 @@
   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();
@@ -1141,7 +1163,7 @@
 
 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;
@@ -1172,6 +1194,9 @@
   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_);
@@ -1183,6 +1208,8 @@
 
 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;
@@ -1202,12 +1229,16 @@
 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_)