[RocksDB] Added nano second stopwatch and new perf counters to track block read cost

Summary: The pupose of this diff is to expose per user-call level precise timing of block read, so that we can answer questions like: a Get() costs me 100ms, is that somehow related to loading blocks from file system, or sth else? We will answer that with EXACTLY how many blocks have been read, how much time was spent on transfering the bytes from os, how much time was spent on checksum verification and how much time was spent on block decompression, just for that one Get. A nano second stopwatch was introduced to track time with higher precision. The cost/precision of the stopwatch is also measured in unit-test. On my dev box, retrieving one time instance costs about 30ns, on average. The deviation of timing results is good enough to track 100ns-1us level events. And the overhead could be safely ignored for 100us level events (10000 instances/s), for example, a viewstate thrift call.

Test Plan: perf_context_test, also testing with viewstate shadow traffic.

Reviewers: dhruba

Reviewed By: dhruba

CC: leveldb, xjin

Differential Revision: https://reviews.facebook.net/D12351

table/format.cc

@@ -4,11 +4,12 @@
 
 #include "table/format.h"
 
-#include "rocksdb/env.h"
 #include "port/port.h"
+#include "rocksdb/env.h"
 #include "table/block.h"
 #include "util/coding.h"
 #include "util/crc32c.h"
+#include "util/perf_context_imp.h"
 
 namespace leveldb {
 
@@ -69,7 +70,8 @@ Status Footer::DecodeFrom(Slice* input) {
 Status ReadBlockContents(RandomAccessFile* file,
                          const ReadOptions& options,
                          const BlockHandle& handle,
-                         BlockContents* result) {
+                         BlockContents* result,
+                         Env* env) {
   result->data = Slice();
   result->cachable = false;
   result->heap_allocated = false;
@@ -79,7 +81,14 @@ Status ReadBlockContents(RandomAccessFile* file,
   size_t n = static_cast<size_t>(handle.size());
   char* buf = new char[n + kBlockTrailerSize];
   Slice contents;
+
+  StopWatchNano timer(env);
+  StartPerfTimer(&timer);
   Status s = file->Read(handle.offset(), n + kBlockTrailerSize, &contents, buf);
+  BumpPerfCount(&perf_context.block_read_count);
+  BumpPerfCount(&perf_context.block_read_byte, n + kBlockTrailerSize);
+  BumpPerfTime(&perf_context.block_read_time, &timer);
+
   if (!s.ok()) {
     delete[] buf;
     return s;
@@ -99,6 +108,7 @@ Status ReadBlockContents(RandomAccessFile* file,
       s = Status::Corruption("block checksum mismatch");
       return s;
     }
+    BumpPerfTime(&perf_context.block_checksum_time, &timer);
   }
 
   char* ubuf = nullptr;
@@ -172,6 +182,8 @@ Status ReadBlockContents(RandomAccessFile* file,
       return Status::Corruption("bad block type");
   }
 
+  BumpPerfTime(&perf_context.block_decompress_time, &timer);
+
   return Status::OK();
 }
 

table/format.h

@@ -94,7 +94,8 @@ struct BlockContents {
 extern Status ReadBlockContents(RandomAccessFile* file,
                                 const ReadOptions& options,
                                 const BlockHandle& handle,
-                                BlockContents* result);
+                                BlockContents* result,
+                                Env* env);
 
 // Implementation details follow.  Clients should ignore,
 

table/table.cc

@@ -19,6 +19,7 @@
 #include "table/two_level_iterator.h"
 
 #include "util/coding.h"
+#include "util/perf_context_imp.h"
 #include "util/stop_watch.h"
 
 namespace leveldb {
@@ -81,9 +82,10 @@ Status ReadBlock(RandomAccessFile* file,
                  const ReadOptions& options,
                  const BlockHandle& handle,
                  Block** result,
+                 Env* env,
                  bool* didIO = nullptr) {
   BlockContents contents;
-  Status s = ReadBlockContents(file, options, handle, &contents);
+  Status s = ReadBlockContents(file, options, handle, &contents, env);
   if (s.ok()) {
     *result = new Block(contents);
   }
@@ -118,14 +120,14 @@ Status Table::Open(const Options& options,
     return Status::InvalidArgument("file is too short to be an sstable");
   }
 
-
   Footer footer;
   s = footer.DecodeFrom(&footer_input);
   if (!s.ok()) return s;
 
   Block* index_block = nullptr;
   // TODO: we never really verify check sum for index block
-  s = ReadBlock(file.get(), ReadOptions(), footer.index_handle(), &index_block);
+  s = ReadBlock(file.get(), ReadOptions(), footer.index_handle(), &index_block,
+                options.env);
 
   if (s.ok()) {
     // We've successfully read the footer and the index block: we're
@@ -176,7 +178,7 @@ void Table::ReadMeta(const Footer& footer) {
   //  TODO: we never really verify check sum for meta index block
   Block* meta = nullptr;
   if (!ReadBlock(rep_->file.get(), ReadOptions(), footer.metaindex_handle(),
-                 &meta).ok()) {
+                 &meta, rep_->options.env).ok()) {
     // Do not propagate errors since meta info is not needed for operation
     return;
   }
@@ -203,7 +205,8 @@ void Table::ReadFilter(const Slice& filter_handle_value) {
   // requiring checksum verification in Table::Open.
   ReadOptions opt;
   BlockContents block;
-  if (!ReadBlockContents(rep_->file.get(), opt, filter_handle, &block).ok()) {
+  if (!ReadBlockContents(rep_->file.get(), opt, filter_handle, &block,
+                        rep_->options.env).ok()) {
     return;
   }
   if (block.heap_allocated) {
@@ -266,6 +269,7 @@ Iterator* Table::BlockReader(void* arg,
       if (cache_handle != nullptr) {
         block = reinterpret_cast<Block*>(block_cache->Value(cache_handle));
 
+        BumpPerfCount(&perf_context.block_cache_hit_count);
         RecordTick(statistics, BLOCK_CACHE_HIT);
       } else if (no_io) {
         // Did not find in block_cache and can't do IO
@@ -280,6 +284,7 @@ Iterator* Table::BlockReader(void* arg,
                 options,
                 handle,
                 &block,
+                table->rep_->options.env,
                 didIO
               );
         }
@@ -295,8 +300,9 @@ Iterator* Table::BlockReader(void* arg,
     } else if (no_io) {
       // Could not read from block_cache and can't do IO
       return NewErrorIterator(Status::Incomplete("no blocking io"));
-    }else {
-      s = ReadBlock(table->rep_->file.get(), options, handle, &block, didIO);
+    } else {
+      s = ReadBlock(table->rep_->file.get(), options, handle, &block,
+                    table->rep_->options.env, didIO);
     }
   }