Adds memory cache logging, and updates disk cache logging

net/disk_cache/mem_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/mem_entry_impl.h"
 
 #include "base/logging.h"
 #include "net/base/io_buffer.h"
 #include "net/base/net_errors.h"
 #include "net/disk_cache/mem_backend_impl.h"
+#include "net/disk_cache/net_log_parameters.h"
 
 using base::Time;
 
 namespace {
 
 const int kSparseData = 1;
 
 // Maximum size of a sparse entry is 2 to the power of this number.
 const int kMaxSparseEntryBits = 12;
 
 // Sparse entry has maximum size of 4KB.
 const int kMaxSparseEntrySize = 1 << kMaxSparseEntryBits;
 
 // Convert global offset to child index.
 inline int ToChildIndex(int64 offset) {
   return static_cast<int>(offset >> kMaxSparseEntryBits);
 }
 
 // Convert global offset to offset in child entry.
 inline int ToChildOffset(int64 offset) {
   return static_cast<int>(offset & (kMaxSparseEntrySize - 1));
 }
 
-}  // nemespace
+}  // namespace
 
 namespace disk_cache {
 
 MemEntryImpl::MemEntryImpl(MemBackendImpl* backend) {
   doomed_ = false;
   backend_ = backend;
   ref_count_ = 0;
   parent_ = NULL;
   child_id_ = 0;
   child_first_pos_ = 0;
   next_ = NULL;
   prev_ = NULL;
   for (int i = 0; i < NUM_STREAMS; i++)
     data_size_[i] = 0;
 }
 
 // ------------------------------------------------------------------------
 
-bool MemEntryImpl::CreateEntry(const std::string& key) {
+bool MemEntryImpl::CreateEntry(const std::string& key, net::NetLog* net_log) {
+  net_log_ = net::BoundNetLog::Make(net_log,
+                                    net::NetLog::SOURCE_MEMORY_CACHE_ENTRY);
+  net_log_.BeginEvent(
+    net::NetLog::TYPE_DISK_CACHE_MEM_ENTRY_IMPL,

[rvargas (doing something else), 2011/03/04 21:39:16]

nit: indent four spaces

[mmenke, 2011/03/07 17:46:41]

Done.

+    make_scoped_refptr(new EntryCreationParameters(key, true)));
   key_ = key;
   Time current = Time::Now();
   last_modified_ = current;
   last_used_ = current;
   Open();
   backend_->ModifyStorageSize(0, static_cast<int32>(key.size()));
   return true;
 }
 
 void MemEntryImpl::InternalDoom() {
+  net_log_.AddEvent(net::NetLog::TYPE_ENTRY_DOOM, NULL);
   doomed_ = true;
   if (!ref_count_) {
     if (type() == kParentEntry) {
       // If this is a parent entry, we need to doom all the child entries.
       if (children_.get()) {
         EntryMap children;
         children.swap(*children_);
         for (EntryMap::iterator i = children.begin();
              i != children.end(); ++i) {
           // Since a pointer to this object is also saved in the map, avoid
@@ skipping 71 matching lines @@
 }
 
 int32 MemEntryImpl::GetDataSize(int index) const {
   if (index < 0 || index >= NUM_STREAMS)
     return 0;
   return data_size_[index];
 }
 
 int MemEntryImpl::ReadData(int index, int offset, net::IOBuffer* buf,
     int buf_len, net::CompletionCallback* completion_callback) {
+  if (net_log_.IsLoggingAllEvents()) {
+    net_log_.BeginEvent(
+        net::NetLog::TYPE_ENTRY_READ_DATA,
+        make_scoped_refptr(
+            new ReadWriteDataParameters(index, offset, buf_len, false)));
+  }
+
+  int result = InternalReadData(index, offset, buf, buf_len);
+
+  if (net_log_.IsLoggingAllEvents()) {
+    net_log_.EndEvent(
+        net::NetLog::TYPE_ENTRY_READ_DATA,
+        make_scoped_refptr(new ReadWriteCompleteParameters(result)));
+  }
+  return result;
+}
+
+int MemEntryImpl::InternalReadData(int index, int offset, net::IOBuffer* buf,

[rvargas (doing something else), 2011/03/04 21:39:16]

I appreciate this being here for the review, but it has to move down before
commit.

[mmenke, 2011/03/07 17:46:41]

Once Eric's had a chance to review, I'll move them.

+    int buf_len) {
   DCHECK(type() == kParentEntry || index == kSparseData);
 
   if (index < 0 || index >= NUM_STREAMS)
     return net::ERR_INVALID_ARGUMENT;
 
   int entry_size = GetDataSize(index);
   if (offset >= entry_size || offset < 0 || !buf_len)
     return 0;
 
   if (buf_len < 0)
     return net::ERR_INVALID_ARGUMENT;
 
   if (offset + buf_len > entry_size)
     buf_len = entry_size - offset;
 
   UpdateRank(false);
 
-  memcpy(buf->data() , &(data_[index])[offset], buf_len);
+  memcpy(buf->data(), &(data_[index])[offset], buf_len);
   return buf_len;
 }
 
 int MemEntryImpl::WriteData(int index, int offset, net::IOBuffer* buf,
     int buf_len, net::CompletionCallback* completion_callback, bool truncate) {
+  if (net_log_.IsLoggingAllEvents()) {
+    net_log_.BeginEvent(
+        net::NetLog::TYPE_ENTRY_WRITE_DATA,
+        make_scoped_refptr(
+            new ReadWriteDataParameters(index, offset, buf_len, truncate)));
+  }
+
+  int result = InternalWriteData(index, offset, buf, buf_len, truncate);
+
+  if (net_log_.IsLoggingAllEvents()) {
+    net_log_.EndEvent(
+        net::NetLog::TYPE_ENTRY_WRITE_DATA,
+        make_scoped_refptr(new ReadWriteCompleteParameters(result)));
+  }
+  return result;
+}
+
+int MemEntryImpl::InternalWriteData(int index, int offset, net::IOBuffer* buf,
+    int buf_len, bool truncate) {

[rvargas (doing something else), 2011/03/04 21:39:16]

nit: could you indent these under index.

[mmenke, 2011/03/07 17:46:41]

Done.

   DCHECK(type() == kParentEntry || index == kSparseData);
 
   if (index < 0 || index >= NUM_STREAMS)
     return net::ERR_INVALID_ARGUMENT;
 
   if (offset < 0 || buf_len < 0)
     return net::ERR_INVALID_ARGUMENT;
 
   int max_file_size = backend_->MaxFileSize();
 
@@ skipping 22 matching lines @@
 
   if (!buf_len)
     return 0;
 
   memcpy(&(data_[index])[offset], buf->data(), buf_len);
   return buf_len;
 }
 
 int MemEntryImpl::ReadSparseData(int64 offset, net::IOBuffer* buf, int buf_len,
                                  net::CompletionCallback* completion_callback) {
+  if (net_log_.IsLoggingAllEvents()) {
+    net_log_.BeginEvent(
+        net::NetLog::TYPE_SPARSE_READ,
+        make_scoped_refptr(
+            new SparseOperationParameters(offset, buf_len)));
+  }
+  int result = InternalReadSparseData(offset, buf, buf_len);
+  if (net_log_.IsLoggingAllEvents())
+    net_log_.EndEvent(net::NetLog::TYPE_SPARSE_READ, NULL);
+  return result;
+}
+
+int MemEntryImpl::InternalReadSparseData(
+    int64 offset, net::IOBuffer* buf, int buf_len) {
   DCHECK(type() == kParentEntry);
 
   if (!InitSparseInfo())
     return net::ERR_CACHE_OPERATION_NOT_SUPPORTED;
 
   if (offset < 0 || buf_len < 0)
     return net::ERR_INVALID_ARGUMENT;
 
   // We will keep using this buffer and adjust the offset in this buffer.
   scoped_refptr<net::DrainableIOBuffer> io_buf(
       new net::DrainableIOBuffer(buf, buf_len));
 
   // Iterate until we have read enough.
   while (io_buf->BytesRemaining()) {
     MemEntryImpl* child = OpenChild(offset + io_buf->BytesConsumed(), false);
 
     // No child present for that offset.
     if (!child)
       break;
 
     // We then need to prepare the child offset and len.
     int child_offset = ToChildOffset(offset + io_buf->BytesConsumed());
 
     // If we are trying to read from a position that the child entry has no data
     // we should stop.
     if (child_offset < child->child_first_pos_)
       break;
+    if (net_log_.IsLoggingAllEvents()) {
+      net_log_.BeginEvent(
+          net::NetLog::TYPE_SPARSE_READ_CHILD_DATA,
+          make_scoped_refptr(new SparseReadWriteParameters(
+              child->net_log().source(),
+              io_buf->BytesRemaining())));
+    }
     int ret = child->ReadData(kSparseData, child_offset, io_buf,
                               io_buf->BytesRemaining(), NULL);
+    if (net_log_.IsLoggingAllEvents()) {
+      net_log_.EndEventWithNetErrorCode(
+          net::NetLog::TYPE_SPARSE_READ_CHILD_DATA, ret);
+    }
 
     // If we encounter an error in one entry, return immediately.
     if (ret < 0)
       return ret;
     else if (ret == 0)
       break;
 
     // Increment the counter by number of bytes read in the child entry.
     io_buf->DidConsume(ret);
   }
 
   UpdateRank(false);
 
   return io_buf->BytesConsumed();
 }
 
 int MemEntryImpl::WriteSparseData(int64 offset, net::IOBuffer* buf, int buf_len,
     net::CompletionCallback* completion_callback) {
+  if (net_log_.IsLoggingAllEvents()) {
+    net_log_.BeginEvent(net::NetLog::TYPE_SPARSE_WRITE,
+        make_scoped_refptr(
+            new SparseOperationParameters(offset, buf_len)));
+  }
+  int result = InternalWriteSparseData(offset, buf, buf_len);
+  if (net_log_.IsLoggingAllEvents())
+    net_log_.EndEvent(net::NetLog::TYPE_SPARSE_WRITE, NULL);
+  return result;
+}
+
+int MemEntryImpl::InternalWriteSparseData(
+    int64 offset, net::IOBuffer* buf, int buf_len) {
   DCHECK(type() == kParentEntry);
 
   if (!InitSparseInfo())
     return net::ERR_CACHE_OPERATION_NOT_SUPPORTED;
 
   if (offset < 0 || buf_len < 0)
     return net::ERR_INVALID_ARGUMENT;
 
   scoped_refptr<net::DrainableIOBuffer> io_buf(
       new net::DrainableIOBuffer(buf, buf_len));
 
   // This loop walks through child entries continuously starting from |offset|
   // and writes blocks of data (of maximum size kMaxSparseEntrySize) into each
   // child entry until all |buf_len| bytes are written. The write operation can
   // start in the middle of an entry.
   while (io_buf->BytesRemaining()) {
     MemEntryImpl* child = OpenChild(offset + io_buf->BytesConsumed(), true);
     int child_offset = ToChildOffset(offset + io_buf->BytesConsumed());
 
     // Find the right amount to write, this evaluates the remaining bytes to
     // write and remaining capacity of this child entry.
     int write_len = std::min(static_cast<int>(io_buf->BytesRemaining()),
                              kMaxSparseEntrySize - child_offset);
 
     // Keep a record of the last byte position (exclusive) in the child.
     int data_size = child->GetDataSize(kSparseData);
 
+    if (net_log_.IsLoggingAllEvents()) {
+      net_log_.BeginEvent(
+          net::NetLog::TYPE_SPARSE_WRITE_CHILD_DATA,
+          make_scoped_refptr(new SparseReadWriteParameters(
+              child->net_log().source(),
+              write_len)));
+    }
+
     // Always writes to the child entry. This operation may overwrite data
     // previously written.
     // TODO(hclam): if there is data in the entry and this write is not
     // continuous we may want to discard this write.
     int ret = child->WriteData(kSparseData, child_offset, io_buf, write_len,
                                NULL, true);
+    if (net_log_.IsLoggingAllEvents()) {
+      net_log_.EndEventWithNetErrorCode(
+          net::NetLog::TYPE_SPARSE_WRITE_CHILD_DATA, ret);
+    }
     if (ret < 0)
       return ret;
     else if (ret == 0)
       break;
 
     // Keep a record of the first byte position in the child if the write was
     // not aligned nor continuous. This is to enable witting to the middle
     // of an entry and still keep track of data off the aligned edge.
     if (data_size != child_offset)
       child->child_first_pos_ = child_offset;
 
     // Adjust the offset in the IO buffer.
     io_buf->DidConsume(ret);
   }
 
   UpdateRank(true);
 
   return io_buf->BytesConsumed();
 }
 
 int MemEntryImpl::GetAvailableRange(int64 offset, int len, int64* start,
                                     CompletionCallback* callback) {
-  return GetAvailableRange(offset, len, start);
+  if (net_log_.IsLoggingAllEvents())
+    net_log_.BeginEvent(net::NetLog::TYPE_SPARSE_GET_RANGE, NULL);
+  int result = GetAvailableRange(offset, len, start);
+  if (net_log_.IsLoggingAllEvents()) {
+    net_log_.EndEvent(
+        net::NetLog::TYPE_SPARSE_GET_RANGE,
+        make_scoped_refptr(
+            new GetAvailableRangeResultParameters(*start, result)));
+  }
+  return result;
 }
 
 bool MemEntryImpl::CouldBeSparse() const {
   DCHECK_EQ(kParentEntry, type());
   return (children_.get() != NULL);
 }
 
 int MemEntryImpl::ReadyForSparseIO(
     net::CompletionCallback* completion_callback) {
   return net::OK;
 }
 
 // ------------------------------------------------------------------------
 
 MemEntryImpl::~MemEntryImpl() {
   for (int i = 0; i < NUM_STREAMS; i++)
     backend_->ModifyStorageSize(data_size_[i], 0);
   backend_->ModifyStorageSize(static_cast<int32>(key_.size()), 0);
+  net_log_.EndEvent(net::NetLog::TYPE_DISK_CACHE_MEM_ENTRY_IMPL, NULL);
 }
 
 int MemEntryImpl::GetAvailableRange(int64 offset, int len, int64* start) {
   DCHECK(type() == kParentEntry);
   DCHECK(start);
 
   if (!InitSparseInfo())
     return net::ERR_CACHE_OPERATION_NOT_SUPPORTED;
 
   if (offset < 0 || len < 0 || !start)
@@ skipping 91 matching lines @@
   return true;
 }
 
 MemEntryImpl* MemEntryImpl::OpenChild(int64 offset, bool create) {
   DCHECK(type() == kParentEntry);
   int index = ToChildIndex(offset);
   EntryMap::iterator i = children_->find(index);
   if (i != children_->end()) {
     return i->second;
   } else if (create) {
     MemEntryImpl* child = new MemEntryImpl(backend_);

[rvargas (doing something else), 2011/03/04 21:39:16]

This creates a child entry that will miss the BeginEvent (doesn't go through
CreateEntry), but will see the EndEvent on the destructor.

The use case is a sparse incognito cache (for media).

[mmenke, 2011/03/07 17:46:41]

Fixed.  I should add that both a build from the top of trunk and Canary have
been having renderer crashes on HTML5 video, so I haven't been able to test
output for sparse operations.

     child->InitChildEntry(this, index);
     (*children_)[index] = child;
     return child;
   }
   return NULL;
 }
 
 int MemEntryImpl::FindNextChild(int64 offset, int len, MemEntryImpl** child) {
   DCHECK(child);
   *child = NULL;
@@ skipping 24 matching lines @@
     scanned_len += kMaxSparseEntrySize - current_child_offset;
   }
   return scanned_len;
 }
 
 void MemEntryImpl::DetachChild(int child_id) {
   children_->erase(child_id);
 }
 
 }  // namespace disk_cache