Adds memory cache logging, and updates disk cache logging

net/disk_cache/sparse_control.cc

 // Copyright (c) 2009-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/sparse_control.h"
 
 #include "base/format_macros.h"
 #include "base/logging.h"
 #include "base/message_loop.h"
 #include "base/string_util.h"
 #include "base/stringprintf.h"
 #include "base/time.h"
 #include "net/base/io_buffer.h"
 #include "net/base/net_errors.h"
 #include "net/disk_cache/backend_impl.h"
 #include "net/disk_cache/entry_impl.h"
 #include "net/disk_cache/file.h"
+#include "net/disk_cache/net_log_parameters.h"
 
 using base::Time;
 
 namespace {
 
 // Stream of the sparse data index.
 const int kSparseIndex = 2;
 
 // Stream of the sparse data.
 const int kSparseData = 1;
 
 // We can have up to 64k children.
 const int kMaxMapSize = 8 * 1024;
 
 // The maximum number of bytes that a child can store.
 const int kMaxEntrySize = 0x100000;
 
 // The size of each data block (tracked by the child allocation bitmap).
 const int kBlockSize = 1024;
 
-// Returns the name of of a child entry given the base_name and signature of the
+// Returns the name of a child entry given the base_name and signature of the
 // parent and the child_id.
 // If the entry is called entry_name, child entries will be named something
 // like Range_entry_name:XXX:YYY where XXX is the entry signature and YYY is the
 // number of the particular child.
 std::string GenerateChildName(const std::string& base_name, int64 signature,
                               int64 child_id) {
   return base::StringPrintf("Range_%s:%" PRIx64 ":%" PRIx64, base_name.c_str(),
                             signature, child_id);
 }
 
@@ skipping 82 matching lines @@
   }
   std::string child_name = GenerateChildName(name_, signature_, child_id);
   backend_->SyncDoomEntry(child_name);
   children_map_.Set(child_id, false);
 
   // Post a task to delete the next child.
   MessageLoop::current()->PostTask(FROM_HERE, NewRunnableMethod(
       this, &ChildrenDeleter::DeleteChildren));
 }
 
-// Logs the end event for |operation|, if all events are being logged.
-void LogOperationEnd(const net::BoundNetLog& net_log,
-                     disk_cache::SparseControl::SparseOperation operation,
-                     int result) {
+// Returns the NetLog event type corresponding to a SparseOperation.
+net::NetLog::EventType GetSparseEventType(
+    disk_cache::SparseControl::SparseOperation operation) {
+  switch (operation) {
+    case disk_cache::SparseControl::kReadOperation:
+      return net::NetLog::TYPE_SPARSE_READ;
+    case disk_cache::SparseControl::kWriteOperation:
+      return net::NetLog::TYPE_SPARSE_WRITE;
+    case disk_cache::SparseControl::kGetRangeOperation:
+      return net::NetLog::TYPE_SPARSE_GET_RANGE;
+    default:
+      NOTREACHED();
+      return net::NetLog::TYPE_CANCELLED;
+  }
+}
+
+// Logs the end event for |operation| on a child entry.  Range operations log
+// no events for each child they search through.
+void LogChildOperationEnd(const net::BoundNetLog& net_log,
+                          disk_cache::SparseControl::SparseOperation operation,
+                          int result) {
   if (net_log.IsLoggingAllEvents()) {
     net::NetLog::EventType event_type;
     switch (operation) {
       case disk_cache::SparseControl::kReadOperation:
-        event_type = net::NetLog::TYPE_SPARSE_CONTROL_READ;
+        event_type = net::NetLog::TYPE_SPARSE_READ_CHILD_DATA;
         break;
       case disk_cache::SparseControl::kWriteOperation:
-        event_type = net::NetLog::TYPE_SPARSE_CONTROL_WRITE;
+        event_type = net::NetLog::TYPE_SPARSE_WRITE_CHILD_DATA;
         break;
       case disk_cache::SparseControl::kGetRangeOperation:
-        event_type = net::NetLog::TYPE_SPARSE_CONTROL_GET_RANGE;
-        break;
+        return;
       default:
         NOTREACHED();
         return;
     }
     net_log.EndEventWithNetErrorCode(event_type, result);
   }
 }
 
 }  // namespace.
 
@@ skipping 73 matching lines @@
   offset_ = offset;
   user_buf_ = buf ? new net::DrainableIOBuffer(buf, buf_len) : NULL;
   buf_len_ = buf_len;
   user_callback_ = callback;
 
   result_ = 0;
   pending_ = false;
   finished_ = false;
   abort_ = false;
 
-  entry_->net_log().BeginEvent(net::NetLog::TYPE_SPARSE_CONTROL, NULL);
+  if (entry_->net_log().IsLoggingAllEvents()) {
+    entry_->net_log().BeginEvent(
+        GetSparseEventType(operation_),
+        make_scoped_refptr(new SparseOperationParameters(offset_, buf_len_)));
+  }
   DoChildrenIO();
 
   if (!pending_) {
     // Everything was done synchronously.
     operation_ = kNoOperation;
     user_buf_ = NULL;
     user_callback_ = NULL;
     return result_;
   }
 
@@ skipping 49 matching lines @@
   int map_len = data_len - sizeof(SparseHeader);
   if (map_len > kMaxMapSize || map_len % 4)
     return;
 
   char* buffer;
   Addr address;
   entry->GetData(kSparseIndex, &buffer, &address);
   if (!buffer && !address.is_initialized())
     return;
 
+  entry->net_log().AddEvent(net::NetLog::TYPE_SPARSE_DELETE_CHILDREN, NULL);
+
   ChildrenDeleter* deleter = new ChildrenDeleter(entry->backend_,
                                                  entry->GetKey());
   // The object will self destruct when finished.
   deleter->AddRef();
 
   if (buffer) {
     MessageLoop::current()->PostTask(FROM_HERE, NewRunnableMethod(
         deleter, &ChildrenDeleter::Start, buffer, data_len));
   } else {
     MessageLoop::current()->PostTask(FROM_HERE, NewRunnableMethod(
@@ skipping 298 matching lines @@
   int rv = child_->WriteData(kSparseIndex, 0, buf, sizeof(child_data_),
                              NULL, false);
   if (rv != sizeof(child_data_))
     DLOG(ERROR) << "Failed to save child data";
   SetChildBit(true);
 }
 
 void SparseControl::DoChildrenIO() {
   while (DoChildIO()) continue;
 
+  // Range operations are finished synchronously, often without setting
+  // |finished_| to true.
+  if (kGetRangeOperation == operation_ &&
+      entry_->net_log().IsLoggingAllEvents()) {
+    entry_->net_log().EndEvent(
+        net::NetLog::TYPE_SPARSE_GET_RANGE,
+        make_scoped_refptr(
+            new GetAvailableRangeResultParameters(offset_, result_)));
+  }
   if (finished_) {
-    entry_->net_log().EndEvent(net::NetLog::TYPE_SPARSE_CONTROL, NULL);
+    if (kGetRangeOperation != operation_ &&
+        entry_->net_log().IsLoggingAllEvents()) {
+      entry_->net_log().EndEvent(GetSparseEventType(operation_), NULL);
+    }
     if (pending_)
       DoUserCallback();
   }
 }
 
 bool SparseControl::DoChildIO() {
   finished_ = true;
   if (!buf_len_ || result_ < 0)
     return false;
 
   if (!OpenChild())
     return false;
 
   if (!VerifyRange())
     return false;
 
   // We have more work to do. Let's not trigger a callback to the caller.
   finished_ = false;
   net::CompletionCallback* callback = user_callback_ ? &child_callback_ : NULL;
 
   int rv = 0;
   switch (operation_) {
     case kReadOperation:
       if (entry_->net_log().IsLoggingAllEvents()) {
         entry_->net_log().BeginEvent(
-            net::NetLog::TYPE_SPARSE_CONTROL_READ,
-            make_scoped_refptr(new net::NetLogSourceParameter(
-                "source_dependency",
-                child_->net_log().source())));
+            net::NetLog::TYPE_SPARSE_READ_CHILD_DATA,
+            make_scoped_refptr(new SparseReadWriteParameters(
+                child_->net_log().source(),
+                child_len_)));
       }
       rv = child_->ReadDataImpl(kSparseData, child_offset_, user_buf_,
                                 child_len_, callback);
       break;
     case kWriteOperation:
       if (entry_->net_log().IsLoggingAllEvents()) {
         entry_->net_log().BeginEvent(
-            net::NetLog::TYPE_SPARSE_CONTROL_WRITE,
-            make_scoped_refptr(new net::NetLogSourceParameter(
-                "source_dependency",
-                child_->net_log().source())));
+            net::NetLog::TYPE_SPARSE_WRITE_CHILD_DATA,
+            make_scoped_refptr(new SparseReadWriteParameters(
+                child_->net_log().source(),
+                child_len_)));
       }
       rv = child_->WriteDataImpl(kSparseData, child_offset_, user_buf_,
                                  child_len_, callback, false);
       break;
     case kGetRangeOperation:
-      if (entry_->net_log().IsLoggingAllEvents()) {
-        entry_->net_log().BeginEvent(net::NetLog::TYPE_SPARSE_CONTROL_GET_RANGE,
-                                     NULL);
-      }
       rv = DoGetAvailableRange();
       break;
     default:
       NOTREACHED();
   }
 
   if (rv == net::ERR_IO_PENDING) {
     if (!pending_) {
       pending_ = true;
       // The child will protect himself against closing the entry while IO is in
@@ skipping 52 matching lines @@
   // Only update offset_ when this query found zeros at the start.
   if (empty_start)
     offset_ += empty_start;
 
   // This will actually break the loop.
   buf_len_ = 0;
   return 0;
 }
 
 void SparseControl::DoChildIOCompleted(int result) {
-  LogOperationEnd(entry_->net_log(), operation_, result);
+  LogChildOperationEnd(entry_->net_log(), operation_, result);
   if (result < 0) {
     // We fail the whole operation if we encounter an error.
     result_ = result;
     return;
   }
 
   UpdateRange(result);
 
   result_ += result;
   offset_ += result;
   buf_len_ -= result;
 
   // We'll be reusing the user provided buffer for the next chunk.
   if (buf_len_ && user_buf_)
     user_buf_->DidConsume(result);
 }
 
 void SparseControl::OnChildIOCompleted(int result) {
   DCHECK_NE(net::ERR_IO_PENDING, result);
   DoChildIOCompleted(result);
 
   if (abort_) {
     // We'll return the current result of the operation, which may be less than
     // the bytes to read or write, but the user cancelled the operation.
     abort_ = false;
-    entry_->net_log().AddEvent(net::NetLog::TYPE_CANCELLED, NULL);
-    entry_->net_log().EndEvent(net::NetLog::TYPE_SPARSE_CONTROL, NULL);
+    if (entry_->net_log().IsLoggingAllEvents()) {
+      entry_->net_log().AddEvent(net::NetLog::TYPE_CANCELLED, NULL);
+      entry_->net_log().EndEvent(GetSparseEventType(operation_), NULL);
+    }
     DoUserCallback();
     return DoAbortCallbacks();
   }
 
   // We are running a callback from the message loop. It's time to restart what
   // we were doing before.
   DoChildrenIO();
 }
 
 void SparseControl::DoUserCallback() {
@@ skipping 14 matching lines @@
     net::CompletionCallback* c = abort_callbacks_[i];
     if (i == abort_callbacks_.size() - 1)
       abort_callbacks_.clear();
 
     entry_->Release();  // Don't touch object after this line.
     c->Run(net::OK);
   }
 }
 
 }  // namespace disk_cache