diff --git a/CMakeLists.txt b/CMakeLists.txt index 30ec64c8..cd71fd33 100644 --- a/CMakeLists.txt +++ b/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) diff --git a/src/stat_trackers.cpp b/src/stat_trackers.cpp new file mode 100644 index 00000000..c3f16578 --- /dev/null +++ b/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 diff --git a/src/stat_trackers.h b/src/stat_trackers.h new file mode 100644 index 00000000..81fc0038 --- /dev/null +++ b/src/stat_trackers.h @@ -0,0 +1,41 @@ +#pragma once + +#include +#include +#include + +#include + +namespace stat_trackers { + + boost::format + one_digit_after_decimal(); + + template + class min_max_avg_tracker { + public: + using callback_function = std::function; + + 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::max(); + T stat_max = 0; + double stat_total = 0; + uint32_t calls = 0; + } data; + }; + +} // namespace stat_trackers diff --git a/src/stream.cpp b/src/stream.cpp index 016f9592..173f8ff6 100644 --- a/src/stream.cpp +++ b/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 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 {