Capture/Linux: add sleep overshoot logging

Logging code for sleep overshoot analysis has been added to all Linux capture backends. Duplicated code has been moved out to common platform code.
LizardByte · Apr 5, 2024 · 87a5d93 · 87a5d93
1 parent 0b77071
commit 87a5d93
Show file tree

Hide file tree

Showing 6 changed files with 57 additions and 21 deletions.
diff --git a/src/platform/common.h b/src/platform/common.h
@@ -10,6 +10,7 @@
 #include <mutex>
 #include <string>
 
+#include "src/config.h"
 #include "src/logging.h"
 #include "src/stat_trackers.h"
 #include "src/thread_safe.h"
@@ -20,6 +21,8 @@ extern "C" {
 #include <moonlight-common-c/src/Limelight.h>
 }
 
+using namespace std::literals;
+
 struct sockaddr;
 struct AVFrame;
 struct AVBufferRef;
@@ -504,6 +507,18 @@ namespace platf {
   protected:
     // collect capture timing data (at loglevel debug)
     stat_trackers::min_max_avg_tracker<double> sleep_overshoot_tracker;
+    void
+    log_sleep_overshoot(std::chrono::nanoseconds overshoot_ns) {
+      if (config::sunshine.min_log_level <= 1) {
+        // Print sleep overshoot stats to debug log every 20 seconds
+        auto print_info = [&](double min_overshoot, double max_overshoot, double avg_overshoot) {
+          auto f = stat_trackers::one_digit_after_decimal();
+          BOOST_LOG(debug) << "Sleep overshoot (min/max/avg): " << f % min_overshoot << "ms/" << f % max_overshoot << "ms/" << f % avg_overshoot << "ms";
+        };
+        // std::chrono::nanoseconds overshoot_ns = std::chrono::steady_clock::now() - next_frame;
+        sleep_overshoot_tracker.collect_and_callback_on_interval(overshoot_ns.count() / 1000000., print_info, 20s);
+      }
+    }
   };
 
   class mic_t {

diff --git a/src/platform/linux/cuda.cpp b/src/platform/linux/cuda.cpp
@@ -800,11 +800,17 @@ namespace cuda {
           handle.reset();
         });
 
+        sleep_overshoot_tracker.reset();
+
         while (true) {
           auto now = std::chrono::steady_clock::now();
           if (next_frame > now) {
             std::this_thread::sleep_for(next_frame - now);
           }
+          now = std::chrono::steady_clock::now();
+          std::chrono::nanoseconds overshoot_ns = now - next_frame;
+          log_sleep_overshoot(overshoot_ns);
+
           next_frame += delay;
           if (next_frame < now) {  // some major slowdown happened; we couldn't keep up
             next_frame = now + delay;

diff --git a/src/platform/linux/kmsgrab.cpp b/src/platform/linux/kmsgrab.cpp
@@ -1193,12 +1193,18 @@ namespace platf {
       capture(const push_captured_image_cb_t &push_captured_image_cb, const pull_free_image_cb_t &pull_free_image_cb, bool *cursor) override {
         auto next_frame = std::chrono::steady_clock::now();
 
+        sleep_overshoot_tracker.reset();
+
         while (true) {
           auto now = std::chrono::steady_clock::now();
 
           if (next_frame > now) {
             std::this_thread::sleep_for(next_frame - now);
           }
+          now = std::chrono::steady_clock::now();
+          std::chrono::nanoseconds overshoot_ns = now - next_frame;
+          log_sleep_overshoot(overshoot_ns);
+
           next_frame += delay;
           if (next_frame < now) {  // some major slowdown happened; we couldn't keep up
             next_frame = now + delay;
@@ -1419,16 +1425,9 @@ namespace platf {
           if (next_frame > now) {
             std::this_thread::sleep_for(next_frame - now);
           }
-
-          if (config::sunshine.min_log_level <= 1) {
-            // Print sleep overshoot stats to debug log every 20 seconds
-            auto print_info = [&](double min_overshoot, double max_overshoot, double avg_overshoot) {
-              auto f = stat_trackers::one_digit_after_decimal();
-              BOOST_LOG(debug) << "Sleep overshoot (min/max/avg): " << f % min_overshoot << "ms/" << f % max_overshoot << "ms/" << f % avg_overshoot << "ms";
-            };
-            std::chrono::nanoseconds overshoot_ns = std::chrono::steady_clock::now() - next_frame;
-            sleep_overshoot_tracker.collect_and_callback_on_interval(overshoot_ns.count() / 1000000., print_info, 20s);
-          }
+          now = std::chrono::steady_clock::now();
+          std::chrono::nanoseconds overshoot_ns = now - next_frame;
+          log_sleep_overshoot(overshoot_ns);
 
           next_frame += delay;
           if (next_frame < now) {  // some major slowdown happened; we couldn't keep up

diff --git a/src/platform/linux/wlgrab.cpp b/src/platform/linux/wlgrab.cpp
@@ -129,12 +129,18 @@ namespace wl {
     capture(const push_captured_image_cb_t &push_captured_image_cb, const pull_free_image_cb_t &pull_free_image_cb, bool *cursor) override {
       auto next_frame = std::chrono::steady_clock::now();
 
+      sleep_overshoot_tracker.reset();
+
       while (true) {
         auto now = std::chrono::steady_clock::now();
 
         if (next_frame > now) {
           std::this_thread::sleep_for(next_frame - now);
         }
+        now = std::chrono::steady_clock::now();
+        std::chrono::nanoseconds overshoot_ns = now - next_frame;
+        log_sleep_overshoot(overshoot_ns);
+
         next_frame += delay;
         if (next_frame < now) {  // some major slowdown happened; we couldn't keep up
           next_frame = now + delay;
@@ -259,12 +265,18 @@ namespace wl {
     capture(const push_captured_image_cb_t &push_captured_image_cb, const pull_free_image_cb_t &pull_free_image_cb, bool *cursor) override {
       auto next_frame = std::chrono::steady_clock::now();
 
+      sleep_overshoot_tracker.reset();
+
       while (true) {
         auto now = std::chrono::steady_clock::now();
 
         if (next_frame > now) {
           std::this_thread::sleep_for(next_frame - now);
         }
+        now = std::chrono::steady_clock::now();
+        std::chrono::nanoseconds overshoot_ns = now - next_frame;
+        log_sleep_overshoot(overshoot_ns);
+
         next_frame += delay;
         if (next_frame < now) {  // some major slowdown happened; we couldn't keep up
           next_frame = now + delay;

diff --git a/src/platform/linux/x11grab.cpp b/src/platform/linux/x11grab.cpp
@@ -481,12 +481,18 @@ namespace platf {
     capture(const push_captured_image_cb_t &push_captured_image_cb, const pull_free_image_cb_t &pull_free_image_cb, bool *cursor) override {
       auto next_frame = std::chrono::steady_clock::now();
 
+      sleep_overshoot_tracker.reset();
+
       while (true) {
         auto now = std::chrono::steady_clock::now();
 
         if (next_frame > now) {
           std::this_thread::sleep_for(next_frame - now);
         }
+        now = std::chrono::steady_clock::now();
+        std::chrono::nanoseconds overshoot_ns = now - next_frame;
+        log_sleep_overshoot(overshoot_ns);
+
         next_frame += delay;
         if (next_frame < now) {  // some major slowdown happened; we couldn't keep up
           next_frame = now + delay;
@@ -621,12 +627,18 @@ namespace platf {
     capture(const push_captured_image_cb_t &push_captured_image_cb, const pull_free_image_cb_t &pull_free_image_cb, bool *cursor) override {
       auto next_frame = std::chrono::steady_clock::now();
 
+      sleep_overshoot_tracker.reset();
+
       while (true) {
         auto now = std::chrono::steady_clock::now();
 
         if (next_frame > now) {
           std::this_thread::sleep_for(next_frame - now);
         }
+        now = std::chrono::steady_clock::now();
+        std::chrono::nanoseconds overshoot_ns = now - next_frame;
+        log_sleep_overshoot(overshoot_ns);
+
         next_frame += delay;
         if (next_frame < now) {  // some major slowdown happened; we couldn't keep up
           next_frame = now + delay;

diff --git a/src/platform/windows/display_base.cpp b/src/platform/windows/display_base.cpp
@@ -154,7 +154,7 @@ namespace platf::dxgi {
       SetThreadExecutionState(ES_CONTINUOUS);
     });
 
-    stat_trackers::min_max_avg_tracker<double> sleep_overshoot_tracker;
+    sleep_overshoot_tracker.reset();
 
     while (true) {
       // This will return false if the HDR state changes or for any number of other
@@ -184,16 +184,8 @@ namespace platf::dxgi {
         }
         else {
           high_precision_sleep(sleep_period);
-
-          if (config::sunshine.min_log_level <= 1) {
-            // Print sleep overshoot stats to debug log every 20 seconds
-            auto print_info = [&](double min_overshoot, double max_overshoot, double avg_overshoot) {
-              auto f = stat_trackers::one_digit_after_decimal();
-              BOOST_LOG(debug) << "Sleep overshoot (min/max/avg): " << f % min_overshoot << "ms/" << f % max_overshoot << "ms/" << f % avg_overshoot << "ms";
-            };
-            std::chrono::nanoseconds overshoot_ns = std::chrono::steady_clock::now() - sleep_target;
-            sleep_overshoot_tracker.collect_and_callback_on_interval(overshoot_ns.count() / 1000000., print_info, 20s);
-          }
+          std::chrono::nanoseconds overshoot_ns = std::chrono::steady_clock::now() - sleep_target;
+          log_sleep_overshoot(overshoot_ns);
 
           status = snapshot(pull_free_image_cb, img_out, 0ms, *cursor);