Cache Backend Proxy to intercept all cache events from the IO thread.

net/disk_cache/tracing_cache_backend.cc

Index: net/disk_cache/tracing_cache_backend.cc
diff --git a/net/disk_cache/tracing_cache_backend.cc b/net/disk_cache/tracing_cache_backend.cc
new file mode 100644
index 0000000000000000000000000000000000000000..59d32f569ded3e704c608994740e19efd90cf892
--- /dev/null
+++ b/net/disk_cache/tracing_cache_backend.cc
@@ -0,0 +1,272 @@
+// Copyright (c) 2013 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/tracing_cache_backend.h"
+
+#include "net/base/net_errors.h"
+
+namespace disk_cache {
+
+TracingCacheBackend::TracingCacheBackend(Backend* backend)
+  : backend_(backend) {
+}
+
+TracingCacheBackend::~TracingCacheBackend() {
+}
+
+net::CacheType TracingCacheBackend::GetCacheType() const {
+  return backend_->GetCacheType();
+}
+
+int32 TracingCacheBackend::GetEntryCount() const {
+  return backend_->GetEntryCount();
+}
+
+class EntryProxy : public Entry,

[rvargas (doing something else), 2013/04/05 19:25:13]

don't declare a class in the middle of the definition of another class.

[pasko-google - do not use, 2013/04/09 11:53:17]

Done.

+      public base::RefCounted<EntryProxy> {
+  friend class base::RefCounted<EntryProxy>;
+ public:
+  EntryProxy(Entry *entry, TracingCacheBackend* be)

[rvargas (doing something else), 2013/04/05 19:25:13]

nit: backend

[pasko-google - do not use, 2013/04/09 11:53:17]

Done.

+    : entry_(entry),
+      backend_(be->AsWeakPtr()) {
+  }
+  virtual void Doom() OVERRIDE {
+    // TODO(pasko): Record the event.
+    entry_->Doom();
+  }
+  virtual void Close() OVERRIDE {
+    // TODO(pasko): Record the event.
+    entry_->Close();
+    Release();
+  }
+  virtual std::string GetKey() const OVERRIDE {

[rvargas (doing something else), 2013/04/05 19:25:13]

why not track everything? To avoid overhead while recording?

[pasko-google - do not use, 2013/04/08 15:37:40]

Yes, I did not measure the CPU/memory overhead yet. We'd keep all events in
memory until they are flushed, which on memory-constrained systems may be an
issue.

More reasoning behind lack of TODOs:

It is not quite interesting to see how much time is spent on trivial operations.
As the first approximation I want to track only he operations that go down to
disk access.

I just did not want to add TODO clutter, this change is rather about backend
interface and main internal interception mechanisms, I am leaving out simple
details now on purpose to simplify the review, make it more gradual than one
huge bulk. I am OK adding the TODOs back if it is more comfortable to review
this way.

+    return entry_->GetKey();
+  }
+  virtual base::Time GetLastUsed() const OVERRIDE {
+    return entry_->GetLastUsed();
+  }
+  virtual base::Time GetLastModified() const OVERRIDE {
+    return entry_->GetLastModified();
+  }
+  virtual int32 GetDataSize(int index) const OVERRIDE {
+    return entry_->GetDataSize(index);
+  }
+  virtual int ReadData(int index, int offset, IOBuffer* buf, int buf_len,
+                       const CompletionCallback& callback) OVERRIDE {
+    int64 start_time = base::TimeTicks::Now().ToInternalValue();

[rvargas (doing something else), 2013/04/05 19:25:13]

separate class definition from class declaration.

[pasko-google - do not use, 2013/04/09 11:53:17]

Done.

+    RwOpExtra extra;
+    extra.index = index;
+    extra.offset = offset;
+    extra.buf_len = buf_len;
+    extra.truncate = false;
+    int rv = entry_->ReadData(index, offset, buf, buf_len,
+        base::Bind(&EntryProxy::EntryOpComplete, base::Unretained(this),

[rvargas (doing something else), 2013/04/05 19:25:13]

nit: indentation

[rvargas (doing something else), 2013/04/05 19:25:13]

Cannot use Unretained here

[pasko-google - do not use, 2013/04/09 11:53:17]

Done.

+                   start_time, BackendIO::OP_READ, extra, callback));
+    if (rv != net::ERR_IO_PENDING) {
+      RecordEvent(start_time, BackendIO::OP_READ, extra, rv);
+    }
+    return rv;
+  }
+  virtual int WriteData(int index, int offset, IOBuffer* buf, int buf_len,
+                        const CompletionCallback& callback,
+                        bool truncate) OVERRIDE {
+    int64 start_time = base::TimeTicks::Now().ToInternalValue();
+    RwOpExtra extra;
+    extra.index = index;
+    extra.offset = offset;
+    extra.buf_len = buf_len;
+    extra.truncate = truncate;
+    int rv = entry_->WriteData(index, offset, buf, buf_len,
+        base::Bind(&EntryProxy::EntryOpComplete, base::Unretained(this),
+                   start_time, BackendIO::OP_WRITE, extra, callback),
+        truncate);
+    if (rv != net::ERR_IO_PENDING) {
+      RecordEvent(start_time, BackendIO::OP_WRITE, extra, rv);
+    }
+    return rv;
+  }
+  virtual int ReadSparseData(int64 offset, IOBuffer* buf, int buf_len,
+                             const CompletionCallback& callback) OVERRIDE {
+    return entry_->ReadSparseData(offset, buf, buf_len, callback);

[rvargas (doing something else), 2013/04/05 19:25:13]

definitely track.

[pasko-google - do not use, 2013/04/09 11:53:17]

Added a TODO.

+  }
+  virtual int WriteSparseData(int64 offset, IOBuffer* buf, int buf_len,
+                              const CompletionCallback& callback) OVERRIDE {
+    return entry_->WriteSparseData(offset, buf, buf_len, callback);
+  }
+  virtual int GetAvailableRange(int64 offset, int len, int64* start,
+                                const CompletionCallback& callback) OVERRIDE {
+    return entry_->GetAvailableRange(offset, len, start, callback);
+  }
+  virtual bool CouldBeSparse() const OVERRIDE {
+    return entry_->CouldBeSparse();
+  }
+  virtual void CancelSparseIO() OVERRIDE {
+    return entry_->CancelSparseIO();
+  }
+  virtual int ReadyForSparseIO(const CompletionCallback& callback) OVERRIDE {
+    return entry_->ReadyForSparseIO(callback);
+  }
+ private:
+  struct RwOpExtra {
+    int index;
+    int offset;
+    int buf_len;
+    bool truncate;
+  };
+
+  void RecordEvent(int64 start_time, BackendIO::Operation op, RwOpExtra extra,
+                   int rv) {
+    // TODO(pasko): Implement.
+  }
+
+  void EntryOpComplete(int64 start_time, BackendIO::Operation op,
+                       RwOpExtra extra,
+                       const CompletionCallback& cb, int rv) {
+    RecordEvent(start_time, op, extra, rv);
+    if (!cb.is_null()) {
+      cb.Run(rv);
+    }
+  }
+
+  virtual ~EntryProxy() {
+    if (backend_.get()) {
+      backend_->OnDeleteEntry(entry_);
+    }
+  }
+
+  Entry* entry_;
+  // Shared with TracingCacheBackend.
+  base::WeakPtr<TracingCacheBackend> backend_;
+
+  DISALLOW_COPY_AND_ASSIGN(EntryProxy);
+};
+
+void TracingCacheBackend::RecordEvent(int64 start_time,
+                                      BackendIO::Operation op,
+                                      std::string key,
+                                      Entry** entry,

[rvargas (doing something else), 2013/04/05 19:25:13]

Why Entry** and not Entry* (this method should not modify the value)

[pasko-google - do not use, 2013/04/09 11:53:17]

Just copied arguments from another function without thinking. Done.

+                                      int rv) {
+  // TODO(pasko): Implement.
+}
+
+EntryProxy* TracingCacheBackend::FindOrCreateEntryProxy(Entry* entry) {
+  EntryProxy* e;

[rvargas (doing something else), 2013/04/05 19:25:13]

nit: don't use single letter variable names (for anything not trivial)

[pasko-google - do not use, 2013/04/09 11:53:17]

Done.

+  if (open_entries_.find(entry) != open_entries_.end()) {
+    e = open_entries_[entry];

[rvargas (doing something else), 2013/04/05 19:25:13]

don't search twice

[pasko-google - do not use, 2013/04/09 11:53:17]

Done.

+    e->AddRef();
+    return e;
+  }
+  e = new EntryProxy(entry, this);
+  e->AddRef();
+  open_entries_[entry] = e;
+  return e;
+}
+
+void TracingCacheBackend::OnDeleteEntry(Entry* e) {
+  EntryToProxyMap::iterator it = open_entries_.find(e);
+  if (it != open_entries_.end()) {
+    open_entries_.erase(it);
+  }
+}
+
+void TracingCacheBackend::BackendOpComplete(int64 start_time,
+                                            BackendIO::Operation op,
+                                            std::string key,
+                                            Entry** entry,
+                                            const CompletionCallback& callback,
+                                            int rv) {
+  RecordEvent(start_time, op, key, entry, rv);
+  if (*entry) {
+    *entry = FindOrCreateEntryProxy(*entry);
+  }
+  if (!callback.is_null()) {
+    callback.Run(rv);
+  }
+}
+
+net::CompletionCallback TracingCacheBackend::BindCompletion(
+    BackendIO::Operation op, int64 start_time, const std::string& key,
+    Entry **entry, const net::CompletionCallback& cb) {
+  DCHECK(entry == NULL || *entry == NULL);

[rvargas (doing something else), 2013/04/05 19:25:13]

why *entry == null ? that's not part of the contract.

[pasko-google - do not use, 2013/04/09 11:53:17]

I was checking this invariant, but seems like it is no longer needed. Removed.

+  return base::Bind(&TracingCacheBackend::BackendOpComplete,

[rvargas (doing something else), 2013/04/05 19:25:13]

nit: A method with a single line of implementation looks like an overkill... how
about at least moving start_time here :)

[pasko-google - do not use, 2013/04/09 11:53:17]

This would not work for, say, OpenEntry that returns synchronously. It save
lines in the end because the amount of characters is smaller :)

[rvargas (doing something else), 2013/04/09 18:54:01]

What would not work?

[pasko-google - do not use, 2013/04/10 17:06:38]

in OpenEntry() we use start_time for two cases:
1. pending operation: should pass the start_time to the callback firing at op
completion, so it gets passed to BindCompletion()
2. synchronous operation: should pass the start_time directly to RecordEvent()

We have a value consumed by both BindCompletion() and RecordEvent(), so we
cannot move its creation to BindCompletion().

+      base::Unretained(this), start_time, op, key, entry, cb);

[rvargas (doing something else), 2013/04/05 19:25:13]

nit: indent under first arg

[pasko-google - do not use, 2013/04/09 11:53:17]

Done.

+}
+
+int TracingCacheBackend::OpenEntry(const std::string& key, Entry** entry,
+                                   const CompletionCallback& callback) {
+  DCHECK(*entry == NULL);
+  int64 start_time = base::TimeTicks::Now().ToInternalValue();
+  int rv = backend_->OpenEntry(key, entry, BindCompletion(BackendIO::OP_OPEN,
+                                                          start_time, key,
+                                                          entry, callback));
+  if (rv != net::ERR_IO_PENDING) {
+    RecordEvent(start_time, BackendIO::OP_OPEN, key, entry, rv);
+    if (*entry) {
+      *entry = FindOrCreateEntryProxy(*entry);
+    }
+  }
+  return rv;
+}
+
+int TracingCacheBackend::CreateEntry(const std::string& key, Entry** entry,
+                                     const CompletionCallback& callback) {
+  int64 start_time = base::TimeTicks::Now().ToInternalValue();

[rvargas (doing something else), 2013/04/05 19:25:13]

why are you using int64 instead of Time?

[pasko-google - do not use, 2013/04/09 11:53:17]

Because passing an object by value feels icky. Sure the compiler would probably
optimize it into copying the single field, but it is easier to understand what
the parameter is when it is just a 64bit timestamp.

[rvargas (doing something else), 2013/04/09 18:54:01]

That's not the convention on Chrome. Time was specifically designed to be passed
around.

[pasko-google - do not use, 2013/04/10 17:06:38]

Done.

+  int rv = backend_->CreateEntry(
+      key, entry, BindCompletion(BackendIO::OP_CREATE, start_time, key, entry,

[rvargas (doing something else), 2013/04/05 19:25:13]

BackendIO is going away... I would not recommend using it just to reuse an enum
(which would be questionable even if the class  were not going away).

[pasko-google - do not use, 2013/04/08 15:37:40]

I could create a different enum, though some enum constants have confusing name
differences, such as: OP_DOOM, OP_DOOM_ENTRY. I thought that they might get
renamed some day, and wanted to make sure the renaming gets propagated. It is
not clear how it is going away, the enum might even stay as it is, and I am not
reusing anything beyond the enum.

[rvargas (doing something else), 2013/04/08 18:28:34]

... and that show that the constants were never meant to be used outside of the
owner class, hence being private.
why would they have to be propagated? The enum is not a canonical list of the
operations that a backend may  need to do... it was just the list of the things
the in_flight_backend_io knows about.

So yes, please don't reuse the enum and define one for the async things needed
by the tracer (and private to it :) )

[pasko-google - do not use, 2013/04/09 11:53:17]

I created an independent enum. Just copied. Some of the operations are unused
right now, will be used later as these values will be saved in the in-memory
representation of the trace events. So let's wait for the coming CLs to discuss
their exact look.

+                                 callback));
+  if (rv != net::ERR_IO_PENDING) {
+    RecordEvent(start_time, BackendIO::OP_CREATE, key, entry, rv);
+    if (*entry) {
+      *entry = FindOrCreateEntryProxy(*entry);
+    }
+  }
+  return rv;
+}
+
+int TracingCacheBackend::DoomEntry(const std::string& key,
+                                   const CompletionCallback& callback) {
+  int64 start_time = base::TimeTicks::Now().ToInternalValue();
+  int rv = backend_->DoomEntry(key, BindCompletion(BackendIO::OP_DOOM_ENTRY,
+                                                   start_time, key, NULL,
+                                                   callback));
+  if (rv != net::ERR_IO_PENDING) {
+    Entry* e;

[rvargas (doing something else), 2013/04/05 19:25:13]

ditto

[pasko-google - do not use, 2013/04/09 11:53:17]

Done.

+    RecordEvent(start_time, BackendIO::OP_DOOM_ENTRY, key, &e, rv);
+  }
+  return rv;
+}
+
+int TracingCacheBackend::DoomAllEntries(const CompletionCallback& callback) {
+  return backend_->DoomAllEntries(callback);

[rvargas (doing something else), 2013/04/05 19:25:13]

why are we not tracking this? (and the other calls)

[pasko-google - do not use, 2013/04/08 15:37:40]

I was not measuring it in the initial experiments since the simple backend does
not implement it. Should do. I am adding a TODO.

+}
+
+int TracingCacheBackend::DoomEntriesBetween(base::Time initial_time,
+                                            base::Time end_time,
+                                            const CompletionCallback& cb) {
+  return backend_->DoomEntriesBetween(initial_time, end_time, cb);
+}
+
+int TracingCacheBackend::DoomEntriesSince(base::Time initial_time,
+                                          const CompletionCallback& callback) {
+  return backend_->DoomEntriesSince(initial_time, callback);
+}
+
+int TracingCacheBackend::OpenNextEntry(void** iter, Entry** next_entry,
+                                       const CompletionCallback& callback) {
+  return backend_->OpenNextEntry(iter, next_entry, callback);
+}
+
+void TracingCacheBackend::EndEnumeration(void** iter) {
+  return backend_->EndEnumeration(iter);
+}
+
+void TracingCacheBackend::GetStats(StatsItems* stats) {
+  return backend_->GetStats(stats);
+}
+
+void TracingCacheBackend::OnExternalCacheHit(const std::string& key) {
+  return backend_->OnExternalCacheHit(key);
+}
+
+}  // namespace disk_cache