Fix a bug in stall time counter. Improve its output format.

Summary: Fix a bug in stall time counter.  Improve its output format.

Test Plan:
export ROCKSDB_TESTS=Timeout
./db_test

./db_bench --benchmarks=fillrandom --stats_interval=10000 --statistics=true --stats_per_interval=1 --num=1000000 --threads=4 --level0_stop_writes_trigger=3 --level0_slowdown_writes_trigger=2

sample output:
    Uptime(secs): 35.8 total, 0.0 interval
    Cumulative writes: 359590 writes, 359589 keys, 183047 batches, 2.0 writes per batch, 0.04 GB user ingest, stall seconds: 1786.008 ms
    Cumulative WAL: 359591 writes, 183046 syncs, 1.96 writes per sync, 0.04 GB written
    Interval writes: 253 writes, 253 keys, 128 batches, 2.0 writes per batch, 0.0 MB user ingest, stall time: 0 us
    Interval WAL: 253 writes, 128 syncs, 1.96 writes per sync, 0.00 MB written

Reviewers: MarkCallaghan, igor, sdong

Reviewed By: sdong

Subscribers: dhruba, leveldb

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

db/db_impl.cc

@@ -3233,6 +3233,7 @@ Status DBImpl::Write(const WriteOptions& write_options, WriteBatch* my_batch) {
 Status DBImpl::DelayWrite(uint64_t expiration_time) {
   uint64_t time_delayed = 0;
   bool delayed = false;
+  bool timed_out = false;
   {
     StopWatch sw(env_, stats_, WRITE_STALL, &time_delayed);
     bool has_timeout = (expiration_time > 0);
@@ -3250,7 +3251,8 @@ Status DBImpl::DelayWrite(uint64_t expiration_time) {
       if (has_timeout) {
         bg_cv_.TimedWait(expiration_time);
         if (env_->NowMicros() > expiration_time) {
-          return Status::TimedOut();
+          timed_out = true;
+          break;
         }
       } else {
         bg_cv_.Wait();
@@ -3263,6 +3265,10 @@ Status DBImpl::DelayWrite(uint64_t expiration_time) {
     RecordTick(stats_, STALL_MICROS, time_delayed);
   }
 
+  if (timed_out) {
+    return Status::TimedOut();
+  }
+
   return bg_error_;
 }
 

db/internal_stats.cc

@@ -312,6 +312,9 @@ void InternalStats::DumpDBStats(std::string* value) {
   uint64_t wal_synced = db_stats_[InternalStats::WAL_FILE_SYNCED];
   uint64_t write_with_wal = db_stats_[InternalStats::WRITE_WITH_WAL];
   uint64_t write_stall_micros = db_stats_[InternalStats::WRITE_STALL_MICROS];
+  const int kHumanMicrosLen = 32;
+  char human_micros[kHumanMicrosLen];
+
   // Data
   // writes: total number of write requests.
   // keys: total number of key updates issued by all the write requests
@@ -321,13 +324,14 @@ void InternalStats::DumpDBStats(std::string* value) {
   // writes/batches is the average group commit size.
   //
   // The format is the same for interval stats.
+  AppendHumanMicros(write_stall_micros, human_micros, kHumanMicrosLen);
   snprintf(buf, sizeof(buf),
            "Cumulative writes: %" PRIu64 " writes, %" PRIu64 " keys, %" PRIu64
            " batches, %.1f writes per batch, %.2f GB user ingest, "
-           "stall micros: %" PRIu64 "\n",
+           "stall time: %s\n",
            write_other + write_self, num_keys_written, write_self,
            (write_other + write_self) / static_cast<double>(write_self + 1),
-           user_bytes_written / kGB, write_stall_micros);
+           user_bytes_written / kGB, human_micros);
   value->append(buf);
   // WAL
   snprintf(buf, sizeof(buf),
@@ -343,16 +347,19 @@ void InternalStats::DumpDBStats(std::string* value) {
   uint64_t interval_write_self = write_self - db_stats_snapshot_.write_self;
   uint64_t interval_num_keys_written =
       num_keys_written - db_stats_snapshot_.num_keys_written;
+  AppendHumanMicros(
+      write_stall_micros - db_stats_snapshot_.write_stall_micros,
+      human_micros, kHumanMicrosLen);
   snprintf(buf, sizeof(buf),
            "Interval writes: %" PRIu64 " writes, %" PRIu64 " keys, %" PRIu64
            " batches, %.1f writes per batch, %.1f MB user ingest, "
-           "stall micros: %" PRIu64 "\n",
+           "stall time: %s\n",
            interval_write_other + interval_write_self,
            interval_num_keys_written, interval_write_self,
            static_cast<double>(interval_write_other + interval_write_self) /
                (interval_write_self + 1),
            (user_bytes_written - db_stats_snapshot_.ingest_bytes) / kMB,
-           write_stall_micros - db_stats_snapshot_.write_stall_micros);
+           human_micros);
   value->append(buf);
 
   uint64_t interval_write_with_wal =

util/logging.cc

@@ -23,6 +23,20 @@
 
 namespace rocksdb {
 
+// for micros < 10ms, print "XX us".
+// for micros < 10sec, print "XX ms".
+// for micros >= 10 sec, print "XX sec".
+int AppendHumanMicros(uint64_t micros, char* output, int len) {
+  if (micros < 10000) {
+    return snprintf(output, len, "%" PRIu64 " us", micros);
+  } else if (micros < 10000000) {
+    return snprintf(output, len, "%.3lf ms",
+                    static_cast<double>(micros) / 1000);
+  } else {
+    return snprintf(output, len, "%.3lf sec",
+                    static_cast<double>(micros) / 1000000);
+  }
+}
 
 // for sizes >=10TB, print "XXTB"
 // for sizes >=10GB, print "XXGB"

util/logging.h

@@ -20,6 +20,9 @@ namespace rocksdb {
 
 class Slice;
 
+// Append a human-readable time in micros.
+int AppendHumanMicros(uint64_t micros, char* output, int len);
+
 // Append a human-readable size in bytes
 int AppendHumanBytes(uint64_t bytes, char* output, int len);