Report elapsed time in micros in ThreadStatus instead of start time.

Summary:
Report elapsed time of a thread operation in micros in ThreadStatus
instead of start time of a thread operation in seconds since the
Epoch, 1970-01-01 00:00:00 (UTC).

Test Plan:
./db_bench --benchmarks=fillrandom --num=100000 --threads=40 \
--max_background_compactions=10 --max_background_flushes=3 \
--thread_status_per_interval=1000 --key_size=16 --value_size=1000 \
--num_column_families=10

Sample Output:
            ThreadID ThreadType                    cfName    Operation  ElapsedTime                                         Stage        State
     140667724562496   High Pri column_family_name_000002        Flush   772.419 ms                    FlushJob::WriteLevel0Table
     140667728756800   High Pri                   default        Flush   617.845 ms                    FlushJob::WriteLevel0Table
     140667732951104   High Pri column_family_name_000005        Flush   772.078 ms                    FlushJob::WriteLevel0Table
     140667875557440    Low Pri column_family_name_000008   Compaction  1409.216 ms                        CompactionJob::Install
     140667737145408    Low Pri
     140667749728320    Low Pri
     140667816837184    Low Pri column_family_name_000007   Compaction  1071.815 ms      CompactionJob::ProcessKeyValueCompaction
     140667787477056    Low Pri column_family_name_000009   Compaction   772.516 ms      CompactionJob::ProcessKeyValueCompaction
     140667741339712    Low Pri
     140667758116928    Low Pri column_family_name_000004   Compaction   620.739 ms      CompactionJob::ProcessKeyValueCompaction
     140667753922624    Low Pri
     140667842003008    Low Pri column_family_name_000006   Compaction  1260.079 ms      CompactionJob::ProcessKeyValueCompaction
     140667745534016    Low Pri

Reviewers: sdong, igor, rven

Subscribers: dhruba, leveldb

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

db/db_bench.cc

@@ -937,28 +937,19 @@ class Stats {
     std::vector<ThreadStatus> thread_list;
     FLAGS_env->GetThreadList(&thread_list);
 
-    fprintf(stderr, "\n%18s %10s %25s %12s %20s %13s %45s %12s\n",
+    fprintf(stderr, "\n%18s %10s %25s %12s %12s %45s %12s\n",
         "ThreadID", "ThreadType", "cfName", "Operation",
-        "OP_StartTime ", "ElapsedTime", "Stage", "State");
+        "ElapsedTime", "Stage", "State");
 
     int64_t current_time = 0;
     Env::Default()->GetCurrentTime(&current_time);
     for (auto ts : thread_list) {
-      char elapsed_time[25];
+      fprintf(stderr, "%18" PRIu64 " %10s %25s %12s %12s %45s %12s\n",
-      if (ts.op_start_time != 0) {
-        AppendHumanMicros(
-            current_time - ts.op_start_time,
-            elapsed_time, 24);
-      } else {
-        elapsed_time[0] = 0;
-      }
-      fprintf(stderr, "%18" PRIu64 " %10s %25s %12s %20s %13s %45s %12s\n",
           ts.thread_id,
           ThreadStatus::GetThreadTypeName(ts.thread_type).c_str(),
           ts.cf_name.c_str(),
           ThreadStatus::GetOperationName(ts.operation_type).c_str(),
-          ThreadStatus::TimeToString(ts.op_start_time).c_str(),
+          ThreadStatus::MicrosToString(ts.op_elapsed_micros).c_str(),
-          elapsed_time,
           ThreadStatus::GetOperationStageName(ts.operation_stage).c_str(),
           ThreadStatus::GetStateName(ts.state_type).c_str());
     }

include/rocksdb/thread_status.h

@@ -78,14 +78,14 @@ struct ThreadStatus {
                const std::string& _db_name,
                const std::string& _cf_name,
                const OperationType _operation_type,
-               const int64_t _op_start_time,
+               const uint64_t _op_elapsed_micros,
                const OperationStage _operation_stage,
                const StateType _state_type) :
       thread_id(_id), thread_type(_thread_type),
       db_name(_db_name),
       cf_name(_cf_name),
       operation_type(_operation_type),
-      op_start_time(_op_start_time),
+      op_elapsed_micros(_op_elapsed_micros),
       operation_stage(_operation_stage),
       state_type(_state_type) {}
 
@@ -109,9 +109,8 @@ struct ThreadStatus {
   // The operation (high-level action) that the current thread is involved.
   const OperationType operation_type;
 
-  // The start time of the current status in the form of seconds since the
+  // The elapsed time in micros of the current thread operation.
-  // Epoch, 1970-01-01 00:00:00 (UTC).
+  const uint64_t op_elapsed_micros;
-  const int64_t op_start_time;
 
   // An integer showing the current stage where the thread is involved
   // in the current operation.
@@ -128,7 +127,7 @@ struct ThreadStatus {
   // Obtain the name of an operation given its type.
   static const std::string& GetOperationName(OperationType op_type);
 
-  static const std::string TimeToString(int64_t op_start_time);
+  static const std::string MicrosToString(uint64_t op_elapsed_time);
 
   // Obtain a human-readable string describing the specified operation stage.
   static const std::string& GetOperationStageName(

util/thread_status_impl.cc

@@ -6,6 +6,7 @@
 
 #include "rocksdb/env.h"
 #include "rocksdb/thread_status.h"
+#include "util/logging.h"
 #include "util/thread_operation.h"
 
 namespace rocksdb {
@@ -33,12 +34,14 @@ const std::string& ThreadStatus::GetStateName(
   return global_state_table[state_type].name;
 }
 
-const std::string ThreadStatus::TimeToString(
+const std::string ThreadStatus::MicrosToString(uint64_t micros) {
-    int64_t time) {
+  if (micros == 0) {
-  if (time == 0) {
     return "";
   }
-  return Env::Default()->TimeToString(time);
+  const int kBufferLen = 100;
+  char buffer[kBufferLen];
+  AppendHumanMicros(micros, buffer, kBufferLen);
+  return std::string(buffer);
 }
 
 #else

util/thread_status_updater.cc

@@ -4,6 +4,7 @@
 // of patent rights can be found in the PATENTS file in the same directory.
 
 #include <memory>
+#include "rocksdb/env.h"
 #include "port/likely.h"
 #include "util/mutexlock.h"
 #include "util/thread_status_updater.h"
@@ -65,7 +66,7 @@ void ThreadStatusUpdater::SetThreadOperation(
   data->operation_type.store(type, std::memory_order_relaxed);
 }
 
-void ThreadStatusUpdater::SetOperationStartTime(const int64_t start_time) {
+void ThreadStatusUpdater::SetOperationStartTime(const uint64_t start_time) {
   auto* data = InitAndGet();
   if (!data->enable_tracking) {
     assert(data->cf_key.load(std::memory_order_relaxed) == nullptr);
@@ -121,6 +122,7 @@ Status ThreadStatusUpdater::GetThreadList(
     std::vector<ThreadStatus>* thread_list) {
   thread_list->clear();
   std::vector<std::shared_ptr<ThreadStatusData>> valid_list;
+  uint64_t now_micros = Env::Default()->NowMicros();
 
   std::lock_guard<std::mutex> lck(thread_list_mutex_);
   for (auto* thread_data : thread_data_set_) {
@@ -141,7 +143,7 @@ Status ThreadStatusUpdater::GetThreadList(
     ThreadStatus::OperationType op_type = ThreadStatus::OP_UNKNOWN;
     ThreadStatus::OperationStage op_stage = ThreadStatus::STAGE_UNKNOWN;
     ThreadStatus::StateType state_type = ThreadStatus::STATE_UNKNOWN;
-    int64_t op_start_time = 0;
+    uint64_t op_elapsed_micros = 0;
     if (cf_info != nullptr) {
       db_name = &cf_info->db_name;
       cf_name = &cf_info->cf_name;
@@ -149,7 +151,7 @@ Status ThreadStatusUpdater::GetThreadList(
           std::memory_order_relaxed);
       // display lower-level info only when higher-level info is available.
       if (op_type != ThreadStatus::OP_UNKNOWN) {
-        op_start_time = thread_data->op_start_time.load(
+        op_elapsed_micros = now_micros - thread_data->op_start_time.load(
             std::memory_order_relaxed);
         op_stage = thread_data->operation_stage.load(
             std::memory_order_relaxed);
@@ -161,7 +163,7 @@ Status ThreadStatusUpdater::GetThreadList(
         thread_data->thread_id, thread_type,
         db_name ? *db_name : "",
         cf_name ? *cf_name : "",
-        op_type, op_start_time, op_stage, state_type);
+        op_type, op_elapsed_micros, op_stage, state_type);
   }
 
   return Status::OK();

util/thread_status_updater.h

@@ -86,7 +86,7 @@ struct ThreadStatusData {
   std::atomic<ThreadStatus::ThreadType> thread_type;
   std::atomic<const void*> cf_key;
   std::atomic<ThreadStatus::OperationType> operation_type;
-  std::atomic<int64_t> op_start_time;
+  std::atomic<uint64_t> op_start_time;
   std::atomic<ThreadStatus::OperationStage> operation_stage;
   std::atomic<ThreadStatus::StateType> state_type;
 #endif  // ROCKSDB_USING_THREAD_STATUS
@@ -127,8 +127,9 @@ class ThreadStatusUpdater {
   // Update the thread operation of the current thread.
   void SetThreadOperation(const ThreadStatus::OperationType type);
 
-  // Set the start time of an operation.
+  // The start time of the current thread operation.  It is in the format
-  void SetOperationStartTime(const int64_t start_time);
+  // of micro-seconds since some fixed point in time.
+  void SetOperationStartTime(const uint64_t start_time);
 
   // Update the thread operation stage of the current thread.
   ThreadStatus::OperationStage SetThreadOperationStage(

util/thread_status_util.cc

@@ -55,8 +55,7 @@ void ThreadStatusUtil::SetThreadOperation(ThreadStatus::OperationType op) {
   }
 
   if (op != ThreadStatus::OP_UNKNOWN) {
-    int64_t current_time = 0;
+    uint64_t current_time = Env::Default()->NowMicros();
-    Env::Default()->GetCurrentTime(&current_time);
     thread_updater_local_cache_->SetOperationStartTime(current_time);
   } else {
     // TDOO(yhchiang): we could report the time when we set operation to