Benchmarks loads can lose 20% to 30% of throughput from this fprintf

[mdcallag]

This fprintf was inherited from LevelDB. For some stress tests that reduces throughput by 20% to 30%.

It is only an issue when db_bench is run with --histogram=1 --stats_interval=0 --stats_interval_seconds=0

The first issue is the use of \r. That is fine for interactive usage of db_bench (when you are watching the output) but not for batch usage when piping the output to a file. I am not asking for all usage of that to be removed, but I want all usage of it to be preventable, and one way to achieve that is for it to only be used when --stats_interval is non-zero.

I think this fprint is usage with two changes:

1. Remove the \r so the output is useful for the batch case, or have an if/else branch that uses \r when stats_interval is non-zero else don't use \r.
2. Make the limit configurable, it is hardwired to 20000 usecs right now which is too low for stress tests, or for most disk-based tests.
3. I am not sure that the fflush(stderr) call is needed. It is more overhead, and the out fprintf's for stats don't use it
4. Switch from stderr to stdout to match what is done for other stats/monitoring info

This is an example patch that solves point 2 without the if/else mentioned in point 1. It also doesn't resolve points 3 and 4. Forgive the use of c-style casts.

--- a/tools/db_bench_tool.cc
+++ b/tools/db_bench_tool.cc
@@ -1186,6 +1186,8 @@ DEFINE_int64(stats_interval_seconds, 0, "Report stats every N seconds. This "
 DEFINE_int32(stats_per_interval, 0, "Reports additional stats per interval when"
              " this is greater than 0.");

+DEFINE_int32(slow_usecs, 1000000, "Report slow ops that take this long");
+
 DEFINE_int64(report_interval_seconds, 0,
              "If greater than zero, it will write simple stats in CSV format "
              "to --report_file every N seconds");
@@ -2277,8 +2279,8 @@ class Stats {
       }
       hist_[op_type]->Add(micros);

-      if (micros > 20000 && !FLAGS_stats_interval) {
-        fprintf(stderr, "long op: %" PRIu64 " micros%30s\r", micros, "");
+      if (micros >= (uint64_t) FLAGS_slow_usecs && !FLAGS_stats_interval) {
+        fprintf(stderr, "long op %d : %" PRIu64 " usecs\n", (int) op_type, micros);
         fflush(stderr);
       }
       last_op_finish_ = now;

[mdcallag]

Fixed by #9732