From 4528c76b718acc9b57956f63069c699ae21edcab Mon Sep 17 00:00:00 2001
From: Eric <eric@efcs.ca>
Date: Thu, 13 Dec 2018 22:49:21 -0500
Subject: [PATCH] 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.
---
 src/console_reporter.cc      | 30 ++++++++++++++++++++++++------
 test/output_test_helper.cc   | 11 ++++++-----
 test/reporter_output_test.cc |  2 +-
 3 files changed, 31 insertions(+), 12 deletions(-)

diff --git a/src/console_reporter.cc b/src/console_reporter.cc
index 7de71386..ca364727 100644
--- a/src/console_reporter.cc
+++ b/src/console_reporter.cc
@@ -53,7 +53,7 @@ bool ConsoleReporter::ReportContext(const Context& context) {
 }
 
 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 @@ static void IgnoreColorPrint(std::ostream& out, LogColor, const char* fmt,
   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 @@ void ConsoleReporter::PrintRunData(const Run& result) {
 
   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 59c9dfb5..5dc951d2 100644
--- a/test/output_test_helper.cc
+++ b/test/output_test_helper.cc
@@ -39,17 +39,18 @@ SubMap& GetSubstitutions() {
   // 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 8263831b..ec6d51b3 100644
--- a/test/reporter_output_test.cc
+++ b/test/reporter_output_test.cc
@@ -534,7 +534,7 @@ ADD_CASES(TC_ConsoleOut, {{"^BM_UserStats/iterations:5/repeats:3/manual_time [ "
                           {"^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(