Add state machine, boost::posix_time based cpu timer & tests for Timer

2 files changed, 218 insertions, 23 deletions

diff --git a/src/caffe/test/test_benchmark.cpp b/src/caffe/test/test_benchmark.cpp
new file mode 100644
index 00000000..9866f7d0
--- /dev/null
+++ b/src/caffe/test/test_benchmark.cpp
@@ -0,0 +1,169 @@
+// Copyright 2014 kloud@github
+
+#include <unistd.h> // for usleep
+#include <cuda_runtime.h>
+#include <gtest/gtest.h>
+
+#include "caffe/common.hpp"
+#include "caffe/util/benchmark.hpp"
+#include "caffe/test/test_caffe_main.hpp"
+
+namespace caffe {
+
+extern cudaDeviceProp CAFFE_TEST_CUDA_PROP;
+
+class BenchmarkTest : public ::testing::Test {};
+
+TEST_F(BenchmarkTest, TestTimerConstructorCPU) {
+  Caffe::set_mode(Caffe::CPU);
+  Timer timer;
+  EXPECT_TRUE(timer.initted());
+  EXPECT_FALSE(timer.running());
+  EXPECT_FALSE(timer.has_run_at_least_once());
+}
+
+TEST_F(BenchmarkTest, TestTimerConstructorGPU) {
+  Caffe::set_mode(Caffe::GPU);
+  Timer timer;
+  EXPECT_TRUE(timer.initted());
+  EXPECT_FALSE(timer.running());
+  EXPECT_FALSE(timer.has_run_at_least_once());
+}
+
+TEST_F(BenchmarkTest, TestTimerStartCPU) {
+  Caffe::set_mode(Caffe::CPU);
+  Timer timer;
+  timer.Start();
+  EXPECT_TRUE(timer.initted());
+  EXPECT_TRUE(timer.running());
+  EXPECT_TRUE(timer.has_run_at_least_once());
+  timer.Start();
+  EXPECT_TRUE(timer.initted());
+  EXPECT_TRUE(timer.running());
+  EXPECT_TRUE(timer.has_run_at_least_once());
+  timer.Stop();
+  timer.Start();
+  EXPECT_TRUE(timer.initted());
+  EXPECT_TRUE(timer.running());
+  EXPECT_TRUE(timer.has_run_at_least_once());
+}
+
+TEST_F(BenchmarkTest, TestTimerStartGPU) {
+  Caffe::set_mode(Caffe::GPU);
+  Timer timer;
+  timer.Start();
+  EXPECT_TRUE(timer.initted());
+  EXPECT_TRUE(timer.running());
+  EXPECT_TRUE(timer.has_run_at_least_once());
+  timer.Stop();
+  timer.Start();
+  EXPECT_TRUE(timer.initted());
+  EXPECT_TRUE(timer.running());
+  EXPECT_TRUE(timer.has_run_at_least_once());
+  timer.Start();
+  EXPECT_TRUE(timer.initted());
+  EXPECT_TRUE(timer.running());
+  EXPECT_TRUE(timer.has_run_at_least_once());
+}
+
+TEST_F(BenchmarkTest, TestTimerStopCPU) {
+  Caffe::set_mode(Caffe::CPU);
+  Timer timer;
+  timer.Stop();
+  EXPECT_TRUE(timer.initted());
+  EXPECT_FALSE(timer.running());
+  EXPECT_FALSE(timer.has_run_at_least_once());
+  timer.Start();
+  timer.Stop();
+  EXPECT_TRUE(timer.initted());
+  EXPECT_FALSE(timer.running());
+  EXPECT_TRUE(timer.has_run_at_least_once());
+  timer.Stop();
+  EXPECT_TRUE(timer.initted());
+  EXPECT_FALSE(timer.running());
+  EXPECT_TRUE(timer.has_run_at_least_once());
+}
+
+TEST_F(BenchmarkTest, TestTimerStopGPU) {
+  Caffe::set_mode(Caffe::GPU);
+  Timer timer;
+  timer.Stop();
+  EXPECT_TRUE(timer.initted());
+  EXPECT_FALSE(timer.running());
+  EXPECT_FALSE(timer.has_run_at_least_once());
+  timer.Start();
+  timer.Stop();
+  EXPECT_TRUE(timer.initted());
+  EXPECT_FALSE(timer.running());
+  EXPECT_TRUE(timer.has_run_at_least_once());
+  timer.Stop();
+  EXPECT_TRUE(timer.initted());
+  EXPECT_FALSE(timer.running());
+  EXPECT_TRUE(timer.has_run_at_least_once());
+}
+
+TEST_F(BenchmarkTest, TestTimerMilliSecondsCPU) {
+  Caffe::set_mode(Caffe::CPU);
+  Timer timer;
+  CHECK_EQ(timer.MilliSeconds(), 0);
+  EXPECT_TRUE(timer.initted());
+  EXPECT_FALSE(timer.running());
+  EXPECT_FALSE(timer.has_run_at_least_once());
+  timer.Start();
+  usleep(300 * 1000);
+  CHECK_GE(timer.MilliSeconds(), 299);
+  CHECK_LE(timer.MilliSeconds(), 301);
+  EXPECT_TRUE(timer.initted());
+  EXPECT_FALSE(timer.running());
+  EXPECT_TRUE(timer.has_run_at_least_once());
+}
+
+TEST_F(BenchmarkTest, TestTimerMilliSecondsGPU) {
+  Caffe::set_mode(Caffe::GPU);
+  Timer timer;
+  CHECK_EQ(timer.MilliSeconds(), 0);
+  EXPECT_TRUE(timer.initted());
+  EXPECT_FALSE(timer.running());
+  EXPECT_FALSE(timer.has_run_at_least_once());
+  timer.Start();
+  usleep(300 * 1000);
+  CHECK_GE(timer.MilliSeconds(), 299);
+  CHECK_LE(timer.MilliSeconds(), 301);
+  EXPECT_TRUE(timer.initted());
+  EXPECT_FALSE(timer.running());
+  EXPECT_TRUE(timer.has_run_at_least_once());
+}
+
+TEST_F(BenchmarkTest, TestTimerSecondsCPU) {
+  Caffe::set_mode(Caffe::CPU);
+  Timer timer;
+  CHECK_EQ(timer.Seconds(), 0);
+  EXPECT_TRUE(timer.initted());
+  EXPECT_FALSE(timer.running());
+  EXPECT_FALSE(timer.has_run_at_least_once());
+  timer.Start();
+  usleep(300 * 1000);
+  CHECK_GE(timer.Seconds(), 0.299);
+  CHECK_LE(timer.Seconds(), 0.301);
+  EXPECT_TRUE(timer.initted());
+  EXPECT_FALSE(timer.running());
+  EXPECT_TRUE(timer.has_run_at_least_once());
+}
+
+TEST_F(BenchmarkTest, TestTimerSecondsGPU) {
+  Caffe::set_mode(Caffe::GPU);
+  Timer timer;
+  CHECK_EQ(timer.Seconds(), 0);
+  EXPECT_TRUE(timer.initted());
+  EXPECT_FALSE(timer.running());
+  EXPECT_FALSE(timer.has_run_at_least_once());
+  timer.Start();
+  usleep(300 * 1000);
+  CHECK_GE(timer.Seconds(), 0.299);
+  CHECK_LE(timer.Seconds(), 0.301);
+  EXPECT_TRUE(timer.initted());
+  EXPECT_FALSE(timer.running());
+  EXPECT_TRUE(timer.has_run_at_least_once());
+}
+
+}  // namespace caffe
diff --git a/src/caffe/util/benchmark.cpp b/src/caffe/util/benchmark.cpp
index 19a036d9..b97a3c3c 100644
--- a/src/caffe/util/benchmark.cpp
+++ b/src/caffe/util/benchmark.cpp
@@ -1,6 +1,6 @@
 // Copyright 2014 kloud@github
 
-#include <ctime>
+#include <boost/date_time/posix_time/posix_time.hpp>
 #include <cuda_runtime.h>
 
 #include "caffe/common.hpp"
@@ -8,46 +8,72 @@
 
 namespace caffe {
 
-Timer::Timer() {
-  if (Caffe::mode() == Caffe::GPU) {
-    cudaEventCreate (&start_gpu_);
-    cudaEventCreate (&stop_gpu_);
-  }
+Timer::Timer()
+    : initted_(false),
+      running_(false),
+      has_run_at_least_once_(false) {
+  Init();
 }
 
 Timer::~Timer() {
   if (Caffe::mode() == Caffe::GPU) {
-    cudaEventDestroy (start_gpu_);
-    cudaEventDestroy (stop_gpu_);
+    CUDA_CHECK(cudaEventDestroy(start_gpu_));
+    CUDA_CHECK(cudaEventDestroy(stop_gpu_));
   }
 }
 
 void Timer::Start() {
-  if (Caffe::mode() == Caffe::GPU) {
-    cudaEventRecord(start_gpu_, 0);
-  } else {
-    start_cpu_ = clock();
+  if (!running()) {
+    if (Caffe::mode() == Caffe::GPU) {
+      CUDA_CHECK(cudaEventRecord(start_gpu_, 0));
+    } else {
+      start_cpu_ = boost::posix_time::microsec_clock::local_time();
+    }
+    running_ = true;
+    has_run_at_least_once_ = true;
   }
 }
 
 void Timer::Stop() {
-  if (Caffe::mode() == Caffe::GPU) {
-    cudaEventRecord(stop_gpu_, 0);
-  } else {
-    stop_cpu_ = clock();
+  if (running()) {
+    if (Caffe::mode() == Caffe::GPU) {
+      CUDA_CHECK(cudaEventRecord(stop_gpu_, 0));
+      CUDA_CHECK(cudaEventSynchronize(stop_gpu_));
+    } else {
+      stop_cpu_ = boost::posix_time::microsec_clock::local_time();
+    }
+    running_ = false;
   }
 }
 
-float Timer::ElapsedSeconds() {
-  float elapsed;
+float Timer::MilliSeconds() {
+  if (!has_run_at_least_once()) {
+    LOG(WARNING) << "Timer has never been run before reading time.";
+    return 0;
+  }
+  if (running()) {
+    Stop();
+  }
   if (Caffe::mode() == Caffe::GPU) {
-    cudaEventSynchronize(stop_gpu_);
-    cudaEventElapsedTime(&elapsed, start_gpu_, stop_gpu_);
-    elapsed /= 1000.;
+    CUDA_CHECK(cudaEventElapsedTime(&elapsed_milliseconds_, start_gpu_, stop_gpu_));
   } else {
-    elapsed = float(stop_cpu_ - start_cpu_) / CLOCKS_PER_SEC;
+    elapsed_milliseconds_ = (stop_cpu_ - start_cpu_).total_milliseconds();
+  }
+  return elapsed_milliseconds_;
+}
+
+float Timer::Seconds() {
+  return MilliSeconds() / 1000.;
+}
+
+void Timer::Init() {
+  if (!initted()) {
+    if (Caffe::mode() == Caffe::GPU) {
+      CUDA_CHECK(cudaEventCreate(&start_gpu_));
+      CUDA_CHECK(cudaEventCreate(&stop_gpu_));
+    }
+    initted_ = true;
   }
-  return elapsed;
 }
 
 }  // namespace caffe