Merge pull request #104 from google/fix-negative-times

Fix #96: Prevent times from being negative.

CMakeLists.txt

@@ -54,6 +54,7 @@ endif()
 cxx_feature_check(STD_REGEX)
 cxx_feature_check(GNU_POSIX_REGEX)
 cxx_feature_check(POSIX_REGEX)
+cxx_feature_check(STEADY_CLOCK)
 
 # Set up directories
 include_directories(${PROJECT_SOURCE_DIR}/include)

cmake/steady_clock.cpp

@@ -0,0 +1,7 @@
+#include <chrono>
+
+int main() {
+    typedef std::chrono::steady_clock Clock;
+    Clock::time_point tp = Clock::now();
+    ((void)tp);
+}

src/benchmark.cc

@@ -69,17 +69,6 @@ DEFINE_bool(color_print, true, "Enables colorized logging.");
 DEFINE_int32(v, 0, "The level of verbose logging to output");
 
 
-// The ""'s catch people who don't pass in a literal for "str"
-#define strliterallen(str) (sizeof("" str "") - 1)
-
-// Must use a string literal for prefix.
-#define memprefix(str, len, prefix)                       \
-  ((((len) >= strliterallen(prefix)) &&                   \
-    std::memcmp(str, prefix, strliterallen(prefix)) == 0) \
-       ? str + strliterallen(prefix)                      \
-       : nullptr)
-
-
 namespace benchmark {
 
 namespace internal {
@@ -120,23 +109,6 @@ bool use_real_time GUARDED_BY(GetBenchmarkLock());
 // TODO(ericwf): support MallocCounter.
 //static benchmark::MallocCounter *benchmark_mc;
 
-static bool CpuScalingEnabled() {
-  // On Linux, the CPUfreq subsystem exposes CPU information as files on the
-  // local file system. If reading the exported files fails, then we may not be
-  // running on Linux, so we silently ignore all the read errors.
-  for (int cpu = 0, num_cpus = NumCPUs(); cpu < num_cpus; ++cpu) {
-    std::string governor_file = StrCat("/sys/devices/system/cpu/cpu", cpu,
-                                       "/cpufreq/scaling_governor");
-    FILE* file = fopen(governor_file.c_str(), "r");
-    if (!file) break;
-    char buff[16];
-    size_t bytes_read = fread(buff, 1, sizeof(buff), file);
-    fclose(file);
-    if (memprefix(buff, bytes_read, "performance") == nullptr) return true;
-  }
-  return false;
-}
-
 struct ThreadStats {
     ThreadStats() : bytes_processed(0), items_processed(0) {}
     int64_t bytes_processed;

src/json_reporter.cc

@@ -65,11 +65,8 @@ bool JSONReporter::ReportContext(const Context& context) {
   // Open context block and print context information.
   out << inner_indent << "\"context\": {\n";
   std::string indent(4, ' ');
-  int remainder_us;
-  std::string walltime_value = walltime::Print(
-                                    walltime::Now(), "%Y/%m/%d-%H:%M:%S",
-                                    true,  // use local timezone
-                                    &remainder_us);
+
+  std::string walltime_value = LocalDateTimeString();
   out << indent << FormatKV("date", walltime_value) << ",\n";
 
   out << indent

src/reporter.cc

@@ -98,16 +98,13 @@ bool ConsoleReporter::ReportContext(const Context& context) {
           context.mhz_per_cpu,
           (context.num_cpus > 1) ? "s" : "");
 
-  int remainder_us;
-  std::string walltime_str = walltime::Print(
-                                walltime::Now(), "%Y/%m/%d-%H:%M:%S",
-                                true,  // use local timezone
-                                &remainder_us);
+  std::string walltime_str = LocalDateTimeString();
   fprintf(stdout, "%s\n", walltime_str.c_str());
 
   if (context.cpu_scaling_enabled) {
     fprintf(stdout, "***WARNING*** CPU scaling is enabled, the benchmark "
-                    "timings may be noisy\n");
+                    "real time measurements may be noisy and will incure extra "
+                    "overhead.\n");
   }
 
 #ifndef NDEBUG

src/sysinfo.cc

@@ -36,6 +36,7 @@
 #include "internal_macros.h"
 #include "log.h"
 #include "sleep.h"
+#include "string_util.h"
 
 namespace benchmark {
 namespace {
@@ -352,4 +353,32 @@ int NumCPUs(void) {
   std::call_once(cpuinfo_init, InitializeSystemInfo);
   return cpuinfo_num_cpus;
 }
+
+// The ""'s catch people who don't pass in a literal for "str"
+#define strliterallen(str) (sizeof("" str "") - 1)
+
+// Must use a string literal for prefix.
+#define memprefix(str, len, prefix)                       \
+  ((((len) >= strliterallen(prefix)) &&                   \
+    std::memcmp(str, prefix, strliterallen(prefix)) == 0) \
+       ? str + strliterallen(prefix)                      \
+       : nullptr)
+
+bool CpuScalingEnabled() {
+  // On Linux, the CPUfreq subsystem exposes CPU information as files on the
+  // local file system. If reading the exported files fails, then we may not be
+  // running on Linux, so we silently ignore all the read errors.
+  for (int cpu = 0, num_cpus = NumCPUs(); cpu < num_cpus; ++cpu) {
+    std::string governor_file = StrCat("/sys/devices/system/cpu/cpu", cpu,
+                                       "/cpufreq/scaling_governor");
+    FILE* file = fopen(governor_file.c_str(), "r");
+    if (!file) break;
+    char buff[16];
+    size_t bytes_read = fread(buff, 1, sizeof(buff), file);
+    fclose(file);
+    if (memprefix(buff, bytes_read, "performance") == nullptr) return true;
+  }
+  return false;
+}
+
 }  // end namespace benchmark

src/sysinfo.h

@@ -6,6 +6,7 @@ double MyCPUUsage();
 double ChildrenCPUUsage();
 int NumCPUs();
 double CyclesPerSecond();
+bool CpuScalingEnabled();
 }  // end namespace benchmark
 
 #endif  // BENCHMARK_SYSINFO_H_

src/walltime.cc

@@ -22,38 +22,41 @@
 #include <ctime>
 
 #include <atomic>
+#include <chrono>
 #include <limits>
 #include <type_traits>
 
+#include "arraysize.h"
 #include "check.h"
 #include "cycleclock.h"
+#include "log.h"
 #include "sysinfo.h"
 
 namespace benchmark {
 namespace walltime {
-namespace {
-
-bool SplitTimezone(WallTime value, bool local, struct tm* t,
-                   double* subsecond) {
-  memset(t, 0, sizeof(*t));
-  if ((value < 0) || (value > std::numeric_limits<time_t>::max())) {
-    *subsecond = 0.0;
-    return false;
-  }
-  const time_t whole_time = static_cast<time_t>(value);
-  *subsecond = value - whole_time;
-  if (local)
-    localtime_r(&whole_time, t);
-  else
-    gmtime_r(&whole_time, t);
-  return true;
-}
-
-} // end anonymous namespace
-
 
 namespace {
 
+#if defined(HAVE_STEADY_CLOCK)
+template <bool HighResIsSteady = std::chrono::high_resolution_clock::is_steady>
+struct ChooseSteadyClock {
+    typedef std::chrono::high_resolution_clock type;
+};
+
+template <>
+struct ChooseSteadyClock<false> {
+    typedef std::chrono::steady_clock type;
+};
+#endif
+
+struct ChooseClockType {
+#if defined(HAVE_STEADY_CLOCK)
+  typedef typename ChooseSteadyClock<>::type type;
+#else
+  typedef std::chrono::high_resolution_clock type;
+#endif
+};
+
 class WallTimeImp
 {
 public:
@@ -160,32 +163,74 @@ WallTimeImp::WallTimeImp()
   last_adjust_time_ = static_cast<uint32_t>(uint64_t(base_cycletime_) >> 32);
 }
 
-} // end anonymous namespace
-
-
-WallTime Now()
-{
-    static WallTimeImp& imp = WallTimeImp::GetWallTimeImp();
-    return imp.Now();
+WallTime CPUWalltimeNow() {
+  static WallTimeImp& imp = WallTimeImp::GetWallTimeImp();
+  return imp.Now();
 }
 
-std::string Print(WallTime time, const char* format, bool local,
-                  int* remainder_us) {
-  char storage[32];
-  struct tm split;
-  double subsecond;
-  if (!SplitTimezone(time, local, &split, &subsecond)) {
-    snprintf(storage, sizeof(storage), "Invalid time: %f", time);
-  } else {
-    if (remainder_us != nullptr) {
-      *remainder_us = static_cast<int>((subsecond * 1000000) + 0.5);
-      if (*remainder_us > 999999) *remainder_us = 999999;
-      if (*remainder_us < 0) *remainder_us = 0;
+WallTime ChronoWalltimeNow() {
+  typedef ChooseClockType::type Clock;
+  typedef std::chrono::duration<WallTime, std::chrono::seconds::period>
+          FPSeconds;
+  static_assert(std::chrono::treat_as_floating_point<WallTime>::value,
+                "This type must be treated as a floating point type.");
+  auto now = Clock::now().time_since_epoch();
+  return std::chrono::duration_cast<FPSeconds>(now).count();
+}
+
+bool UseCpuCycleClock() {
+    bool useWallTime = !CpuScalingEnabled();
+    if (useWallTime) {
+        VLOG(1) << "Using the CPU cycle clock to provide walltime::Now().\n";
+    } else {
+        VLOG(1) << "Using std::chrono to provide walltime::Now().\n";
     }
-    strftime(storage, sizeof(storage), format, &split);
+    return useWallTime;
+}
+
+
+} // end anonymous namespace
+
+// WallTimeImp doesn't work when CPU Scaling is enabled. If CPU Scaling is
+// enabled at the start of the program then std::chrono::system_clock is used
+// instead.
+WallTime Now()
+{
+  static bool useCPUClock = UseCpuCycleClock();
+  if (useCPUClock) {
+    return CPUWalltimeNow();
+  } else {
+    return ChronoWalltimeNow();
   }
-  return std::string(storage);
 }
 
 }  // end namespace walltime
+
+
+namespace {
+
+std::string DateTimeString(bool local) {
+  typedef std::chrono::system_clock Clock;
+  std::time_t now = Clock::to_time_t(Clock::now());
+  char storage[128];
+
+  std::tm timeinfo;
+  std::memset(&timeinfo, 0, sizeof(std::tm));
+  if (local) {
+    ::localtime_r(&now, &timeinfo);
+  } else {
+    ::gmtime_r(&now, &timeinfo);
+  }
+  std::size_t written = std::strftime(storage, sizeof(storage), "%F %T", &timeinfo);
+  CHECK(written < arraysize(storage));
+  ((void)written); // prevent unused variable in optimized mode.
+  return std::string(storage);
+}
+
+} // end namespace
+
+std::string LocalDateTimeString() {
+  return DateTimeString(true);
+}
+
 }  // end namespace benchmark

src/walltime.h

@@ -8,15 +8,10 @@ typedef double WallTime;
 
 namespace walltime {
 WallTime Now();
-
-// GIVEN: walltime, generic format string (as understood by strftime),
-// a boolean flag specifying if the time is local or UTC (true=local).
-// RETURNS: the formatted string. ALSO RETURNS: the remaining number of
-// microseconds (never printed in the string since strftime does not understand
-// it)
-std::string Print(WallTime time, const char *format, bool local,
-                  int *remainder_us);
 }  // end namespace walltime
+
+std::string LocalDateTimeString();
+
 }  // end namespace benchmark
 
 #endif  // BENCHMARK_WALLTIME_H_

test/basic_test.cc

@@ -59,6 +59,24 @@ void BM_spin_pause_during(benchmark::State& state) {
 BASIC_BENCHMARK_TEST(BM_spin_pause_during);
 BASIC_BENCHMARK_TEST(BM_spin_pause_during)->ThreadPerCpu();
 
+void BM_pause_during(benchmark::State& state) {
+  while(state.KeepRunning()) {
+    state.PauseTiming();
+    state.ResumeTiming();
+  }
+}
+BENCHMARK(BM_pause_during);
+BENCHMARK(BM_pause_during)->ThreadPerCpu();
+
+void BM_pause_during_realtime(benchmark::State& state) {
+  state.UseRealTime();
+  while(state.KeepRunning()) {
+    state.PauseTiming();
+    state.ResumeTiming();
+  }
+}
+BENCHMARK(BM_pause_during_realtime);
+BENCHMARK(BM_pause_during_realtime)->ThreadPerCpu();
 
 void BM_spin_pause_after(benchmark::State& state) {
   while(state.KeepRunning()) {