Move timing code into logging system

Also implement a WithPerfLogging class based on timing code to
remove duplicate timing code in several processors.

Author: xlz

examples/protonect/CMakeLists.txt

@@ -101,7 +101,6 @@ SET(SOURCES
   src/resource.cpp
   src/command_transaction.cpp
   src/registration.cpp
-  src/timer.cpp
   src/logging.cpp
   src/libfreenect2.cpp
 

examples/protonect/include/libfreenect2/logging.h

@@ -36,6 +36,19 @@
 namespace libfreenect2
 {
 
+class WithPerfLoggingImpl;
+
+class WithPerfLogging
+{
+public:
+  WithPerfLogging();
+  virtual ~WithPerfLogging();
+  void startTiming();
+  std::ostream &stopTiming(std::ostream &stream);
+private:
+  WithPerfLoggingImpl *impl_;
+};
+
 class LogMessage
 {
 private:

examples/protonect/include/libfreenect2/packet_processor.h

@@ -27,8 +27,6 @@
 #ifndef PACKET_PROCESSOR_H_
 #define PACKET_PROCESSOR_H_
 
-#include <libfreenect2/timer.h>
-
 namespace libfreenect2
 {
 

examples/protonect/include/libfreenect2/timer.h

@@ -202,7 +202,7 @@ inline int bfi(int width, int offset, int src2, int src3)
   return ((src2 << offset) & bitmask) | (src3 & ~bitmask);
 }
 
-class CpuDepthPacketProcessorImpl
+class CpuDepthPacketProcessorImpl: public WithPerfLogging
 {
 public:
   Mat<uint16_t> p0_table0, p0_table1, p0_table2;
@@ -214,11 +214,6 @@ class CpuDepthPacketProcessorImpl
   float trig_table1[512*424][6];
   float trig_table2[512*424][6];
 
-  double timing_acc;
-  double timing_acc_n;
-
-  Timer timer;
-
   bool enable_bilateral_filter, enable_edge_filter;
   DepthPacketProcessor::Parameters params;
 
@@ -231,34 +226,12 @@ class CpuDepthPacketProcessorImpl
     newIrFrame();
     newDepthFrame();
 
-    timing_acc = 0.0;
-    timing_acc_n = 0.0;
-
     enable_bilateral_filter = true;
     enable_edge_filter = true;
 
     flip_ptables = true;
   }
 
-  void startTiming()
-  {
-    timer.start();
-  }
-
-  void stopTiming()
-  {
-    timing_acc += timer.stop();
-    timing_acc_n += 1.0;
-
-    if(timing_acc_n >= 100.0)
-    {
-      double avg = (timing_acc / timing_acc_n);
-      LOG_INFO << "[CpuDepthPacketProcessor] avg. time: " << (avg * 1000) << "ms -> ~" << (1.0/avg) << "Hz";
-      timing_acc = 0.0;
-      timing_acc_n = 0.0;
-    }
-  }
-
   void newIrFrame()
   {
     ir_frame = new Frame(512, 424, 4);
@@ -975,7 +948,7 @@ void CpuDepthPacketProcessor::process(const DepthPacket &packet)
     impl_->newDepthFrame();
   }
 
-  impl_->stopTiming();
+  impl_->stopTiming(LOG_INFO);
 }
 
 } /* namespace libfreenect2 */

examples/protonect/src/cpu_depth_packet_processor.cpp

@@ -30,6 +30,14 @@
 #include <string>
 #include <algorithm>
 
+#ifdef LIBFREENECT2_WITH_CXX11_SUPPORT
+#include <chrono>
+#endif
+
+#ifdef LIBFREENECT2_WITH_OPENGL_SUPPORT
+#include <GLFW/glfw3.h>
+#endif
+
 namespace libfreenect2
 {
 Logger::~Logger() {}
@@ -144,6 +152,98 @@ void setGlobalLogger(Logger *logger)
   userLogger_ = logger;
 }
 
+class Timer
+{
+ public:
+  double duration;
+  size_t count;
+
+  Timer()
+  {
+    reset();
+  }
+
+  void reset()
+  {
+    duration = 0;
+    count = 0;
+  }
+
+#ifdef LIBFREENECT2_WITH_CXX11_SUPPORT
+  std::chrono::time_point<std::chrono::high_resolution_clock> time_start;
+
+  void start()
+  {
+    time_start = std::chrono::high_resolution_clock::now();
+  }
+
+  void stop()
+  {
+    duration += std::chrono::duration_cast<std::chrono::duration<double>>(std::chrono::high_resolution_clock::now() - time_start).count();
+    count++;
+  }
+#elif defined(LIBFREENECT2_WITH_OPENGL_SUPPORT)
+  double time_start;
+
+  void start()
+  {
+    time_start = glfwGetTime();
+  }
+
+  void stop()
+  {
+    duration += glfwGetTime() - time_start;
+    count++;
+  }
+#else
+  void start()
+  {
+  }
+
+  void stop()
+  {
+  }
+#endif
+};
+
+class WithPerfLoggingImpl: public Timer
+{
+public:
+  std::ostream &stop(std::ostream &stream)
+  {
+    Timer::stop();
+    if (count < 100)
+    {
+      stream.setstate(std::ios::eofbit);
+      return stream;
+    }
+    double avg = duration / count;
+    reset();
+    stream << "avg. time: " << (avg * 1000) << "ms -> ~" << (1.0/avg) << "Hz";
+    return stream;
+  }
+};
+
+WithPerfLogging::WithPerfLogging()
+  :impl_(new WithPerfLoggingImpl)
+{
+}
+
+WithPerfLogging::~WithPerfLogging()
+{
+  delete impl_;
+}
+
+void WithPerfLogging::startTiming()
+{
+  impl_->start();
+}
+
+std::ostream &WithPerfLogging::stopTiming(std::ostream &stream)
+{
+  impl_->stop(stream);
+}
+
 std::string getShortName(const char *func)
 {
   std::string src(func);

examples/protonect/src/logging.cpp

@@ -65,7 +65,7 @@ std::string loadCLSource(const std::string &filename)
   return std::string(reinterpret_cast<const char *>(data), length);
 }
 
-class OpenCLDepthPacketProcessorImpl
+class OpenCLDepthPacketProcessorImpl: public WithPerfLogging
 {
 public:
   cl_short lut11to16[2048];
@@ -75,11 +75,6 @@ class OpenCLDepthPacketProcessorImpl
   libfreenect2::DepthPacketProcessor::Config config;
   DepthPacketProcessor::Parameters params;
 
-  double timing_acc;
-  double timing_acc_n;
-
-  Timer timer;
-
   Frame *ir_frame, *depth_frame;
 
   cl::Context context;
@@ -144,8 +139,6 @@ class OpenCLDepthPacketProcessorImpl
     newIrFrame();
     newDepthFrame();
 
-    timing_acc = 0.0;
-    timing_acc_n = 0.0;
     image_size = 512 * 424;
 
     deviceInitialized = initDevice(deviceId);
@@ -536,25 +529,6 @@ class OpenCLDepthPacketProcessorImpl
     return true;
   }
 
-  void startTiming()
-  {
-    timer.start();
-  }
-
-  void stopTiming()
-  {
-    timing_acc += timer.stop();
-    timing_acc_n += 1.0;
-
-    if(timing_acc_n >= 100.0)
-    {
-      double avg = (timing_acc / timing_acc_n);
-      LOG_INFO << "[OpenCLDepthPacketProcessor] avg. time: " << (avg * 1000) << "ms -> ~" << (1.0 / avg) << "Hz";
-      timing_acc = 0.0;
-      timing_acc_n = 0.0;
-    }
-  }
-
   void newIrFrame()
   {
     ir_frame = new Frame(512, 424, 4);
@@ -673,7 +647,7 @@ void OpenCLDepthPacketProcessor::process(const DepthPacket &packet)
 
   impl_->run(packet);
 
-  impl_->stopTiming();
+  impl_->stopTiming(LOG_INFO);
 
   if(has_listener)
   {

examples/protonect/src/opencl_depth_packet_processor.cpp

@@ -330,7 +330,7 @@ struct Texture : public WithOpenGLBindings
   }
 };
 
-struct OpenGLDepthPacketProcessorImpl : public WithOpenGLBindings
+struct OpenGLDepthPacketProcessorImpl : public WithOpenGLBindings, public WithPerfLogging
 {
   GLFWwindow *opengl_context_ptr;
   std::string shader_folder;
@@ -364,11 +364,6 @@ struct OpenGLDepthPacketProcessorImpl : public WithOpenGLBindings
   DepthPacketProcessor::Parameters params;
   bool params_need_update;
 
-  double timing_acc;
-  double timing_acc_n;
-
-  Timer timer;
-
   bool do_debug;
 
   struct Vertex
@@ -387,8 +382,6 @@ struct OpenGLDepthPacketProcessorImpl : public WithOpenGLBindings
     stage2_framebuffer(0),
     filter2_framebuffer(0),
     params_need_update(true),
-    timing_acc(0),
-    timing_acc_n(0),
     do_debug(debug)
   {
   }
@@ -441,25 +434,6 @@ struct OpenGLDepthPacketProcessorImpl : public WithOpenGLBindings
     debug.gl(b);
   }
 
-  void startTiming()
-  {
-    timer.start();
-  }
-
-  void stopTiming()
-  {
-    timing_acc += timer.stop();
-    timing_acc_n += 1.0;
-
-    if(timing_acc_n >= 100.0)
-    {
-      double avg = (timing_acc / timing_acc_n);
-      LOG_INFO << "[OpenGLDepthPacketProcessor] avg. time: " << (avg * 1000) << "ms -> ~" << (1.0/avg) << "Hz";
-      timing_acc = 0.0;
-      timing_acc_n = 0.0;
-    }
-  }
-
   void initialize()
   {
     ChangeCurrentOpenGLContext ctx(opengl_context_ptr);
@@ -946,7 +920,7 @@ void OpenGLDepthPacketProcessor::process(const DepthPacket &packet)
 
   if(impl_->do_debug) glfwSwapBuffers(impl_->opengl_context_ptr);
 
-  impl_->stopTiming();
+  impl_->stopTiming(LOG_INFO);
 
   if(has_listener)
   {