From bf68d1c93d0a15ea6bdf3e630215b113d90cba66 Mon Sep 17 00:00:00 2001 From: Mark Callaghan Date: Wed, 4 May 2022 10:15:49 -0700 Subject: [PATCH] Print elapsed time and number of operations completed (#9886) Summary: This is inspired by debugging a regression test that runs for ~0.05 seconds and the short running time makes it prone to variance. While db_bench ran for ~60 seconds, 59.95 seconds was spent opening 128 databases (and doing recovery). So it was harder to notice that the benchmark only ran for 0.05 seconds. Normally I add output to the end of the line to make life easier for existing tools that parse it but in this case the output near the end of the line has two optional parts and one of the optional parts adds an extra newline. This is for https://github.com/facebook/rocksdb/issues/9856 Pull Request resolved: https://github.com/facebook/rocksdb/pull/9886 Test Plan: ./db_bench --benchmarks=overwrite,readrandom --num=1000000 --threads=4 old output: DB path: [/tmp/rocksdbtest-2260/dbbench] overwrite : 14.108 micros/op 283338 ops/sec; 31.3 MB/s DB path: [/tmp/rocksdbtest-2260/dbbench] readrandom : 7.994 micros/op 496788 ops/sec; 55.0 MB/s (1000000 of 1000000 found) new output: DB path: [/tmp/rocksdbtest-2260/dbbench] overwrite : 14.117 micros/op 282862 ops/sec 14.141 seconds 4000000 operations; 31.3 MB/s DB path: [/tmp/rocksdbtest-2260/dbbench] readrandom : 8.649 micros/op 458475 ops/sec 8.725 seconds 4000000 operations; 49.8 MB/s (981548 of 1000000 found) Reviewed By: ajkr Differential Revision: D36102269 Pulled By: mdcallag fbshipit-source-id: 5cd8a9e11f5cbe2a46809571afd83335b6b0caa0 --- tools/db_bench_tool.cc | 14 ++++++-------- 1 file changed, 6 insertions(+), 8 deletions(-) diff --git a/tools/db_bench_tool.cc b/tools/db_bench_tool.cc index 367bacfb28..b63b0a9a47 100644 --- a/tools/db_bench_tool.cc +++ b/tools/db_bench_tool.cc @@ -2265,25 +2265,23 @@ class Stats { if (done_ < 1) done_ = 1; std::string extra; + double elapsed = (finish_ - start_) * 1e-6; if (bytes_ > 0) { // Rate is computed on actual elapsed time, not the sum of per-thread // elapsed times. - double elapsed = (finish_ - start_) * 1e-6; char rate[100]; snprintf(rate, sizeof(rate), "%6.1f MB/s", (bytes_ / 1048576.0) / elapsed); extra = rate; } AppendWithSpace(&extra, message_); - double elapsed = (finish_ - start_) * 1e-6; double throughput = (double)done_/elapsed; - fprintf(stdout, "%-12s : %11.3f micros/op %ld ops/sec;%s%s\n", - name.ToString().c_str(), - seconds_ * 1e6 / done_, - (long)throughput, - (extra.empty() ? "" : " "), - extra.c_str()); + fprintf(stdout, + "%-12s : %11.3f micros/op %ld ops/sec %.3f seconds %" PRIu64 + " operations;%s%s\n", + name.ToString().c_str(), seconds_ * 1e6 / done_, (long)throughput, + elapsed, done_, (extra.empty() ? "" : " "), extra.c_str()); if (FLAGS_histogram) { for (auto it = hist_.begin(); it != hist_.end(); ++it) { fprintf(stdout, "Microseconds per %s:\n%s\n",