First pass at adding http/backend cache to NetLog

net/disk_cache/entry_impl.cc

 // Copyright (c) 2006-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/disk_cache/entry_impl.h"
 
 #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"
 #include "net/disk_cache/bitmap.h"
 #include "net/disk_cache/cache_util.h"
 #include "net/disk_cache/histogram_macros.h"
 #include "net/disk_cache/sparse_control.h"
 
 using base::Time;
 using base::TimeDelta;
 using base::TimeTicks;
 
 namespace {
 
 // 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();
   }
   ~SyncCallback() {}
 
   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_);
     callback_->Run(bytes_copied);
   }
   entry_->Release();
   delete this;
 }
 
 void SyncCallback::Discard() {
@@ skipping 239 matching lines @@
   // maybe for a child entry, so it is important to do it before deleting this
   // entry.
   sparse_.reset();
 
   // Remove this entry from the list of open entries.
   backend_->OnEntryDestroyBegin(entry_.address());
 
   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()) {
         if (!(ret = Flush(index, 0)))
           LOG(ERROR) << "Failed to save user data";
       }
       if (unreported_size_[index]) {
         backend_->ModifyStorageSize(
             entry_.Data()->data_size[index] - unreported_size_[index],
             entry_.Data()->data_size[index]);
       }
     }
 
     if (!ret) {
       // There was a failure writing the actual data. Mark the entry as dirty.
       int current_id = backend_->GetCurrentEntryId();
       node_.Data()->dirty = current_id == 1 ? -1 : current_id - 1;
       node_.Store();
     } else if (node_.HasData() && node_.Data()->dirty) {
       node_.Data()->dirty = 0;
       node_.Store();
     }
   }
 
   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() {
   backend_->background_queue()->DoomEntryImpl(this);
 }
 
 void EntryImpl::Close() {
   backend_->background_queue()->CloseEntryImpl(this);
 }
 
@@ skipping 127 matching lines @@
   backend_->background_queue()->ReadyForSparseIO(this, callback);
   return net::ERR_IO_PENDING;
 }
 
 // ------------------------------------------------------------------------
 
 void EntryImpl::DoomImpl() {
   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)
     return net::ERR_INVALID_ARGUMENT;
 
   int entry_size = entry_.Data()->data_size[index];
   if (offset >= entry_size || offset < 0 || !buf_len)
     return 0;
 
   if (buf_len < 0)
@@ skipping 29 matching lines @@
     return net::ERR_FAILED;
 
   size_t file_offset = offset;
   if (address.is_block_file()) {
     DCHECK_LE(offset + buf_len, kMaxBlockSize);
     file_offset += address.start_block() * address.BlockSize() +
                    kBlockHeaderSize;
   }
 
   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)) {
     if (io_callback)
       io_callback->Discard();
     return net::ERR_FAILED;
   }
 
   if (io_callback && completed)
     io_callback->Discard();
 
   ReportIOTime(kRead, start);
   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)
     return net::ERR_INVALID_ARGUMENT;
 
   if (offset < 0 || buf_len < 0)
     return net::ERR_INVALID_ARGUMENT;
 
   int max_file_size = backend_->MaxFileSize();
 
@@ skipping 52 matching lines @@
                    kBlockHeaderSize;
   } else if (truncate || (extending && !buf_len)) {
     if (!file->SetLength(offset + buf_len))
       return net::ERR_FAILED;
   }
 
   if (!buf_len)
     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,
                    &completed)) {
     if (io_callback)
       io_callback->Discard();
     return net::ERR_FAILED;
   }
 
   if (io_callback && completed)
@@ skipping 107 matching lines @@
 bool EntryImpl::IsSameEntry(const std::string& key, uint32 hash) {
   if (entry_.Data()->hash != hash ||
       static_cast<size_t>(entry_.Data()->key_len) != key.size())
     return false;
 
   std::string my_key = GetKey();
   return key.compare(my_key) ? false : true;
 }
 
 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();
     node_.Store();
   }
   doomed_ = true;
 }
 
 void EntryImpl::DeleteEntryData(bool everything) {
   DCHECK(doomed_ || !everything);
@@ skipping 137 matching lines @@
       CACHE_UMA(AGE_MS, "SparseWriteTime", 0, start);
       break;
     case kAsyncIO:
       CACHE_UMA(AGE_MS, "AsyncIOTime", group, start);
       break;
     default:
       NOTREACHED();
   }
 }
 
+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) {
   DCHECK(index >= 0 && index < kNumStreams);
 
   Addr address(entry_.Data()->data_addr[index]);
   if (!CreateBlock(size, &address))
     return false;
 
   entry_.Data()->data_addr[index] = address.value();
@@ skipping 363 matching lines @@
   Trace("%s 0x%p 0x%x 0x%x", msg, reinterpret_cast<void*>(this),
         entry_.address().value(), node_.address().value());
 
   Trace("  data: 0x%x 0x%x 0x%x", entry_.Data()->data_addr[0],
         entry_.Data()->data_addr[1], entry_.Data()->long_key);
 
   Trace("  doomed: %d 0x%x", doomed_, dirty);
 }
 
 }  // namespace disk_cache