ofh: log warning when the timing worker skips more than two symbols

Author: Pavel Harbanau

.gitlab/ci/e2e/.env

@@ -1,6 +1,6 @@
 SRSGNB_REGISTRY_URI=registry.gitlab.com/softwareradiosystems/srsgnb
 RETINA_REGISTRY_PREFIX=registry.gitlab.com/softwareradiosystems/ci/retina
-RETINA_VERSION=0.89.2
+RETINA_VERSION=0.89.3
 UBUNTU_VERSION=24.04
 AMARISOFT_VERSION=2025-09-19
 SRSUE_VERSION=23.11

lib/ofh/timing/realtime_timing_worker.cpp

@@ -68,6 +68,7 @@ void realtime_timing_worker::start()
 
         auto now                  = gps_clock::now();
         auto ns_fraction          = calculate_ns_fraction_from(now);
+        last_wakeup_tp            = std::chrono::steady_clock::now();
         previous_symb_index       = get_symbol_index(ns_fraction, symbol_duration);
         previous_time_since_epoch = now.time_since_epoch().count();
 
@@ -122,6 +123,8 @@ calculate_slot_point(subcarrier_spacing scs, uint64_t gps_seconds, uint32_t frac
 
 void realtime_timing_worker::poll()
 {
+  auto sleeping_time = calculate_sleeping_time();
+
   auto now         = gps_clock::now();
   auto ns_fraction = calculate_ns_fraction_from(now);
 
@@ -158,6 +161,18 @@ void realtime_timing_worker::poll()
                 current_symbol_index % nof_symbols_per_slot);
     metrics_collector.update_skipped_symbols(delta);
   }
+  if (SRSRAN_UNLIKELY(delta >= 3)) {
+    log_conditional_warning(
+        logger,
+        enable_log_warnings_for_lates,
+        "Real-time timing worker woke up late, skipped '{}' symbols. Current symbol is '{}'. Equivalent realtime clock "
+        "sleep time has been '{}us', wall clock sleep time has been '{}us'",
+        delta,
+        current_symbol_index % nof_symbols_per_slot,
+        std::chrono::duration_cast<std::chrono::microseconds>(delta * symbol_duration).count(),
+        sleeping_time.count());
+  }
+
   if (SRSRAN_UNLIKELY(delta >= nof_symbols_per_slot)) {
     log_conditional_warning(
         logger,

lib/ofh/timing/realtime_timing_worker.h

@@ -84,6 +84,7 @@ class realtime_timing_worker : public operation_controller, public ota_symbol_bo
   bool                                           enable_log_warnings_for_lates;
   unsigned                                       previous_symb_index       = 0;
   gps_clock::rep                                 previous_time_since_epoch = 0;
+  std::chrono::steady_clock::time_point          last_wakeup_tp;
   stop_event_source                              stop_manager;
   timing_metrics_collector_impl                  metrics_collector;
 
@@ -118,6 +119,16 @@ class realtime_timing_worker : public operation_controller, public ota_symbol_bo
     auto tp_sec = std::chrono::time_point_cast<std::chrono::seconds>(tp);
     return tp - tp_sec;
   }
+
+  /// Calculates the time passed since last wake-up using the steady clock.
+  std::chrono::microseconds calculate_sleeping_time()
+  {
+    auto tp_now        = std::chrono::steady_clock::now();
+    auto sleeping_time = std::chrono::duration_cast<std::chrono::microseconds>(tp_now - last_wakeup_tp);
+    last_wakeup_tp     = tp_now;
+
+    return sleeping_time;
+  }
 };
 
 } // namespace ofh