First pass at adding http/backend cache to NetLog

net/disk_cache/entry_impl.cc

Index: net/disk_cache/entry_impl.cc
===================================================================
--- net/disk_cache/entry_impl.cc	(revision 68857)
+++ net/disk_cache/entry_impl.cc	(working copy)
@@ -7,6 +7,7 @@
 #include "base/message_loop.h"
 #include "base/metrics/histogram.h"
 #include "base/string_util.h"
+#include "base/values.h"
 #include "net/base/io_buffer.h"
 #include "net/base/net_errors.h"
 #include "net/disk_cache/backend_impl.h"
@@ -24,14 +25,58 @@
 // Index for the file used to store the key, if any (files_[kKeyFileIndex]).
 const int kKeyFileIndex = 3;
 
+class EntryCreationParameters : public net::NetLog::EventParameters {

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

nit: Add a short description.

[mmenke, 2010/12/14 17:53:43]

Done

+ public:
+  EntryCreationParameters(const std::string& key, bool created)
+      : key_(key), created_(created) {
+  }
+
+  Value* ToValue() const {
+    DictionaryValue *dict = new DictionaryValue();
+    dict->SetString("key", key_);
+    dict->SetBoolean("created", created_);
+    return dict;
+  }
+
+ private:
+  const std::string key_;
+  const bool created_;
+};
+
+class ReadWriteDataParams : public net::NetLog::EventParameters {

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

nit: same here.

[mmenke, 2010/12/14 17:53:43]

Done

+ public:
+  ReadWriteDataParams(int index, int offset, int buf_len, bool truncate)
+      : index_(index), offset_(offset), buf_len_(buf_len), truncate_(truncate) {
+  }
+
+  Value* ToValue() const {
+    DictionaryValue* dict = new DictionaryValue();
+    dict->SetInteger("index", index_);
+    dict->SetInteger("offset", offset_);
+    dict->SetInteger("buf_len", buf_len_);
+    if (truncate_)
+      dict->SetBoolean("truncate", truncate_);
+    return dict;
+  }
+
+ private:
+  int index_;
+  int offset_;
+  int buf_len_;
+  bool truncate_;
+};
+
 // This class implements FileIOCallback to buffer the callback from a file IO
 // operation from the actual net class.
 class SyncCallback: public disk_cache::FileIOCallback {
  public:
+  // |end_event_type| is the event type to log on completion.  Logs nothing on
+  // discard, or when the NetLog is not set to log all events.
   SyncCallback(disk_cache::EntryImpl* entry, net::IOBuffer* buffer,
-               net::CompletionCallback* callback )
+               net::CompletionCallback* callback,
+               net::NetLog::EventType end_event_type)
       : entry_(entry), callback_(callback), buf_(buffer),
-        start_(TimeTicks::Now()) {
+        start_(TimeTicks::Now()), end_event_type_(end_event_type) {
     entry->AddRef();
     entry->IncrementIoCount();
   }
@@ -39,16 +84,21 @@
 
   virtual void OnFileIOComplete(int bytes_copied);
   void Discard();
+
  private:
   disk_cache::EntryImpl* entry_;
   net::CompletionCallback* callback_;
   scoped_refptr<net::IOBuffer> buf_;
   TimeTicks start_;
+  net::NetLog::EventType end_event_type_;
 
   DISALLOW_COPY_AND_ASSIGN(SyncCallback);
 };
 
 void SyncCallback::OnFileIOComplete(int bytes_copied) {
+  if (entry_->net_log().IsLoggingAllEvents())

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

This should be moved down, under the "if (callback_)", to avoid calling EndEvent
twice.

[mmenke, 2010/12/14 17:53:43]

You're right.  Done.  Not sure there's any reason we'd ever end up here with a
null callback_, but definitely a bug.

+    entry_->net_log().EndEventWithErrorCode(end_event_type_, bytes_copied);
+
   entry_->DecrementIoCount();
   if (callback_) {
     entry_->ReportIOTime(disk_cache::EntryImpl::kAsyncIO, start_);
@@ -308,6 +358,7 @@
   if (doomed_) {
     DeleteEntryData(true);
   } else {
+    net_log_.AddEvent(net::NetLog::TYPE_DISK_CACHE_CLOSE, NULL);
     bool ret = true;
     for (int index = 0; index < kNumStreams; index++) {
       if (user_buffers_[index].get()) {
@@ -334,6 +385,8 @@
 
   Trace("~EntryImpl out 0x%p", reinterpret_cast<void*>(this));
   backend_->OnEntryDestroyEnd();
+
+  net_log_.EndEvent(net::NetLog::TYPE_DISK_CACHE_ENTRY, NULL);

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

Please move this line before the call to OnEntryDestroyEnd()

[mmenke, 2010/12/14 17:53:43]

Done

 }
 
 void EntryImpl::Doom() {
@@ -481,12 +534,51 @@
   if (doomed_)
     return;
 
+  net_log_.AddEvent(net::NetLog::TYPE_DISK_CACHE_DOOM, NULL);

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

Given the log at InternalDoom(), this one is not needed.

[mmenke, 2010/12/14 17:53:43]

Done (Well, deleted this one.  Accidentally was logging on both).  Wasn't sure
which one would be the most useful.

   SetPointerForInvalidEntry(backend_->GetCurrentEntryId());
   backend_->InternalDoomEntry(this);
 }
 
 int EntryImpl::ReadDataImpl(int index, int offset, net::IOBuffer* buf,
                             int buf_len, CompletionCallback* callback) {
+  if (net_log_.IsLoggingAllEvents()) {
+    net_log_.BeginEvent(
+        net::NetLog::TYPE_DISK_CACHE_READ_DATA,
+        make_scoped_refptr(
+            new ReadWriteDataParams(index, offset, buf_len, false)));
+  }
+
+  int result = InternalReadData(index, offset, buf, buf_len, callback);
+
+  if (result != net::ERR_IO_PENDING && net_log_.IsLoggingAllEvents()) {
+    net_log_.EndEventWithErrorCode(net::NetLog::TYPE_DISK_CACHE_READ_DATA,
+                                   result);
+  }
+  return result;
+}
+
+int EntryImpl::WriteDataImpl(int index, int offset, net::IOBuffer* buf,
+                             int buf_len, CompletionCallback* callback,
+                             bool truncate) {
+  if (net_log_.IsLoggingAllEvents()) {
+    net_log_.BeginEvent(
+        net::NetLog::TYPE_DISK_CACHE_WRITE_DATA,
+        make_scoped_refptr(
+            new ReadWriteDataParams(index, offset, buf_len, truncate)));
+  }
+
+  int result = InternalWriteData(index, offset, buf, buf_len, callback,
+                                 truncate);
+
+  if (result != net::ERR_IO_PENDING && net_log_.IsLoggingAllEvents()) {
+    net_log_.EndEventWithErrorCode(net::NetLog::TYPE_DISK_CACHE_WRITE_DATA,
+                                    result);
+  }
+  return result;
+}
+
+int EntryImpl::InternalReadData(int index, int offset, net::IOBuffer* buf,
+                                int buf_len, CompletionCallback* callback) {
   DCHECK(node_.Data()->dirty || read_only_);
   DVLOG(2) << "Read from " << index << " at " << offset << " : " << buf_len;
   if (index < 0 || index >= kNumStreams)
@@ -536,8 +628,10 @@
   }
 
   SyncCallback* io_callback = NULL;
-  if (callback)
-    io_callback = new SyncCallback(this, buf, callback);
+  if (callback) {
+    io_callback = new SyncCallback(this, buf, callback,
+                                   net::NetLog::TYPE_DISK_CACHE_READ_DATA);
+  }
 
   bool completed;
   if (!file->Read(buf->data(), buf_len, file_offset, io_callback, &completed)) {
@@ -553,9 +647,9 @@
   return (completed || !callback) ? buf_len : net::ERR_IO_PENDING;
 }
 
-int EntryImpl::WriteDataImpl(int index, int offset, net::IOBuffer* buf,
-                             int buf_len, CompletionCallback* callback,
-                             bool truncate) {
+int EntryImpl::InternalWriteData(int index, int offset, net::IOBuffer* buf,
+                                 int buf_len, CompletionCallback* callback,
+                                 bool truncate) {
   DCHECK(node_.Data()->dirty || read_only_);
   DVLOG(2) << "Write to " << index << " at " << offset << " : " << buf_len;
   if (index < 0 || index >= kNumStreams)
@@ -628,8 +722,10 @@
     return 0;
 
   SyncCallback* io_callback = NULL;
-  if (callback)
-    io_callback = new SyncCallback(this, buf, callback);
+  if (callback) {
+    io_callback = new SyncCallback(this, buf, callback,
+                                   net::NetLog::TYPE_DISK_CACHE_WRITE_DATA);
+  }
 
   bool completed;
   if (!file->Write(buf->data(), buf_len, file_offset, io_callback,
@@ -757,6 +853,7 @@
 }
 
 void EntryImpl::InternalDoom() {
+  net_log_.AddEvent(net::NetLog::TYPE_DISK_CACHE_DOOM, NULL);
   DCHECK(node_.HasData());
   if (!node_.Data()->dirty) {
     node_.Data()->dirty = backend_->GetCurrentEntryId();
@@ -914,6 +1011,19 @@
   }
 }
 
+void EntryImpl::BeginLogging(net::NetLog* net_log, bool created) {
+  DCHECK(!net_log_.net_log());
+  net_log_ = net::BoundNetLog::Make(
+      net_log, net::NetLog::SOURCE_DISK_CACHE_ENTRY);
+  net_log_.BeginEvent(
+      net::NetLog::TYPE_DISK_CACHE_ENTRY,
+      make_scoped_refptr(new EntryCreationParameters(GetKey(), created)));
+}
+
+const net::BoundNetLog& EntryImpl::net_log() const {
+  return net_log_;
+}
+
 // ------------------------------------------------------------------------
 
 bool EntryImpl::CreateDataBlock(int index, int size) {