logging: Add an option to collect profiling

Use cmake -DENABLE_PROFILING=ON (OFF by default).

Author: xlz

CMakeLists.txt

@@ -36,6 +36,11 @@ OPTION(ENABLE_CUDA "Enable CUDA support" ON)
 OPTION(ENABLE_OPENGL "Enable OpenGL support" ON)
 OPTION(ENABLE_VAAPI "Enable VA-API support" ON)
 OPTION(ENABLE_TEGRAJPEG "Enable Tegra HW JPEG support" ON)
+OPTION(ENABLE_PROFILING "Collect profiling stats (memory consuming)" OFF)
+
+IF(ENABLE_PROFILING)
+  SET(LIBFREENECT2_WITH_PROFILING 1)
+ENDIF()
 
 IF(MSVC)
   # suppress several "possible loss of data" warnings, and

include/libfreenect2/config.h.in

@@ -61,4 +61,6 @@
 
 #cmakedefine LIBFREENECT2_WITH_CXX11_SUPPORT
 
+#cmakedefine LIBFREENECT2_WITH_PROFILING
+
 #endif // LIBFREENECT2_CONFIG_H

src/logging.cpp

@@ -32,6 +32,13 @@
 #include <string>
 #include <algorithm>
 
+#ifdef LIBFREENECT2_WITH_PROFILING
+#include <vector>
+#include <numeric>
+#include <functional>
+#include <cmath>
+#endif
+
 #ifdef LIBFREENECT2_WITH_CXX11_SUPPORT
 #include <chrono>
 #endif
@@ -192,6 +199,9 @@ class Timer
 
   Timer()
   {
+#if defined(LIBFREENECT2_WITH_OPENGL_SUPPORT)
+    glfwInit();
+#endif
     reset();
   }
 
@@ -209,10 +219,13 @@ class Timer
     time_start = std::chrono::high_resolution_clock::now();
   }
 
-  void stop()
+  double stop()
   {
-    duration += std::chrono::duration_cast<std::chrono::duration<double>>(std::chrono::high_resolution_clock::now() - time_start).count();
+    auto time_diff = std::chrono::high_resolution_clock::now() - time_start;
+    double this_duration = std::chrono::duration_cast<std::chrono::duration<double>>(time_diff).count();
+    duration += this_duration;
     count++;
+    return this_duration;
   }
 #elif defined(LIBFREENECT2_WITH_OPENGL_SUPPORT)
   double time_start;
@@ -222,28 +235,68 @@ class Timer
     time_start = glfwGetTime();
   }
 
-  void stop()
+  double stop()
   {
-    duration += glfwGetTime() - time_start;
+    double this_duration = glfwGetTime() - time_start;
+    duration += this_duration;
     count++;
+    return this_duration;
   }
 #else
   void start()
   {
   }
 
-  void stop()
+  double stop()
   {
+    return 0;
   }
 #endif
 };
 
 class WithPerfLoggingImpl: public Timer
 {
 public:
+#ifdef LIBFREENECT2_WITH_PROFILING
+  std::vector<double> stats;
+  std::string name;
+
+  WithPerfLoggingImpl()
+  {
+    stats.reserve(30*100);
+  }
+
+  ~WithPerfLoggingImpl()
+  {
+    if (stats.size() < 2)
+      return;
+    std::vector<double> &v = stats;
+    std::sort(v.begin(), v.end());
+    double sum = std::accumulate(v.begin(), v.end(), 0.0);
+    size_t n = v.size();
+    double mean = sum / n;
+    std::vector<double> diff(n);
+    std::transform(v.begin(), v.end(), diff.begin(), std::bind2nd(std::minus<double>(), mean));
+    double sqsum = std::inner_product(diff.begin(), diff.end(), diff.begin(), 0.0);
+    double std = std::sqrt(sqsum / (n-1));
+
+    std::cout << name << v[0] << " " << v[n/20] << " " << v[n/2] << " " << v[n - (n+19)/20] << " " << v[n-1] << " mean=" << mean << " std=" << std <<  " n=" << n << std::endl;
+  }
+#endif
+
   std::ostream &stop(std::ostream &stream)
   {
+#ifndef LIBFREENECT2_WITH_PROFILING
     Timer::stop();
+#else
+    double this_duration = Timer::stop();
+    if (name.empty())
+    {
+      std::stringstream &ss = static_cast<std::stringstream &>(stream);
+      name = ss.str();
+    }
+    stats.push_back(this_duration*1e3);
+#endif
     if (count < 100)
     {
       stream.setstate(std::ios::eofbit);

src/turbo_jpeg_rgb_packet_processor.cpp

@@ -96,6 +96,8 @@ void TurboJpegRgbPacketProcessor::process(const RgbPacket &packet)
 
     int r = tjDecompress2(impl_->decompressor, packet.jpeg_buffer, packet.jpeg_buffer_length, impl_->frame->data, 1920, 1920 * tjPixelSize[TJPF_BGRX], 1080, TJPF_BGRX, 0);
 
+    impl_->stopTiming(LOG_INFO);
+
     if(r == 0)
     {
       if(listener_->onNewFrame(Frame::Color, impl_->frame))
@@ -108,7 +110,6 @@ void TurboJpegRgbPacketProcessor::process(const RgbPacket &packet)
       LOG_ERROR << "Failed to decompress rgb image! TurboJPEG error: '" << tjGetErrorStr() << "'";
     }
 
-    impl_->stopTiming(LOG_INFO);
   }
 }