From 91d7c03cdcb021e270db3b7fcb3f55bc9d357597 Mon Sep 17 00:00:00 2001
From: Zhongyi Xie <xiez@fb.com>
Date: Fri, 13 Jul 2018 18:29:50 -0700
Subject: [PATCH] Exclude time waiting for rate limiter from
 rocksdb.sst.read.micros (#4102)

Summary:
Our "rocksdb.sst.read.micros" stat includes time spent waiting for rate limiter. It probably only affects people rate limiting compaction reads, which is fairly rare.
Pull Request resolved: https://github.com/facebook/rocksdb/pull/4102

Differential Revision: D8848506

Pulled By: miasantreble

fbshipit-source-id: 01258ac5ae56e4eee372978cfc9143a6869f8bfc
---
 util/file_reader_writer.cc |  9 ++++++++-
 util/stop_watch.h          | 31 ++++++++++++++++++++++++++++++-
 2 files changed, 38 insertions(+), 2 deletions(-)

diff --git a/util/file_reader_writer.cc b/util/file_reader_writer.cc
index 9efc24806..ae1e6671d 100644
--- a/util/file_reader_writer.cc
+++ b/util/file_reader_writer.cc
@@ -75,7 +75,8 @@ Status RandomAccessFileReader::Read(uint64_t offset, size_t n, Slice* result,
   uint64_t elapsed = 0;
   {
     StopWatch sw(env_, stats_, hist_type_,
-                 (stats_ != nullptr) ? &elapsed : nullptr);
+                 (stats_ != nullptr) ? &elapsed : nullptr, true /*overwrite*/,
+                true /*delay_enabled*/);
     IOSTATS_TIMER_GUARD(read_nanos);
     if (use_direct_io()) {
 #ifndef ROCKSDB_LITE
@@ -117,9 +118,15 @@ Status RandomAccessFileReader::Read(uint64_t offset, size_t n, Slice* result,
       while (pos < n) {
         size_t allowed;
         if (for_compaction_ && rate_limiter_ != nullptr) {
+          if (rate_limiter_->IsRateLimited(RateLimiter::OpType::kRead)) {
+            sw.DelayStart();
+          }
           allowed = rate_limiter_->RequestToken(n - pos, 0 /* alignment */,
                                                 Env::IOPriority::IO_LOW, stats_,
                                                 RateLimiter::OpType::kRead);
+          if (rate_limiter_->IsRateLimited(RateLimiter::OpType::kRead)) {
+            sw.DelayStop();
+          }
         } else {
           allowed = n;
         }
diff --git a/util/stop_watch.h b/util/stop_watch.h
index 89be103b7..b018eb1d6 100644
--- a/util/stop_watch.h
+++ b/util/stop_watch.h
@@ -15,13 +15,17 @@ namespace rocksdb {
 class StopWatch {
  public:
   StopWatch(Env* const env, Statistics* statistics, const uint32_t hist_type,
-            uint64_t* elapsed = nullptr, bool overwrite = true)
+            uint64_t* elapsed = nullptr, bool overwrite = true,
+            bool delay_enabled = false)
       : env_(env),
         statistics_(statistics),
         hist_type_(hist_type),
         elapsed_(elapsed),
         overwrite_(overwrite),
         stats_enabled_(statistics && statistics->HistEnabledForType(hist_type)),
+        delay_enabled_(delay_enabled),
+        total_delay_(0),
+        delay_start_time_(0),
         start_time_((stats_enabled_ || elapsed != nullptr) ? env->NowMicros()
                                                            : 0) {}
 
@@ -33,6 +37,9 @@ class StopWatch {
         *elapsed_ += env_->NowMicros() - start_time_;
       }
     }
+    if (elapsed_ && delay_enabled_) {
+      *elapsed_ -= total_delay_;
+    }
     if (stats_enabled_) {
       statistics_->measureTime(hist_type_,
           (elapsed_ != nullptr) ? *elapsed_ :
@@ -40,6 +47,25 @@ class StopWatch {
     }
   }
 
+  void DelayStart() {
+    // if delay_start_time_ is not 0, it means we are already tracking delay,
+    // so delay_start_time_ should not be overwritten
+    if (elapsed_ && delay_enabled_ && delay_start_time_ == 0) {
+      delay_start_time_ = env_->NowMicros();
+    }
+  }
+
+  void DelayStop() {
+    if (elapsed_ && delay_enabled_ && delay_start_time_ != 0) {
+      total_delay_ += env_->NowMicros() - delay_start_time_;
+    }
+    // reset to 0 means currently no delay is being tracked, so two consecutive
+    // calls to DelayStop will not increase total_delay_
+    delay_start_time_ = 0;
+  }
+
+  uint64_t GetDelay() const { return delay_enabled_ ? total_delay_ : 0; }
+
   uint64_t start_time() const { return start_time_; }
 
  private:
@@ -49,6 +75,9 @@ class StopWatch {
   uint64_t* elapsed_;
   bool overwrite_;
   bool stats_enabled_;
+  bool delay_enabled_;
+  uint64_t total_delay_;
+  uint64_t delay_start_time_;
   const uint64_t start_time_;
 };