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

diff --git a/include/caffe/util/benchmark.hpp b/include/caffe/util/benchmark.hpp
index 073b33c..fd6719a 100644 (file)
--- a/include/caffe/util/benchmark.hpp
+++ b/include/caffe/util/benchmark.hpp
@@ -3,6 +3,7 @@
 #ifndef CAFFE_UTIL_BENCHMARK_H_
 #define CAFFE_UTIL_BENCHMARK_H_
 
+#include <boost/date_time/posix_time/posix_time.hpp>
 #include <cuda_runtime.h>
 
 namespace caffe {
@@ -13,13 +14,24 @@ class Timer {
   virtual ~Timer();
   void Start();
   void Stop();
-  float ElapsedSeconds();
+  float MilliSeconds();
+  float Seconds();
+
+  inline bool initted() { return initted_; }
+  inline bool running() { return running_; }
+  inline bool has_run_at_least_once() { return has_run_at_least_once_; }
 
  protected:
+  void Init();
+
+  bool initted_;
+  bool running_;
+  bool has_run_at_least_once_;
   cudaEvent_t start_gpu_;
   cudaEvent_t stop_gpu_;
-  clock_t start_cpu_;
-  clock_t stop_cpu_;
+  boost::posix_time::ptime start_cpu_;
+  boost::posix_time::ptime stop_cpu_;
+  float elapsed_milliseconds_;
 };
 
 }  // namespace caffe

diff --git a/src/caffe/test/test_benchmark.cpp b/src/caffe/test/test_benchmark.cpp
new file mode 100644 (file)
index 0000000..9866f7d
--- /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 19a036d..b97a3c3 100644 (file)
--- 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

diff --git a/tools/net_speed_benchmark.cpp b/tools/net_speed_benchmark.cpp
index a0e589e..e7bcd48 100644 (file)
--- a/tools/net_speed_benchmark.cpp
+++ b/tools/net_speed_benchmark.cpp
@@ -76,11 +76,9 @@ int main(int argc, char** argv) {
     for (int j = 0; j < total_iter; ++j) {
       layers[i]->Forward(bottom_vecs[i], &top_vecs[i]);
     }
-    timer.Stop();
-    LOG(ERROR) << layername << "\tforward: " << timer.ElapsedSeconds() << " seconds.";
+    LOG(ERROR) << layername << "\tforward: " << timer.MilliSeconds() << " milli seconds.";
   }
-  forward_timer.Stop();
-  LOG(ERROR) << "Forward pass: " << forward_timer.ElapsedSeconds() << " seconds.";
+  LOG(ERROR) << "Forward pass: " << forward_timer.MilliSeconds() << " milli seconds.";
   Timer backward_timer;
   backward_timer.Start();
   for (int i = layers.size() - 1; i >= 0; --i) {
@@ -89,14 +87,11 @@ int main(int argc, char** argv) {
     for (int j = 0; j < total_iter; ++j) {
       layers[i]->Backward(top_vecs[i], true, &bottom_vecs[i]);
     }
-    timer.Stop();
     LOG(ERROR) << layername << "\tbackward: "
-        << timer.ElapsedSeconds() << " seconds.";
+        << timer.MilliSeconds() << " milli seconds.";
   }
-  backward_timer.Stop();
-  LOG(ERROR) << "Backward pass: " << backward_timer.ElapsedSeconds() << " seconds.";
-  total_timer.Stop();
-  LOG(ERROR) << "Total Time: " << total_timer.ElapsedSeconds() << " seconds.";
+  LOG(ERROR) << "Backward pass: " << backward_timer.MilliSeconds() << " milli seconds.";
+  LOG(ERROR) << "Total Time: " << total_timer.MilliSeconds() << " milli seconds.";
   LOG(ERROR) << "*** Benchmark ends ***";
   return 0;
 }