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 "base/stringprintf.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
+// Returns a name for a child entry given the base_name of the parent and the
+// child_id.  This name is only used for logging purposes.
+// If the entry is called entry_name, child entries will be named something
+// like Range_entry_name:YYY where YYY is the number of the particular child.
+std::string GenerateChildName(const std::string& base_name, int child_id) {
+  return base::StringPrintf("Range_%s:%i", base_name.c_str(), child_id);
+}
+
+}  // 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,
+      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::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::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::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::GetAvailableRange(int64 offset, int len, int64* start,
+                                    CompletionCallback* callback) {
+  if (net_log_.IsLoggingAllEvents()) {
+    net_log_.BeginEvent(
+        net::NetLog::TYPE_SPARSE_GET_RANGE,
+        make_scoped_refptr(
+            new SparseOperationParameters(offset, len)));
+  }
+  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::InternalReadData(int index, int offset, net::IOBuffer* buf,
+                                   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) {
+int MemEntryImpl::InternalWriteData(int index, int offset, net::IOBuffer* buf,
+                                    int buf_len, bool truncate) {
   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 20 matching lines @@
 
   UpdateRank(true);
 
   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) {
+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) {
+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);
-}
-
-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);
-}
-
 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)
     return net::ERR_INVALID_ARGUMENT;
 
@@ skipping 69 matching lines @@
       return false;
     children_.reset(new EntryMap());
 
     // The parent entry stores data for the first block, so save this object to
     // index 0.
     (*children_)[0] = this;
   }
   return true;
 }
 
-bool MemEntryImpl::InitChildEntry(MemEntryImpl* parent, int child_id) {
+bool MemEntryImpl::InitChildEntry(MemEntryImpl* parent, int child_id,
+                                  net::NetLog* net_log) {
   DCHECK(!parent_);
   DCHECK(!child_id_);
+
+  net_log_ = net::BoundNetLog::Make(net_log,
+                                    net::NetLog::SOURCE_MEMORY_CACHE_ENTRY);
+  net_log_.BeginEvent(
+      net::NetLog::TYPE_DISK_CACHE_MEM_ENTRY_IMPL,
+      make_scoped_refptr(new EntryCreationParameters(
+          GenerateChildName(parent->key(), child_id_),
+          true)));
+
   parent_ = parent;
   child_id_ = child_id;
   Time current = Time::Now();
   last_modified_ = current;
   last_used_ = current;
   // Insert this to the backend's ranking list.
   backend_->InsertIntoRankingList(this);
   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_);
-    child->InitChildEntry(this, index);
+    child->InitChildEntry(this, index, net_log_.net_log());
     (*children_)[index] = child;
     return child;
   }
   return NULL;
 }
 
 int MemEntryImpl::FindNextChild(int64 offset, int len, MemEntryImpl** child) {
   DCHECK(child);
   *child = NULL;
   int scanned_len = 0;
@@ skipping 23 matching lines @@
     scanned_len += kMaxSparseEntrySize - current_child_offset;
   }
   return scanned_len;
 }
 
 void MemEntryImpl::DetachChild(int child_id) {
   children_->erase(child_id);
 }
 
 }  // namespace disk_cache