Print frame processing latency to debug log

CMakeLists.txt

@@ -536,6 +536,8 @@ set(SUNSHINE_TARGET_FILES
         src/thread_safe.h
         src/sync.h
         src/round_robin.h
+        src/stat_trackers.h
+        src/stat_trackers.cpp
         ${PLATFORM_TARGET_FILES})
 
 set_source_files_properties(src/upnp.cpp PROPERTIES COMPILE_FLAGS -Wno-pedantic)

src/stat_trackers.cpp

@@ -0,0 +1,10 @@
+#include "stat_trackers.h"
+
+namespace stat_trackers {
+
+  boost::format
+  one_digit_after_decimal() {
+    return boost::format("%1$.1f");
+  }
+
+}  // namespace stat_trackers

src/stat_trackers.h

@@ -0,0 +1,41 @@
+#pragma once
+
+#include <chrono>
+#include <functional>
+#include <limits>
+
+#include <boost/format.hpp>
+
+namespace stat_trackers {
+
+  boost::format
+  one_digit_after_decimal();
+
+  template <typename T>
+  class min_max_avg_tracker {
+  public:
+    using callback_function = std::function<void(T stat_min, T stat_max, double stat_avg)>;
+
+    void
+    collect_and_callback_on_interval(T stat, const callback_function &callback, std::chrono::seconds interval_in_seconds) {
+      if (std::chrono::steady_clock::now() > data.last_callback_time + interval_in_seconds) {
+        callback(data.stat_min, data.stat_max, data.stat_total / data.calls);
+        data = {};
+      }
+      data.stat_min = std::min(data.stat_min, stat);
+      data.stat_max = std::max(data.stat_max, stat);
+      data.stat_total += stat;
+      data.calls += 1;
+    }
+
+  private:
+    struct {
+      std::chrono::steady_clock::steady_clock::time_point last_callback_time = std::chrono::steady_clock::now();
+      T stat_min = std::numeric_limits<T>::max();
+      T stat_max = 0;
+      double stat_total = 0;
+      uint32_t calls = 0;
+    } data;
+  };
+
+}  // namespace stat_trackers

src/stream.cpp

@@ -20,6 +20,7 @@ extern "C" {
 #include "input.h"
 #include "main.h"
 #include "network.h"
+#include "stat_trackers.h"
 #include "stream.h"
 #include "sync.h"
 #include "thread_safe.h"
@@ -1003,6 +1004,8 @@ namespace stream {
     // Video traffic is sent on this thread
     platf::adjust_thread_priority(platf::thread_priority_e::high);
 
+    stat_trackers::min_max_avg_tracker<uint16_t> frame_processing_latency_tracker;
+
     while (auto packet = packets->pop()) {
       if (shutdown_event->peek()) {
         break;
@@ -1026,6 +1029,16 @@ namespace stream {
         };
 
         uint16_t latency = duration_to_latency(std::chrono::steady_clock::now() - *packet->frame_timestamp);
+
+        if (config::sunshine.min_log_level <= 1) {
+          // Print frame processing latency stats to debug log every 20 seconds
+          auto print_info = [&](uint16_t min_latency, uint16_t max_latency, double avg_latency) {
+            auto f = stat_trackers::one_digit_after_decimal();
+            BOOST_LOG(debug) << "Frame processing latency (min/max/avg): " << f % (min_latency / 10.) << "ms/" << f % (max_latency / 10.) << "ms/" << f % (avg_latency / 10.) << "ms";
+          };
+          frame_processing_latency_tracker.collect_and_callback_on_interval(latency, print_info, 20s);
+        }
+
         frame_header.frame_processing_latency = latency;
       }
       else {