Refactor time measurement to use std::chrono::steady_clock in benchmark tools. Previously used gettimeofday can be adjusted backwards, resulting in incorrect measurements.

Author: olegmak

tools/bpm_bench/bpm_bench.cpp

@@ -34,21 +34,13 @@
 #include "fmt/std.h"
 #include "storage/disk/disk_manager_memory.h"
 
-#include <sys/time.h>
-
-auto ClockMs() -> uint64_t {
-  struct timeval tm;
-  gettimeofday(&tm, nullptr);
-  return static_cast<uint64_t>(tm.tv_sec * 1000) + static_cast<uint64_t>(tm.tv_usec / 1000);
-}
-
 struct BpmTotalMetrics {
   uint64_t scan_cnt_{0};
   uint64_t get_cnt_{0};
-  uint64_t start_time_{0};
+  std::chrono::steady_clock::time_point start_time_;
   std::mutex mutex_;
 
-  void Begin() { start_time_ = ClockMs(); }
+  void Begin() { start_time_ = std::chrono::steady_clock::now(); }
 
   void ReportScan(uint64_t scan_cnt) {
     std::unique_lock<std::mutex> l(mutex_);
@@ -61,8 +53,8 @@ struct BpmTotalMetrics {
   }
 
   void Report() {
-    auto now = ClockMs();
-    auto elapsed = now - start_time_;
+    auto now = std::chrono::steady_clock::now();
+    auto elapsed = std::chrono::duration_cast<std::chrono::milliseconds>(now - start_time_).count();
     auto scan_per_sec = scan_cnt_ / static_cast<double>(elapsed) * 1000;
     auto get_per_sec = get_cnt_ / static_cast<double>(elapsed) * 1000;
 
@@ -74,7 +66,7 @@ struct BpmTotalMetrics {
 };
 
 struct BpmMetrics {
-  uint64_t start_time_{0};
+  std::chrono::steady_clock::time_point start_time_;
   uint64_t last_report_at_{0};
   uint64_t last_cnt_{0};
   uint64_t cnt_{0};
@@ -86,12 +78,12 @@ struct BpmMetrics {
 
   void Tick() { cnt_ += 1; }
 
-  void Begin() { start_time_ = ClockMs(); }
+  void Begin() { start_time_ = std::chrono::steady_clock::now(); }
 
   void Report() {
-    auto now = ClockMs();
-    auto elapsed = now - start_time_;
-    if (elapsed - last_report_at_ > 1000) {
+    auto now = std::chrono::steady_clock::now();
+    auto elapsed = std::chrono::duration_cast<std::chrono::milliseconds>(now - start_time_).count();
+    if (elapsed - last_report_at_ >= 1000) {
       fmt::print(stderr, "[{:5.2f}] {}: total_cnt={:<10} throughput={:<10.3f} avg_throughput={:<10.3f}\n",
                  elapsed / 1000.0, reporter_, cnt_,
                  (cnt_ - last_cnt_) / static_cast<double>(elapsed - last_report_at_) * 1000,
@@ -102,8 +94,8 @@ struct BpmMetrics {
   }
 
   auto ShouldFinish() -> bool {
-    auto now = ClockMs();
-    return now - start_time_ > duration_ms_;
+    auto now = std::chrono::steady_clock::now();
+    return std::chrono::duration_cast<std::chrono::milliseconds>(now - start_time_).count() > duration_ms_;
   }
 };
 

tools/btree_bench/btree_bench.cpp

@@ -36,14 +36,6 @@
 #include "storage/index/generic_key.h"
 #include "test_util.h"
 
-#include <sys/time.h>
-
-auto ClockMs() -> uint64_t {
-  struct timeval tm;
-  gettimeofday(&tm, nullptr);
-  return static_cast<uint64_t>(tm.tv_sec * 1000) + static_cast<uint64_t>(tm.tv_usec / 1000);
-}
-
 static const size_t BUSTUB_READ_THREAD = 4;
 static const size_t BUSTUB_WRITE_THREAD = 2;
 // We should keep the BPM size large enough to hold all pages in memory, to minimize the dependency on P1.
@@ -55,10 +47,10 @@ static const size_t KEY_MODIFY_RANGE = 2048;
 struct BTreeTotalMetrics {
   uint64_t write_cnt_{0};
   uint64_t read_cnt_{0};
-  uint64_t start_time_{0};
+  std::chrono::steady_clock::time_point start_time_;
   std::mutex mutex_;
 
-  void Begin() { start_time_ = ClockMs(); }
+  void Begin() { start_time_ = std::chrono::steady_clock::now(); }
 
   void ReportWrite(uint64_t scan_cnt) {
     std::unique_lock<std::mutex> l(mutex_);
@@ -71,8 +63,8 @@ struct BTreeTotalMetrics {
   }
 
   void Report() {
-    auto now = ClockMs();
-    auto elapsed = now - start_time_;
+    auto now = std::chrono::steady_clock::now();
+    auto elapsed = std::chrono::duration_cast<std::chrono::milliseconds>(now - start_time_).count();
     auto write_per_sec = write_cnt_ / static_cast<double>(elapsed) * 1000;
     auto read_per_sec = read_cnt_ / static_cast<double>(elapsed) * 1000;
 
@@ -84,7 +76,7 @@ struct BTreeTotalMetrics {
 };
 
 struct BTreeMetrics {
-  uint64_t start_time_{0};
+  std::chrono::steady_clock::time_point start_time_;
   uint64_t last_report_at_{0};
   uint64_t last_cnt_{0};
   uint64_t cnt_{0};
@@ -96,12 +88,12 @@ struct BTreeMetrics {
 
   void Tick() { cnt_ += 1; }
 
-  void Begin() { start_time_ = ClockMs(); }
+  void Begin() { start_time_ = std::chrono::steady_clock::now(); }
 
   void Report() {
-    auto now = ClockMs();
-    auto elapsed = now - start_time_;
-    if (elapsed - last_report_at_ > 1000) {
+    auto now = std::chrono::steady_clock::now();
+    auto elapsed = std::chrono::duration_cast<std::chrono::milliseconds>(now - start_time_).count();
+    if (elapsed - last_report_at_ >= 1000) {
       fmt::print(stderr, "[{:5.2f}] {}: total_cnt={:<10} throughput={:<10.3f} avg_throughput={:<10.3f}\n",
                  elapsed / 1000.0, reporter_, cnt_,
                  (cnt_ - last_cnt_) / static_cast<double>(elapsed - last_report_at_) * 1000,
@@ -112,8 +104,8 @@ struct BTreeMetrics {
   }
 
   auto ShouldFinish() -> bool {
-    auto now = ClockMs();
-    return now - start_time_ > duration_ms_;
+    auto now = std::chrono::steady_clock::now();
+    return std::chrono::duration_cast<std::chrono::milliseconds>(now - start_time_).count() > duration_ms_;
   }
 };
 

tools/htable_bench/htable_bench.cpp

@@ -36,14 +36,6 @@
 #include "storage/index/generic_key.h"
 #include "test_util.h"
 
-#include <sys/time.h>
-
-auto ClockMs() -> uint64_t {
-  struct timeval tm;
-  gettimeofday(&tm, nullptr);
-  return static_cast<uint64_t>(tm.tv_sec * 1000) + static_cast<uint64_t>(tm.tv_usec / 1000);
-}
-
 static const size_t BUSTUB_READ_THREAD = 5;
 static const size_t BUSTUB_WRITE_THREAD = 3;
 static const size_t BUSTUB_BPM_SIZE = 2048;
@@ -55,10 +47,10 @@ static const size_t HTABLE_DIRECTORY_DEPTH = 9;
 struct HTableTotalMetrics {
   uint64_t write_cnt_{0};
   uint64_t read_cnt_{0};
-  uint64_t start_time_{0};
+  std::chrono::steady_clock::time_point start_time_;
   std::mutex mutex_;
 
-  void Begin() { start_time_ = ClockMs(); }
+  void Begin() { start_time_ = std::chrono::steady_clock::now(); }
 
   void ReportWrite(uint64_t scan_cnt) {
     std::unique_lock<std::mutex> l(mutex_);
@@ -71,8 +63,8 @@ struct HTableTotalMetrics {
   }
 
   void Report() {
-    auto now = ClockMs();
-    auto elapsed = now - start_time_;
+    auto now = std::chrono::steady_clock::now();
+    auto elapsed = std::chrono::duration_cast<std::chrono::milliseconds>(now - start_time_).count();
     auto write_per_sec = write_cnt_ / static_cast<double>(elapsed) * 1000;
     auto read_per_sec = read_cnt_ / static_cast<double>(elapsed) * 1000;
 
@@ -84,7 +76,7 @@ struct HTableTotalMetrics {
 };
 
 struct HTableMetrics {
-  uint64_t start_time_{0};
+  std::chrono::steady_clock::time_point start_time_;
   uint64_t last_report_at_{0};
   uint64_t last_cnt_{0};
   uint64_t cnt_{0};
@@ -96,12 +88,12 @@ struct HTableMetrics {
 
   void Tick() { cnt_ += 1; }
 
-  void Begin() { start_time_ = ClockMs(); }
+  void Begin() { start_time_ = std::chrono::steady_clock::now(); }
 
   void Report() {
-    auto now = ClockMs();
-    auto elapsed = now - start_time_;
-    if (elapsed - last_report_at_ > 1000) {
+    auto now = std::chrono::steady_clock::now();
+    auto elapsed = std::chrono::duration_cast<std::chrono::milliseconds>(now - start_time_).count();
+    if (elapsed - last_report_at_ >= 1000) {
       fmt::print(stderr, "[{:5.2f}] {}: total_cnt={:<10} throughput={:<10.3f} avg_throughput={:<10.3f}\n",
                  elapsed / 1000.0, reporter_, cnt_,
                  (cnt_ - last_cnt_) / static_cast<double>(elapsed - last_report_at_) * 1000,
@@ -112,8 +104,8 @@ struct HTableMetrics {
   }
 
   auto ShouldFinish() -> bool {
-    auto now = ClockMs();
-    return now - start_time_ > duration_ms_;
+    auto now = std::chrono::steady_clock::now();
+    return std::chrono::duration_cast<std::chrono::milliseconds>(now - start_time_).count() > duration_ms_;
   }
 };
 

tools/terrier_bench/terrier.cpp

@@ -35,24 +35,16 @@
 #include "fmt/core.h"
 #include "fmt/std.h"
 
-#include <sys/time.h>
-
-auto ClockMs() -> uint64_t {
-  struct timeval tm;
-  gettimeofday(&tm, nullptr);
-  return static_cast<uint64_t>(tm.tv_sec * 1000) + static_cast<uint64_t>(tm.tv_usec / 1000);
-}
-
 struct TerrierTotalMetrics {
   uint64_t aborted_transfer_txn_cnt_{0};
   uint64_t committed_transfer_txn_cnt_{0};
   uint64_t aborted_join_txn_cnt_{0};
   uint64_t committed_join_txn_cnt_{0};
-  uint64_t start_time_{0};
+  std::chrono::steady_clock::time_point start_time_;
   uint64_t elapsed_{0};
   std::mutex mutex_;
 
-  void Begin() { start_time_ = ClockMs(); }
+  void Begin() { start_time_ = std::chrono::steady_clock::now(); }
 
   void ReportTransfer(uint64_t aborted_cnt, uint64_t committed_cnt) {
     std::unique_lock<std::mutex> l(mutex_);
@@ -67,8 +59,8 @@ struct TerrierTotalMetrics {
   }
 
   void End() {
-    auto now = ClockMs();
-    elapsed_ = now - start_time_;
+    auto now = std::chrono::steady_clock::now();
+    elapsed_ = std::chrono::duration_cast<std::chrono::milliseconds>(now - start_time_).count();
   }
 
   void Report(uint64_t db_size) {
@@ -93,7 +85,7 @@ struct TerrierTotalMetrics {
 };
 
 struct TerrierMetrics {
-  uint64_t start_time_{0};
+  std::chrono::steady_clock::time_point start_time_;
   uint64_t last_report_at_{0};
   uint64_t last_committed_txn_cnt_{0};
   uint64_t last_aborted_txn_cnt_{0};
@@ -109,12 +101,12 @@ struct TerrierMetrics {
 
   void TxnCommitted() { committed_txn_cnt_ += 1; }
 
-  void Begin() { start_time_ = ClockMs(); }
+  void Begin() { start_time_ = std::chrono::steady_clock::now(); }
 
   void Report() {
-    auto now = ClockMs();
-    auto elapsed = now - start_time_;
-    if (elapsed - last_report_at_ > 1000) {
+    auto now = std::chrono::steady_clock::now();
+    auto elapsed = std::chrono::duration_cast<std::chrono::milliseconds>(now - start_time_).count();
+    if (elapsed - last_report_at_ >= 1000) {
       fmt::print(stderr,
                  "[{:5.2f}] {}: total_committed_txn={:<8} total_aborted_txn={:<8} throughput={:<8.3f} "
                  "avg_throughput={:<8.3f}\n",
@@ -127,8 +119,8 @@ struct TerrierMetrics {
   }
 
   auto ShouldFinish() -> bool {
-    auto now = ClockMs();
-    return now - start_time_ > duration_ms_;
+    auto now = std::chrono::steady_clock::now();
+    return std::chrono::duration_cast<std::chrono::milliseconds>(now - start_time_).count() > duration_ms_;
   }
 };