First pass at adding http/backend cache to NetLog

net/http/http_cache.cc

 // Copyright (c) 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/http/http_cache.h"
 
 #include <algorithm>
 
 #include "base/compiler_specific.h"
 
 #if defined(OS_POSIX)
 #include <unistd.h>
 #endif
 
 #include "base/callback.h"
 #include "base/format_macros.h"
 #include "base/message_loop.h"
 #include "base/pickle.h"
 #include "base/ref_counted.h"
 #include "base/stl_util-inl.h"
 #include "base/string_number_conversions.h"
 #include "base/string_util.h"
 #include "base/stringprintf.h"
+#include "base/values.h"
 #include "net/base/io_buffer.h"
 #include "net/base/load_flags.h"
 #include "net/base/net_errors.h"
 #include "net/disk_cache/disk_cache.h"
 #include "net/http/disk_cache_based_ssl_host_info.h"
 #include "net/http/http_cache_transaction.h"
 #include "net/http/http_network_layer.h"
 #include "net/http/http_network_session.h"
 #include "net/http/http_request_info.h"
 #include "net/http/http_response_headers.h"
 #include "net/http/http_response_info.h"
 #include "net/http/http_util.h"
 #include "net/socket/ssl_host_info.h"
 #include "net/spdy/spdy_session_pool.h"
 
 namespace net {
 
+namespace {
+
+class ActiveEntryCreationParameters : public NetLog::EventParameters {
+ public:
+  ActiveEntryCreationParameters(std::string key, const NetLog::Source& source)
+      : key_(key), source_(source) {
+  }
+
+  virtual Value* ToValue() const {
+    DictionaryValue* dict = new DictionaryValue();
+    dict->SetString("key", key_);
+    dict->Set("source_dependency", source_.ToValue());
+    return dict;
+  }
+
+ private:
+  const std::string key_;
+  const NetLog::Source source_;
+};
+
+// Used for adding and queuing both read and write transactions.
+class AddTransactionParams : public NetLog::EventParameters {
+ public:
+  AddTransactionParams(const NetLog::Source& source, size_t queue_length)
+      : source_(source), queue_length_(queue_length) {
+  }
+
+  virtual Value* ToValue() const {
+    DictionaryValue* dict = new DictionaryValue();
+    dict->Set("source_dependency", source_.ToValue());
+    if (queue_length_ > 0)
+      dict->SetInteger("queue_length", queue_length_);
+    return dict;
+  }
+
+ private:
+  const NetLog::Source source_;
+  size_t queue_length_;
+};
+
+}  // namespace
+
 HttpCache::DefaultBackend::DefaultBackend(CacheType type,
                                           const FilePath& path,
                                           int max_bytes,
                                           base::MessageLoopProxy* thread)
     : type_(type),
       path_(path),
       max_bytes_(max_bytes),
       thread_(thread) {
 }
 
 HttpCache::DefaultBackend::~DefaultBackend() {}
 
 // static
 HttpCache::BackendFactory* HttpCache::DefaultBackend::InMemory(int max_bytes) {
   return new DefaultBackend(MEMORY_CACHE, FilePath(), max_bytes, NULL);
 }
 
 int HttpCache::DefaultBackend::CreateBackend(disk_cache::Backend** backend,
-                                             CompletionCallback* callback) {
+                                             CompletionCallback* callback,
+                                             NetLog* net_log) {
   DCHECK_GE(max_bytes_, 0);
   return disk_cache::CreateCacheBackend(type_, path_, max_bytes_, true,
-                                        thread_, backend, callback);
+                                        thread_, backend, callback, net_log);
 }
 
 //-----------------------------------------------------------------------------
 
-HttpCache::ActiveEntry::ActiveEntry(disk_cache::Entry* e)
-    : disk_entry(e),
+HttpCache::ActiveEntry::ActiveEntry(disk_cache::Entry* entry, NetLog* log)
+    : disk_entry(entry),
       writer(NULL),
       will_process_pending_queue(false),
-      doomed(false) {
+      doomed(false),
+      net_log(BoundNetLog::Make(log, NetLog::SOURCE_HTTP_CACHE_ACTIVE_ENTRY)) {
+  net_log.BeginEvent(NetLog::TYPE_HTTP_CACHE_ACTIVE_ENTRY,
+                     new NetLogStringParameter("key", entry->GetKey()));
 }
 
 HttpCache::ActiveEntry::~ActiveEntry() {
+  net_log.EndEvent(NetLog::TYPE_HTTP_CACHE_ACTIVE_ENTRY, NULL);
   if (disk_entry) {
     disk_entry->Close();
     disk_entry = NULL;
   }
 }
 
 //-----------------------------------------------------------------------------
 
 // This structure keeps track of work items that are attempting to create or
 // open cache entries or the backend itself.
@@ skipping 195 matching lines @@
 
 HttpCache::HttpCache(HostResolver* host_resolver,
                      DnsRRResolver* dnsrr_resolver,
                      DnsCertProvenanceChecker* dns_cert_checker_,
                      ProxyService* proxy_service,
                      SSLConfigService* ssl_config_service,
                      HttpAuthHandlerFactory* http_auth_handler_factory,
                      HttpNetworkDelegate* network_delegate,
                      NetLog* net_log,
                      BackendFactory* backend_factory)
-    : backend_factory_(backend_factory),
+    : net_log_(net_log),
+      backend_factory_(backend_factory),
       building_backend_(false),
       mode_(NORMAL),
       ssl_host_info_factory_(new SSLHostInfoFactoryAdaptor(
             ALLOW_THIS_IN_INITIALIZER_LIST(this))),
       network_layer_(HttpNetworkLayer::CreateFactory(host_resolver,
           dnsrr_resolver, dns_cert_checker_,
           ssl_host_info_factory_.get(),
           proxy_service, ssl_config_service,
           http_auth_handler_factory, network_delegate, net_log)),
       ALLOW_THIS_IN_INITIALIZER_LIST(task_factory_(this)) {
 }
 
 HttpCache::HttpCache(HttpNetworkSession* session,
                      BackendFactory* backend_factory)
-    : backend_factory_(backend_factory),
+    : net_log_(session->net_log()),
+      backend_factory_(backend_factory),
       building_backend_(false),
       mode_(NORMAL),
       network_layer_(HttpNetworkLayer::CreateFactory(session)),
       ALLOW_THIS_IN_INITIALIZER_LIST(task_factory_(this)) {
 }
 
 HttpCache::HttpCache(HttpTransactionFactory* network_layer,
-                     BackendFactory* backend_factory)
-    : backend_factory_(backend_factory),
+                     BackendFactory* backend_factory,
+                     NetLog* net_log)
+    : net_log_(net_log),
+      backend_factory_(backend_factory),
       building_backend_(false),
       mode_(NORMAL),
       network_layer_(network_layer),
       ALLOW_THIS_IN_INITIALIZER_LIST(task_factory_(this)) {
 }
 
 HttpCache::~HttpCache() {
   // If we have any active entries remaining, then we need to deactivate them.
   // We may have some pending calls to OnProcessPendingQueue, but since those
   // won't run (due to our destruction), we can simply ignore the corresponding
@@ skipping 131 matching lines @@
       pending_op->pending_queue.push_back(item.release());
     return ERR_IO_PENDING;
   }
 
   DCHECK(pending_op->pending_queue.empty());
 
   pending_op->writer = item.release();
   BackendCallback* my_callback = new BackendCallback(this, pending_op);
   pending_op->callback = my_callback;
 
-  int rv = backend_factory_->CreateBackend(&pending_op->backend, my_callback);
+  int rv = backend_factory_->CreateBackend(&pending_op->backend, my_callback,
+                                           net_log_);
   if (rv != ERR_IO_PENDING) {
     pending_op->writer->ClearCallback();
     my_callback->Run(rv);
   }
 
   return rv;
 }
 
 int HttpCache::GetBackendForTransaction(Transaction* trans) {
   if (disk_cache_.get())
@@ skipping 54 matching lines @@
   // longer be returned by FindActiveEntry (and it will also be destroyed once
   // all consumers are finished with the entry).
   ActiveEntriesMap::iterator it = active_entries_.find(key);
   if (it == active_entries_.end()) {
     return AsyncDoomEntry(key, trans);
   }
 
   ActiveEntry* entry = it->second;
   active_entries_.erase(it);
 
+  entry->net_log.AddEvent(NetLog::TYPE_ACTIVE_ENTRY_DOOM, NULL);
+
   // We keep track of doomed entries so that we can ensure that they are
   // cleaned up properly when the cache is destroyed.
   doomed_entries_.insert(entry);
 
   entry->disk_entry->Doom();
   entry->doomed = true;
 
   DCHECK(entry->writer || !entry->readers.empty());
   return OK;
 }
@@ skipping 21 matching lines @@
 
   return rv;
 }
 
 void HttpCache::FinalizeDoomedEntry(ActiveEntry* entry) {
   DCHECK(entry->doomed);
   DCHECK(!entry->writer);
   DCHECK(entry->readers.empty());
   DCHECK(entry->pending_queue.empty());
 
+  entry->net_log.AddEvent(NetLog::TYPE_ACTIVE_ENTRY_FINALIZE_DOOMED_ENTRY,
+                          NULL);
+
   ActiveEntriesSet::iterator it = doomed_entries_.find(entry);
   DCHECK(it != doomed_entries_.end());
   doomed_entries_.erase(it);
 
   delete entry;
 }
 
 HttpCache::ActiveEntry* HttpCache::FindActiveEntry(const std::string& key) {
   ActiveEntriesMap::const_iterator it = active_entries_.find(key);
   return it != active_entries_.end() ? it->second : NULL;
 }
 
 HttpCache::ActiveEntry* HttpCache::ActivateEntry(
     disk_cache::Entry* disk_entry) {
   DCHECK(!FindActiveEntry(disk_entry->GetKey()));
-  ActiveEntry* entry = new ActiveEntry(disk_entry);
+  ActiveEntry* entry = new ActiveEntry(disk_entry, net_log_);
   active_entries_[disk_entry->GetKey()] = entry;
   return entry;
 }
 
 void HttpCache::DeactivateEntry(ActiveEntry* entry) {
   DCHECK(!entry->will_process_pending_queue);
   DCHECK(!entry->doomed);
   DCHECK(!entry->writer);
   DCHECK(entry->disk_entry);
   DCHECK(entry->readers.empty());
   DCHECK(entry->pending_queue.empty());
 
+  entry->net_log.AddEvent(NetLog::TYPE_ACTIVE_ENTRY_DEACTIVATE, NULL);
+
   std::string key = entry->disk_entry->GetKey();
   if (key.empty())
     return SlowDeactivateEntry(entry);
 
   ActiveEntriesMap::iterator it = active_entries_.find(key);
   DCHECK(it != active_entries_.end());
   DCHECK(it->second == entry);
 
   active_entries_.erase(it);
   delete entry;
@@ skipping 105 matching lines @@
 
 void HttpCache::DestroyEntry(ActiveEntry* entry) {
   if (entry->doomed) {
     FinalizeDoomedEntry(entry);
   } else {
     DeactivateEntry(entry);
   }
 }
 
 int HttpCache::AddTransactionToEntry(ActiveEntry* entry, Transaction* trans) {
+  int result = AddTransactionToEntryInternal(entry, trans);
+  if (result == ERR_IO_PENDING) {
+    entry->net_log.AddEvent(
+        NetLog::TYPE_ACTIVE_ENTRY_ADD_TO_QUEUE,
+        new AddTransactionParams(trans->net_log().source(),
+                                 entry->pending_queue.size()));
+  }
+  return result;
+}
+
+int HttpCache::AddTransactionToEntryInternal(ActiveEntry* entry,
+                                             Transaction* trans) {
   DCHECK(entry);
   DCHECK(entry->disk_entry);
 
   // We implement a basic reader/writer lock for the disk cache entry.  If
   // there is already a writer, then everyone has to wait for the writer to
   // finish before they can access the cache entry.  There can be multiple
   // readers.
   //
   // NOTE: If the transaction can only write, then the entry should not be in
   // use (since any existing entry should have already been doomed).
 
   if (entry->writer || entry->will_process_pending_queue) {
     entry->pending_queue.push_back(trans);
     return ERR_IO_PENDING;
   }
 
   if (trans->mode() & Transaction::WRITE) {
     // transaction needs exclusive access to the entry
     if (entry->readers.empty()) {
       entry->writer = trans;
+      entry->net_log.BeginEvent(
+          NetLog::TYPE_ACTIVE_ENTRY_SET_WRITER,
+          new AddTransactionParams(trans->net_log().source(),
+                                   entry->pending_queue.size()));
     } else {
       entry->pending_queue.push_back(trans);
       return ERR_IO_PENDING;
     }
   } else {
     // transaction needs read access to the entry
     entry->readers.push_back(trans);
+    entry->net_log.AddEvent(
+        NetLog::TYPE_ACTIVE_ENTRY_ADD_READER,
+        new AddTransactionParams(trans->net_log().source(),
+                                 entry->pending_queue.size()));
   }
 
   // We do this before calling EntryAvailable to force any further calls to
   // AddTransactionToEntry to add their transaction to the pending queue, which
   // ensures FIFO ordering.
   if (!entry->writer && !entry->pending_queue.empty())
     ProcessPendingQueue(entry);
 
   return OK;
 }
@@ skipping 19 matching lines @@
     DoneWritingToEntry(entry, success);
   } else {
     DoneReadingFromEntry(entry, trans);
   }
 }
 
 void HttpCache::DoneWritingToEntry(ActiveEntry* entry, bool success) {
   DCHECK(entry->readers.empty());
 
   entry->writer = NULL;
+  entry->net_log.EndEvent(NetLog::TYPE_ACTIVE_ENTRY_SET_WRITER, NULL);
 
   if (success) {
     ProcessPendingQueue(entry);
   } else {
     DCHECK(!entry->will_process_pending_queue);
 
     // We failed to create this entry.
     TransactionList pending_queue;
     pending_queue.swap(entry->pending_queue);
 
@@ skipping 11 matching lines @@
 }
 
 void HttpCache::DoneReadingFromEntry(ActiveEntry* entry, Transaction* trans) {
   DCHECK(!entry->writer);
 
   TransactionList::iterator it =
       std::find(entry->readers.begin(), entry->readers.end(), trans);
   DCHECK(it != entry->readers.end());
 
   entry->readers.erase(it);
+  entry->net_log.AddEvent(
+      NetLog::TYPE_ACTIVE_ENTRY_REMOVE_READER,
+      new NetLogSourceParameter("source_dependency",
+                                trans->net_log().source()));
 
   ProcessPendingQueue(entry);
 }
 
 void HttpCache::ConvertWriterToReader(ActiveEntry* entry) {
   DCHECK(entry->writer);
   DCHECK(entry->writer->mode() == Transaction::READ_WRITE);
   DCHECK(entry->readers.empty());
 
   Transaction* trans = entry->writer;
 
   entry->writer = NULL;
+  entry->net_log.EndEvent(NetLog::TYPE_ACTIVE_ENTRY_SET_WRITER, NULL);
   entry->readers.push_back(trans);
+  entry->net_log.AddEvent(
+      NetLog::TYPE_ACTIVE_ENTRY_ADD_READER,
+      new NetLogSourceParameter("source_dependency",
+                                trans->net_log().source()));
 
   ProcessPendingQueue(entry);
 }
 
 LoadState HttpCache::GetLoadStateForPendingTransaction(
       const Transaction* trans) {
   ActiveEntriesMap::const_iterator i = active_entries_.find(trans->key());
   if (i == active_entries_.end()) {
     // If this is really a pending transaction, and it is not part of
     // active_entries_, we should be creating the backend or the entry.
@@ skipping 38 matching lines @@
 
 bool HttpCache::RemovePendingTransactionFromEntry(ActiveEntry* entry,
                                                   Transaction* trans) {
   TransactionList& pending_queue = entry->pending_queue;
 
   TransactionList::iterator j =
       find(pending_queue.begin(), pending_queue.end(), trans);
   if (j == pending_queue.end())
     return false;
 
+  entry->net_log.AddEvent(
+      NetLog::TYPE_ACTIVE_ENTRY_REMOVE_PENDING_TRANSACTION,
+      new NetLogSourceParameter("source_dependency",
+                                trans->net_log().source()));
   pending_queue.erase(j);
   return true;
 }
 
 bool HttpCache::RemovePendingTransactionFromPendingOp(PendingOp* pending_op,
                                                       Transaction* trans) {
   if (pending_op->writer->Matches(trans)) {
     pending_op->writer->ClearTransaction();
     pending_op->writer->ClearEntry();
     return true;
@@ skipping 36 matching lines @@
     return;
   }
 
   // Promote next transaction from the pending queue.
   Transaction* next = entry->pending_queue.front();
   if ((next->mode() & Transaction::WRITE) && !entry->readers.empty())
     return;  // Have to wait.
 
   entry->pending_queue.erase(entry->pending_queue.begin());
 
-  int rv = AddTransactionToEntry(entry, next);
+  int rv = AddTransactionToEntryInternal(entry, next);
   if (rv != ERR_IO_PENDING) {
     next->io_callback()->Run(rv);
   }
 }
 
 void HttpCache::OnIOComplete(int result, PendingOp* pending_op) {
   WorkItemOperation op = pending_op->writer->operation();
 
   // Completing the creation of the backend is simpler than the other cases.
   if (op == WI_CREATE_BACKEND)
@@ skipping 116 matching lines @@
     building_backend_ = false;
     DeletePendingOp(pending_op);
   }
 
   // The cache may be gone when we return from the callback.
   if (!item->DoCallback(result, backend))
     item->NotifyTransaction(result, NULL);
 }
 
 }  // namespace net