Print at least three significant digits for times. (#701)
Some benchmarks are particularly sensitive and they run in less than
a nanosecond. In order for the console reporter to provide meaningful
output for such benchmarks it needs to be able to display the times
using more resolution than a single nanosecond.
This patch changes the console reporter to print at least three
significant digits for all results.
Unlike the initial attempt, this patch does not align the decimal point.
diff --git a/src/console_reporter.cc b/src/console_reporter.cc
index 7de7138..ca36472 100644
--- a/src/console_reporter.cc
+++ b/src/console_reporter.cc
@@ -53,7 +53,7 @@
}
void ConsoleReporter::PrintHeader(const Run& run) {
- std::string str = FormatString("%-*s %13s %13s %10s", static_cast<int>(name_field_width_),
+ std::string str = FormatString("%-*s %13s %15s %12s", static_cast<int>(name_field_width_),
"Benchmark", "Time", "CPU", "Iterations");
if(!run.counters.empty()) {
if(output_options_ & OO_Tabular) {
@@ -98,6 +98,21 @@
va_end(args);
}
+
+static std::string FormatTime(double time) {
+ // Align decimal places...
+ if (time < 1.0) {
+ return FormatString("%10.3f", time);
+ }
+ if (time < 10.0) {
+ return FormatString("%10.2f", time);
+ }
+ if (time < 100.0) {
+ return FormatString("%10.1f", time);
+ }
+ return FormatString("%10.0f", time);
+}
+
void ConsoleReporter::PrintRunData(const Run& result) {
typedef void(PrinterFn)(std::ostream&, LogColor, const char*, ...);
auto& Out = GetOutputStream();
@@ -117,18 +132,21 @@
const double real_time = result.GetAdjustedRealTime();
const double cpu_time = result.GetAdjustedCPUTime();
+ const std::string real_time_str = FormatTime(real_time);
+ const std::string cpu_time_str = FormatTime(cpu_time);
+
if (result.report_big_o) {
std::string big_o = GetBigOString(result.complexity);
- printer(Out, COLOR_YELLOW, "%10.2f %s %10.2f %s ", real_time, big_o.c_str(),
+ printer(Out, COLOR_YELLOW, "%10.2f %-4s %10.2f %-4s ", real_time, big_o.c_str(),
cpu_time, big_o.c_str());
} else if (result.report_rms) {
- printer(Out, COLOR_YELLOW, "%10.0f %% %10.0f %% ", real_time * 100,
- cpu_time * 100);
+ printer(Out, COLOR_YELLOW, "%10.0f %-4s %10.0f %-4s ", real_time * 100, "%",
+ cpu_time * 100, "%");
} else {
const char* timeLabel = GetTimeUnitString(result.time_unit);
- printer(Out, COLOR_YELLOW, "%10.0f %s %10.0f %s ", real_time, timeLabel,
- cpu_time, timeLabel);
+ printer(Out, COLOR_YELLOW, "%s %-4s %s %-4s ", real_time_str.c_str(), timeLabel,
+ cpu_time_str.c_str(), timeLabel);
}
if (!result.report_big_o && !result.report_rms) {
diff --git a/test/output_test_helper.cc b/test/output_test_helper.cc
index 59c9dfb..5dc951d 100644
--- a/test/output_test_helper.cc
+++ b/test/output_test_helper.cc
@@ -39,17 +39,18 @@
// Don't use 'dec_re' from header because it may not yet be initialized.
// clang-format off
static std::string safe_dec_re = "[0-9]*[.]?[0-9]+([eE][-+][0-9]+)?";
+ static std::string time_re = "([0-9]+[.])?[0-9]+";
static SubMap map = {
{"%float", "[0-9]*[.]?[0-9]+([eE][-+][0-9]+)?"},
// human-readable float
{"%hrfloat", "[0-9]*[.]?[0-9]+([eE][-+][0-9]+)?[kMGTPEZYmunpfazy]?"},
{"%int", "[ ]*[0-9]+"},
{" %s ", "[ ]+"},
- {"%time", "[ ]*[0-9]+ ns"},
- {"%console_report", "[ ]*[0-9]+ ns [ ]*[0-9]+ ns [ ]*[0-9]+"},
- {"%console_time_only_report", "[ ]*[0-9]+ ns [ ]*[0-9]+ ns"},
- {"%console_us_report", "[ ]*[0-9]+ us [ ]*[0-9]+ us [ ]*[0-9]+"},
- {"%console_us_time_only_report", "[ ]*[0-9]+ us [ ]*[0-9]+ us"},
+ {"%time", "[ ]*" + time_re + "[ ]+ns"},
+ {"%console_report", "[ ]*" + time_re + "[ ]+ns [ ]*" + time_re + "[ ]+ns [ ]*[0-9]+"},
+ {"%console_time_only_report", "[ ]*" + time_re + "[ ]+ns [ ]*" + time_re + "[ ]+ns"},
+ {"%console_us_report", "[ ]*" + time_re + "[ ]+us [ ]*" + time_re + "[ ]+us [ ]*[0-9]+"},
+ {"%console_us_time_only_report", "[ ]*" + time_re + "[ ]+us [ ]*" + time_re + "[ ]+us"},
{"%csv_header",
"name,iterations,real_time,cpu_time,time_unit,bytes_per_second,"
"items_per_second,label,error_occurred,error_message"},
diff --git a/test/reporter_output_test.cc b/test/reporter_output_test.cc
index 8263831..ec6d51b 100644
--- a/test/reporter_output_test.cc
+++ b/test/reporter_output_test.cc
@@ -534,7 +534,7 @@
{"^BM_UserStats/iterations:5/repeats:3/"
"manual_time_median [ ]* 150 ns %time [ ]*3$"},
{"^BM_UserStats/iterations:5/repeats:3/"
- "manual_time_stddev [ ]* 0 ns %time [ ]*3$"},
+ "manual_time_stddev [ ]* 0.000 ns %time [ ]*3$"},
{"^BM_UserStats/iterations:5/repeats:3/manual_time_ "
"[ ]* 150 ns %time [ ]*3$"}});
ADD_CASES(
