[blobfs][vnode] Add instrumentation.

Instruments Blobfs vnodes paths, but does not yet flush to cobalt.
This will be done once the project data is updated on cobalt side.

TEST=blobfs-integration-tests, locally verified metrics are incremented
when on.

Change-Id: Ic1ed3c9dce649192a56c99dc10a22d8b797a867e
diff --git a/system/uapp/blobfs/rules.mk b/system/uapp/blobfs/rules.mk
index 47db1fc..4e81251 100644
--- a/system/uapp/blobfs/rules.mk
+++ b/system/uapp/blobfs/rules.mk
@@ -22,6 +22,7 @@
     system/ulib/bitmap \
     system/ulib/blobfs \
     system/ulib/block-client \
+    system/ulib/cobalt-client \
     system/ulib/digest \
     system/ulib/fbl \
     system/ulib/fs \
@@ -43,6 +44,8 @@
     system/ulib/zircon \
 
 MODULE_FIDL_LIBS := \
+    system/fidl/fuchsia-cobalt \
     system/fidl/fuchsia-io \
+    system/fidl/fuchsia-mem \
 
 include make/module.mk
diff --git a/system/ulib/blobfs/blobfs.cpp b/system/ulib/blobfs/blobfs.cpp
index 35899b5..408079a 100644
--- a/system/ulib/blobfs/blobfs.cpp
+++ b/system/ulib/blobfs/blobfs.cpp
@@ -16,6 +16,7 @@
 #include <blobfs/extent-reserver.h>
 #include <blobfs/lz4.h>
 #include <blobfs/node-reserver.h>
+#include <cobalt-client/cpp/collector.h>
 #include <digest/digest.h>
 #include <digest/merkle-tree.h>
 #include <fbl/auto_call.h>
@@ -40,6 +41,39 @@
 namespace blobfs {
 namespace {
 
+cobalt_client::CollectorOptions MakeCollectorOptions() {
+    cobalt_client::CollectorOptions options = cobalt_client::CollectorOptions::Debug();
+#ifdef __Fuchsia__
+    // Reads from boot the cobalt_filesystem.pb
+    options.load_config = [](zx::vmo* out_vmo, size_t* out_size) -> bool {
+        fbl::unique_fd config_fd(open("/boot/config/cobalt_filesystem.pb", O_RDONLY));
+        if (!config_fd) {
+            return false;
+        }
+        *out_size = lseek(config_fd.get(), 0L, SEEK_END);
+        if (*out_size <= 0) {
+            return false;
+        }
+        zx_status_t result = zx::vmo::create(*out_size, 0, out_vmo);
+        if (result != ZX_OK) {
+            return false;
+        }
+        fbl::Array<uint8_t> buffer(new uint8_t[*out_size], *out_size);
+        memset(buffer.get(), 0, *out_size);
+        if (lseek(config_fd.get(), 0L, SEEK_SET) < 0) {
+            return false;
+        }
+        if (static_cast<uint32_t>(read(config_fd.get(), buffer.get(), buffer.size())) < *out_size) {
+            return false;
+        }
+        return out_vmo->write(buffer.get(), 0, *out_size) == ZX_OK;
+    };
+    options.initial_response_deadline = zx::usec(0);
+    options.response_deadline = zx::nsec(0);
+#endif // __Fuchsia__
+    return options;
+}
+
 zx_status_t CheckFvmConsistency(const Superblock* info, int block_fd) {
     if ((info->flags & kBlobFlagFVM) == 0) {
         return ZX_OK;
@@ -611,7 +645,9 @@
     status = EnqueueWork(std::move(wb), EnqueueType::kJournal);
 }
 
-Blobfs::Blobfs(fbl::unique_fd fd, const Superblock* info) : blockfd_(std::move(fd)) {
+Blobfs::Blobfs(fbl::unique_fd fd, const Superblock* info)
+    : blockfd_(std::move(fd)), metrics_(),
+      cobalt_metrics_(MakeCollectorOptions(), false, "blobfs") {
     memcpy(&info_, info, sizeof(Superblock));
 }
 
diff --git a/system/ulib/blobfs/include/blobfs/blobfs.h b/system/ulib/blobfs/include/blobfs/blobfs.h
index 1fef26e..d74b55e 100644
--- a/system/ulib/blobfs/include/blobfs/blobfs.h
+++ b/system/ulib/blobfs/include/blobfs/blobfs.h
@@ -28,6 +28,7 @@
 #include <fbl/vector.h>
 #include <fs/block-txn.h>
 #include <fs/managed-vfs.h>
+#include <fs/metrics.h>
 #include <fs/trace.h>
 #include <fs/vfs.h>
 #include <fs/vnode.h>
@@ -110,8 +111,10 @@
     CachePolicy cache_policy = CachePolicy::EvictImmediately;
 };
 
-class Blobfs : public fs::ManagedVfs, public fbl::RefCounted<Blobfs>,
-               public fs::TransactionHandler, public SpaceManager {
+class Blobfs : public fs::ManagedVfs,
+               public fbl::RefCounted<Blobfs>,
+               public fs::TransactionHandler,
+               public SpaceManager {
 public:
     DISALLOW_COPY_ASSIGN_AND_MOVE(Blobfs);
 
@@ -123,13 +126,9 @@
     ////////////////
     // fs::TransactionHandler interface.
 
-    uint32_t FsBlockSize() const final {
-        return kBlobfsBlockSize;
-    }
+    uint32_t FsBlockSize() const final { return kBlobfsBlockSize; }
 
-    uint32_t DeviceBlockSize() const final {
-        return block_info_.block_size;
-    }
+    uint32_t DeviceBlockSize() const final { return block_info_.block_size; }
 
     groupid_t BlockGroupID() final {
         thread_local groupid_t group_ = next_group_.fetch_add(1);
@@ -150,13 +149,10 @@
     zx_status_t AddInodes(fzl::ResizeableVmoMapper* node_map) final;
     zx_status_t AddBlocks(size_t nblocks, RawBitmap* block_map) final;
 
-
     ////////////////
     // Other methods.
 
-    uint64_t DataStart() const {
-        return DataStartBlock(info_);
-    }
+    uint64_t DataStart() const { return DataStartBlock(info_); }
 
     bool CheckBlocksAllocated(uint64_t start_block, uint64_t end_block,
                               uint64_t* first_unset = nullptr) const {
@@ -166,13 +162,9 @@
         return AllocatedExtentIterator(allocator_.get(), node_index);
     }
 
-    Allocator* GetAllocator() {
-        return allocator_.get();
-    }
+    Allocator* GetAllocator() { return allocator_.get(); }
 
-    Inode* GetNode(uint32_t node_index) {
-        return allocator_->GetNode(node_index);
-    }
+    Inode* GetNode(uint32_t node_index) { return allocator_->GetNode(node_index); }
     zx_status_t ReserveBlocks(size_t num_blocks, fbl::Vector<ReservedExtent>* out_extents) {
         return allocator_->ReserveBlocks(num_blocks, out_extents);
     }
@@ -184,13 +176,25 @@
                               const Superblock* info, fbl::unique_ptr<Blobfs>* out);
 
     void SetCachePolicy(CachePolicy policy) { cache_policy_ = policy; }
-    BlobfsMetrics& LocalMetrics() {
-        return metrics_;
+
+    BlobfsMetrics& LocalMetrics() { return metrics_; }
+
+    void CollectMetrics() {
+        collecting_metrics_ = true;
+        cobalt_metrics_.EnableMetrics(true);
+    }
+    bool CollectingMetrics() const { return cobalt_metrics_.IsEnabled(); }
+    void DisableMetrics() {
+        cobalt_metrics_.EnableMetrics(false);
+        collecting_metrics_ = false;
+    }
+    void DumpMetrics() const {
+        if (collecting_metrics_) {
+            metrics_.Dump();
+        }
     }
 
-    void SetUnmountCallback(fbl::Closure closure) {
-        on_unmount_ = std::move(closure);
-    }
+    void SetUnmountCallback(fbl::Closure closure) { on_unmount_ = std::move(closure); }
 
     // Initializes the WritebackQueue and Journal (if enabled in |options|),
     // replaying any existing journal entries.
@@ -228,9 +232,7 @@
 
     zx_status_t Readdir(fs::vdircookie_t* cookie, void* dirents, size_t len, size_t* out_actual);
 
-    int Fd() const {
-        return blockfd_.get();
-    }
+    int Fd() const { return blockfd_.get(); }
 
     const Superblock& Info() const { return info_; }
 
@@ -245,8 +247,8 @@
     // Enqueues |work| to the appropriate buffer. If |journal| is true and the journal is enabled,
     // the transaction(s) will first be written to the journal. Otherwise, they will be sent
     // straight to the writeback buffer.
-    zx_status_t EnqueueWork(fbl::unique_ptr<WritebackWork> work, EnqueueType type)
-        __WARN_UNUSED_RESULT;
+    zx_status_t EnqueueWork(fbl::unique_ptr<WritebackWork> work,
+                            EnqueueType type) __WARN_UNUSED_RESULT;
 
     // Does a single pass of all blobs, creating uninitialized Vnode
     // objects for them all.
@@ -276,6 +278,8 @@
     // Adds reserved blocks to allocated bitmap and writes the bitmap out to disk.
     void PersistBlocks(WritebackWork* wb, const ReservedExtent& extent);
 
+    fs::VnodeMetrics* GetMutableVnodeMetrics() { return cobalt_metrics_.mutable_vnode_metrics(); }
+
 private:
     friend class BlobfsChecker;
 
@@ -336,10 +340,8 @@
 
     // VnodeBlobs exist in the WAVLTree as long as one or more reference exists;
     // when the Vnode is deleted, it is immediately removed from the WAVL tree.
-    using WAVLTreeByMerkle = fbl::WAVLTree<const uint8_t*,
-                                           VnodeBlob*,
-                                           MerkleRootTraits,
-                                           VnodeBlob::TypeWavlTraits>;
+    using WAVLTreeByMerkle =
+        fbl::WAVLTree<const uint8_t*, VnodeBlob*, MerkleRootTraits, VnodeBlob::TypeWavlTraits>;
     fbl::unique_ptr<WritebackQueue> writeback_;
     fbl::unique_ptr<Journal> journal_;
     Superblock info_;
@@ -365,12 +367,14 @@
 
     CachePolicy cache_policy_;
     fbl::Closure on_unmount_ = {};
+
+    // TODO(gevalentino): clean up old metrics and update this to inspect API.
+    fs::Metrics cobalt_metrics_;
 };
 
 zx_status_t Initialize(fbl::unique_fd blockfd, const MountOptions& options,
                        fbl::unique_ptr<Blobfs>* out);
 zx_status_t Mount(async_dispatcher_t* dispatcher, fbl::unique_fd blockfd,
-                  const MountOptions& options, zx::channel root,
-                  fbl::Closure on_unmount);
+                  const MountOptions& options, zx::channel root, fbl::Closure on_unmount);
 
 } // namespace blobfs
diff --git a/system/ulib/blobfs/rules.mk b/system/ulib/blobfs/rules.mk
index 9dde8f1..c98c140 100644
--- a/system/ulib/blobfs/rules.mk
+++ b/system/ulib/blobfs/rules.mk
@@ -44,6 +44,7 @@
     system/ulib/async-loop.cpp \
     system/ulib/bitmap \
     system/ulib/block-client \
+    system/ulib/cobalt-client \
     system/ulib/digest \
     system/ulib/fbl \
     system/ulib/fs \
@@ -64,7 +65,9 @@
     system/ulib/zircon \
 
 TARGET_MODULE_FIDL_LIBS := \
+    system/fidl/fuchsia-cobalt \
     system/fidl/fuchsia-io \
+    system/fidl/fuchsia-mem \
 
 # target blobfs lib
 MODULE_SRCS := \
@@ -130,6 +133,7 @@
     -Isystem/ulib/digest/include \
     -Ithird_party/ulib/lz4/include \
     -Ithird_party/ulib/uboringssl/include \
+    -Isystem/ulib/cobalt-client/include \
     -Isystem/ulib/fbl/include \
     -Isystem/ulib/fs/include \
     -Isystem/ulib/fdio/include \
diff --git a/system/ulib/blobfs/vnode.cpp b/system/ulib/blobfs/vnode.cpp
index 7be661b..65874e7 100644
--- a/system/ulib/blobfs/vnode.cpp
+++ b/system/ulib/blobfs/vnode.cpp
@@ -15,9 +15,11 @@
 #include <zircon/device/device.h>
 #include <zircon/device/vfs.h>
 
+#include <cobalt-client/cpp/timer.h>
 #include <fbl/auto_call.h>
 #include <fbl/ref_ptr.h>
 #include <fbl/string_piece.h>
+#include <fs/metrics.h>
 #include <lib/fdio/debug.h>
 #include <lib/fdio/vfs.h>
 #include <lib/sync/completion.h>
@@ -36,12 +38,32 @@
 #include <utility>
 
 namespace blobfs {
-
 namespace {
 
 using digest::Digest;
 using digest::MerkleTree;
 
+// RAII interface for registering latency events.
+class LatencyEvent {
+public:
+    LatencyEvent(cobalt_client::Histogram<fs::VnodeMetrics::kHistogramBuckets>* histogram,
+                 bool collect)
+        : timer_(collect), histogram_(histogram) {}
+    LatencyEvent(LatencyEvent&& rhs)
+        : timer_(std::move(rhs.timer_)), histogram_(std::move(rhs.histogram_)) {}
+    ~LatencyEvent() {
+        zx::duration latency = timer_.End();
+        if (latency.get() > 0) {
+            ZX_DEBUG_ASSERT(histogram_ != nullptr);
+            histogram_->Add(latency.get());
+        }
+    }
+
+private:
+    cobalt_client::Timer timer_;
+    cobalt_client::Histogram<fs::VnodeMetrics::kHistogramBuckets>* histogram_;
+};
+
 // A wrapper around "Enqueue" for content which risks being larger
 // than the writeback buffer.
 //
@@ -238,8 +260,7 @@
     }
 
     blobfs_->LocalMetrics().UdpateMerkleDecompress(compressed_blocks * kBlobfsBlockSize,
-                                                   inode_.blob_size, read_time,
-                                                   ticker.End());
+                                                   inode_.blob_size, read_time, ticker.End());
     return ZX_OK;
 }
 
@@ -843,6 +864,7 @@
 
 zx_status_t VnodeBlob::Read(void* data, size_t len, size_t off, size_t* out_actual) {
     TRACE_DURATION("blobfs", "VnodeBlob::Read", "len", len, "off", off);
+    LatencyEvent event(&blobfs_->GetMutableVnodeMetrics()->read, blobfs_->CollectingMetrics());
 
     if (IsDirectory()) {
         return ZX_ERR_NOT_FILE;
@@ -853,6 +875,7 @@
 
 zx_status_t VnodeBlob::Write(const void* data, size_t len, size_t offset, size_t* out_actual) {
     TRACE_DURATION("blobfs", "VnodeBlob::Write", "len", len, "off", offset);
+    LatencyEvent event(&blobfs_->GetMutableVnodeMetrics()->write, blobfs_->CollectingMetrics());
     if (IsDirectory()) {
         return ZX_ERR_NOT_FILE;
     }
@@ -860,6 +883,7 @@
 }
 
 zx_status_t VnodeBlob::Append(const void* data, size_t len, size_t* out_end, size_t* out_actual) {
+    LatencyEvent event(&blobfs_->GetMutableVnodeMetrics()->append, blobfs_->CollectingMetrics());
     zx_status_t status = WriteInternal(data, len, out_actual);
     if (GetState() == kBlobStateDataWrite) {
         ZX_DEBUG_ASSERT(write_info_ != nullptr);
@@ -872,6 +896,7 @@
 
 zx_status_t VnodeBlob::Lookup(fbl::RefPtr<fs::Vnode>* out, fbl::StringPiece name) {
     TRACE_DURATION("blobfs", "VnodeBlob::Lookup", "name", name);
+    LatencyEvent event(&blobfs_->GetMutableVnodeMetrics()->look_up, blobfs_->CollectingMetrics());
     assert(memchr(name.data(), '/', name.length()) == nullptr);
     if (name == "." && IsDirectory()) {
         // Special case: Accessing root directory via '.'
@@ -897,6 +922,7 @@
 }
 
 zx_status_t VnodeBlob::Getattr(vnattr_t* a) {
+    LatencyEvent event(&blobfs_->GetMutableVnodeMetrics()->get_attr, blobfs_->CollectingMetrics());
     memset(a, 0, sizeof(vnattr_t));
     a->mode = (IsDirectory() ? V_TYPE_DIR : V_TYPE_FILE) | V_IRUSR;
     a->inode = fuchsia_io_INO_UNKNOWN;
@@ -911,6 +937,7 @@
 
 zx_status_t VnodeBlob::Create(fbl::RefPtr<fs::Vnode>* out, fbl::StringPiece name, uint32_t mode) {
     TRACE_DURATION("blobfs", "VnodeBlob::Create", "name", name, "mode", mode);
+    LatencyEvent event(&blobfs_->GetMutableVnodeMetrics()->create, blobfs_->CollectingMetrics());
     assert(memchr(name.data(), '/', name.length()) == nullptr);
 
     if (!IsDirectory()) {
@@ -933,6 +960,7 @@
 
 zx_status_t VnodeBlob::Truncate(size_t len) {
     TRACE_DURATION("blobfs", "VnodeBlob::Truncate", "len", len);
+    LatencyEvent event(&blobfs_->GetMutableVnodeMetrics()->truncate, blobfs_->CollectingMetrics());
 
     if (IsDirectory()) {
         return ZX_ERR_NOT_SUPPORTED;
@@ -974,6 +1002,7 @@
 
 zx_status_t VnodeBlob::Unlink(fbl::StringPiece name, bool must_be_dir) {
     TRACE_DURATION("blobfs", "VnodeBlob::Unlink", "name", name, "must_be_dir", must_be_dir);
+    LatencyEvent event(&blobfs_->GetMutableVnodeMetrics()->unlink, blobfs_->CollectingMetrics());
     assert(memchr(name.data(), '/', name.length()) == nullptr);
 
     if (!IsDirectory()) {
@@ -1014,8 +1043,9 @@
 }
 
 void VnodeBlob::Sync(SyncCallback closure) {
+    LatencyEvent event(&blobfs_->GetMutableVnodeMetrics()->sync, blobfs_->CollectingMetrics());
     if (atomic_load(&syncing_)) {
-        blobfs_->Sync([this, cb = std::move(closure)](zx_status_t status) {
+        blobfs_->Sync([this, evt = std::move(event), cb = std::move(closure)](zx_status_t status) {
             if (status != ZX_OK) {
                 cb(status);
                 return;
@@ -1051,6 +1081,7 @@
 }
 
 zx_status_t VnodeBlob::Close() {
+    LatencyEvent event(&blobfs_->GetMutableVnodeMetrics()->close, blobfs_->CollectingMetrics());
     ZX_DEBUG_ASSERT_MSG(fd_count_ > 0, "Closing blob with no fds open");
     fd_count_--;
     // Attempt purge in case blob was unlinked prior to close
diff --git a/system/utest/blobfs/rules.mk b/system/utest/blobfs/rules.mk
index 2bf5117..acf3d1a 100644
--- a/system/utest/blobfs/rules.mk
+++ b/system/utest/blobfs/rules.mk
@@ -23,6 +23,7 @@
     system/ulib/bitmap \
     system/ulib/blobfs \
     system/ulib/block-client \
+    system/ulib/cobalt-client \
     system/ulib/digest \
     system/ulib/fbl \
     system/ulib/fvm \
@@ -48,6 +49,8 @@
     system/ulib/zircon \
 
 MODULE_FIDL_LIBS := \
+    system/fidl/fuchsia-cobalt \
     system/fidl/fuchsia-io \
+    system/fidl/fuchsia-mem \
 
 include make/module.mk