Diagnose invalid PauseTiming()/ResumeTiming() calls (#2235)

docs/user_guide.md

@@ -1342,6 +1342,12 @@ BENCHMARK(BM_SetInsert_With_Timer_Control)->Ranges({{1<<10, 8<<10}, {128, 512}})
 ```
 <!-- {% endraw %} -->
 
+Both calls are only valid inside the benchmark loop. Calling them outside it
+stops a timer that was never started, which adds an absolute clock reading to
+the reported time instead of a duration. This is asserted, and the assertion is
+compiled into the benchmark rather than into the library, so it fires whenever
+the benchmark itself is built without `NDEBUG`.
+
 For convenience, a `ScopedPauseTiming` class is provided to manage pausing and
 resuming timers within a scope. This is less error-prone than manually calling
 `PauseTiming` and `ResumeTiming`.

include/benchmark/state.h

@@ -52,9 +52,19 @@ class BENCHMARK_EXPORT BENCHMARK_INTERNAL_CACHELINE_ALIGNED State {
 
   inline bool KeepRunningBatch(IterationCount n);
 
-  void PauseTiming();
+  // Only valid while the benchmark loop is running.
+  void PauseTiming() {
+    assert(started_ && !finished_ && !skipped() &&
+           "PauseTiming() called outside of the benchmark loop");
+    PauseTimingImpl();
+  }
 
-  void ResumeTiming();
+  // Only valid while the benchmark loop is running.
+  void ResumeTiming() {
+    assert(started_ && !finished_ && !skipped() &&
+           "ResumeTiming() called outside of the benchmark loop");
+    ResumeTimingImpl();
+  }
 
   void SkipWithMessage(const std::string& msg);
 
@@ -164,6 +174,12 @@ class BENCHMARK_EXPORT BENCHMARK_INTERNAL_CACHELINE_ALIGNED State {
   inline bool KeepRunningInternal(IterationCount n, bool is_batch);
   void FinishKeepRunning();
 
+  // The checked entry points above forward here; keeping the bodies out of
+  // line keeps the assertions with the caller, whose NDEBUG decides whether
+  // they are compiled in.
+  void PauseTimingImpl();
+  void ResumeTimingImpl();
+
   const std::string name_;
   const int thread_index_;
   const int threads_;

src/benchmark.cc

@@ -260,9 +260,8 @@ State::State(std::string name, IterationCount max_iters,
 #endif
 }
 
-void State::PauseTiming() {
+void State::PauseTimingImpl() {
   // Add in time accumulated so far
-  BM_CHECK(started_ && !finished_ && !skipped());
   timer_->StopTimer();
   if (perf_counters_measurement_ != nullptr) {
     std::vector<std::pair<std::string, double>> measurements;
@@ -279,8 +278,7 @@ void State::PauseTiming() {
   }
 }
 
-void State::ResumeTiming() {
-  BM_CHECK(started_ && !finished_ && !skipped());
+void State::ResumeTimingImpl() {
   timer_->StartTimer();
   if (perf_counters_measurement_ != nullptr) {
     perf_counters_measurement_->Start();

test/CMakeLists.txt

@@ -137,8 +137,6 @@ benchmark_add_test(NAME basic_benchmark COMMAND basic_test --benchmark_min_time=
 compile_output_test(repetitions_test)
 benchmark_add_test(NAME repetitions_benchmark COMMAND repetitions_test --benchmark_min_time=0.01s --benchmark_repetitions=3)
 
-compile_benchmark_test(diagnostics_test)
-benchmark_add_test(NAME diagnostics_test COMMAND diagnostics_test --benchmark_min_time=0.01s)
 
 compile_benchmark_test(skip_with_error_test)
 benchmark_add_test(NAME skip_with_error_test COMMAND skip_with_error_test --benchmark_min_time=0.01s)
@@ -263,6 +261,7 @@ if (BENCHMARK_ENABLE_GTEST_TESTS)
   add_gtest(benchmark_setup_teardown_cb_types_gtest)
   add_gtest(memory_results_gtest)
   add_gtest(memory_manager_ordering_gtest)
+  add_gtest(diagnostics_gtest)
 endif(BENCHMARK_ENABLE_GTEST_TESTS)
 
 ###############################################################################

test/diagnostics_gtest.cc

@@ -0,0 +1,98 @@
+// Testing:
+//   State::PauseTiming()
+//   State::ResumeTiming()
+// Test that the assertions in these functions diagnose calls made outside of
+// the benchmark loop, and that a run they do not diagnose still reports a
+// sane time.
+
+#include <string>
+#include <vector>
+
+#include "benchmark/benchmark.h"
+#include "gtest/gtest.h"
+
+namespace {
+
+void BM_pause_before_loop(benchmark::State& state) {
+  state.PauseTiming();
+  for (auto _ : state) {
+  }
+}
+BENCHMARK(BM_pause_before_loop)->Iterations(1);
+
+void BM_resume_before_loop(benchmark::State& state) {
+  state.ResumeTiming();
+  for (auto _ : state) {
+  }
+}
+BENCHMARK(BM_resume_before_loop)->Iterations(1);
+
+void BM_pause_after_loop(benchmark::State& state) {
+  for (auto _ : state) {
+  }
+  state.PauseTiming();
+}
+BENCHMARK(BM_pause_after_loop)->Iterations(1);
+
+void BM_resume_after_loop(benchmark::State& state) {
+  for (auto _ : state) {
+  }
+  state.ResumeTiming();
+}
+BENCHMARK(BM_resume_after_loop)->Iterations(1);
+
+void BM_pause_and_resume_in_loop(benchmark::State& state) {
+  for (auto _ : state) {
+    state.PauseTiming();
+    state.ResumeTiming();
+  }
+}
+BENCHMARK(BM_pause_and_resume_in_loop)->Iterations(1);
+
+class CapturingReporter : public benchmark::BenchmarkReporter {
+ public:
+  bool ReportContext(const Context& /*context*/) override { return true; }
+  void ReportRuns(const std::vector<Run>& runs) override {
+    runs_.insert(runs_.end(), runs.begin(), runs.end());
+  }
+
+  const std::vector<Run>& runs() const { return runs_; }
+
+ private:
+  std::vector<Run> runs_;
+};
+
+std::vector<benchmark::BenchmarkReporter::Run> RunOne(const std::string& name) {
+  CapturingReporter reporter;
+  benchmark::RunSpecifiedBenchmarks(&reporter, name);
+  return reporter.runs();
+}
+
+TEST(Diagnostics, PauseOutsideOfTheLoopIsDiagnosed) {
+#ifndef NDEBUG
+  ASSERT_DEATH_IF_SUPPORTED(RunOne("BM_pause_before_loop"), "PauseTiming");
+  ASSERT_DEATH_IF_SUPPORTED(RunOne("BM_pause_after_loop"), "PauseTiming");
+#endif
+}
+
+TEST(Diagnostics, ResumeOutsideOfTheLoopIsDiagnosed) {
+#ifndef NDEBUG
+  ASSERT_DEATH_IF_SUPPORTED(RunOne("BM_resume_before_loop"), "ResumeTiming");
+  ASSERT_DEATH_IF_SUPPORTED(RunOne("BM_resume_after_loop"), "ResumeTiming");
+#endif
+}
+
+TEST(Diagnostics, PauseAndResumeInsideTheLoopReportASaneTime) {
+  const std::vector<benchmark::BenchmarkReporter::Run> runs =
+      RunOne("BM_pause_and_resume_in_loop");
+  ASSERT_EQ(runs.size(), 1u);
+  EXPECT_EQ(runs[0].skipped, 0u);
+  // One iteration of an empty loop. A whole second would mean an absolute
+  // clock reading was accumulated instead of a duration.
+  EXPECT_GE(runs[0].real_accumulated_time, 0.0);
+  EXPECT_LT(runs[0].real_accumulated_time, 1.0);
+  EXPECT_GE(runs[0].cpu_accumulated_time, 0.0);
+  EXPECT_LT(runs[0].cpu_accumulated_time, 1.0);
+}
+
+}  // namespace