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;
 
+// NetLog parameters for the creation of an EntryImpl.  Contains an entry's name
+// and whether it was created or opened.
+class EntryCreationParameters : public net::NetLog::EventParameters {
+ public:
+  EntryCreationParameters(const std::string& key, bool created)
+      : key_(key), created_(created) {
+  }
+
+  Value* ToValue() const {
+    DictionaryValue *dict = new DictionaryValue();

[eroman, 2011/01/05 02:39:06]

nit: DictionaryValue*

[mmenke, 2011/01/05 16:32:25]

DOn 2011/01/05 02:39:06, eroman wrote:
Done.

+    dict->SetString("key", key_);
+    dict->SetBoolean("created", created_);
+    return dict;
+  }
+
+ private:
+  const std::string key_;
+  const bool created_;
+};
+
+// NetLog parameters for both reading and writing to an EntryImpl.
+class ReadWriteDataParams : public net::NetLog::EventParameters {
+ public:
+  // For reads, |truncate| must be false.
+  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_;

[eroman, 2011/01/05 02:39:06]

nit: can you make these all const ?

[mmenke, 2011/01/05 16:32:25]

Done.

+  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) {
   entry_->DecrementIoCount();
   if (callback_) {
+    if (entry_->net_log().IsLoggingAllEvents())
+      entry_->net_log().EndEventWithErrorCode(end_event_type_, bytes_copied);

[eroman, 2011/01/05 02:39:06]

Would we want to log the actual bytes copied on non-errors? (as I understand the
code, will not log anything if net_error >= 0).

[mmenke, 2011/01/05 16:32:25]

You do, indeed, understand the code.  With writes, at least, if fewer were
copied than were read, it's actually an error, which would certainly be useful
to know.  I didn't do it mostly for legibility.

Anyways change made.

     entry_->ReportIOTime(disk_cache::EntryImpl::kAsyncIO, start_);
     callback_->Run(bytes_copied);
   }
   entry_->Release();
   delete this;
 }
 
 void SyncCallback::Discard() {
   callback_ = NULL;
   buf_ = NULL;
@@ skipping 237 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));
+  net_log_.EndEvent(net::NetLog::TYPE_DISK_CACHE_ENTRY, NULL);
   backend_->OnEntryDestroyEnd();
 }
 
 void EntryImpl::Doom() {
   backend_->background_queue()->DoomEntryImpl(this);
 }
 
 void EntryImpl::Close() {
   backend_->background_queue()->CloseEntryImpl(this);
 }
@@ skipping 134 matching lines @@
 void EntryImpl::DoomImpl() {
   if (doomed_)
     return;
 
   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 {

[eroman, 2011/01/05 02:39:06]

Is it possible for this to be called before BeginLogging()? Is it valid?

[mmenke, 2011/01/05 16:32:25]

No, I don't believe it's possible.  The only two functions that create
EntryImpls call BeginLogging(), and don't call the read or write functions
directly or indirectly before then, to the extent of my knowledge.

However, it is valid.  The no-parameter BoundNetLog constructor initializes
net_log_ to NULL, and BoundNetLogs are designed to work when they have a NULL
NetLog.

+  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