nvmeof: refactor timer for exact frequency timing with drift correction

- Replace relative timing with absolute time calculation to prevent drift
- Implement drift detection and correction mechanism
- Add comprehensive logging for timer firing, execution duration, drift
  and rescheduling

This refactoring ensures the nvmeof monitor client maintains exact frequency
timing over long periods, even when individual tick executions are delayed.

Signed-off-by: Alexander Indenbaum <aindenba@redhat.com>

diff --git a/src/nvmeof/NVMeofGwMonitorClient.cc b/src/nvmeof/NVMeofGwMonitorClient.cc
index c362bf21ca2a82020dd00884a269d5175b41f24d..2a84ee5d2083d8497cd47c4403ffbbcfadce133f 100644 (file)
--- a/src/nvmeof/NVMeofGwMonitorClient.cc
+++ b/src/nvmeof/NVMeofGwMonitorClient.cc
@@ -81,6 +81,7 @@ std::shared_ptr<grpc::ChannelCredentials> NVMeofGwMonitorClient::gw_creds()
 
 int NVMeofGwMonitorClient::init()
 {
+  dout(1) << "=== NVMeofGwMonitorClient::init() STARTED ===" << dendl;
   dout(10) << dendl;
   std::string val;
   auto args = argv_to_vec(orig_argc, orig_argv);
@@ -109,7 +110,7 @@ int NVMeofGwMonitorClient::init()
     }
   }
 
-  dout(10) << "gateway name: " << name <<
+  dout(1) << "Configuration parsed - gateway name: " << name <<
     " pool:" << pool <<
     " group:" << group <<
     " address: " << gateway_address << dendl;
@@ -119,28 +120,36 @@ int NVMeofGwMonitorClient::init()
   ceph_assert((server_cert.empty() == client_key.empty()) && (client_key.empty() == client_cert.empty()));
   init_gw_ssl_opts();
 
+  dout(1) << "About to initialize signal handlers" << dendl;
   init_async_signal_handler();
   register_async_signal_handler(SIGHUP, sighup_handler);
+  dout(1) << "Signal handlers initialized" << dendl;
 
   std::lock_guard l(lock);
+  dout(1) << "Acquired main lock, starting messenger initialization" << dendl;
 
   // Initialize Messenger
   client_messenger->add_dispatcher_tail(this);
   client_messenger->add_dispatcher_head(&objecter);
   client_messenger->start();
+  dout(1) << "Messenger started" << dendl;
 
   poolctx.start(2);
+  dout(1) << "Pool context started" << dendl;
 
   // Initialize MonClient
+  dout(1) << "About to build initial monmap" << dendl;
   if (monc.build_initial_monmap() < 0) {
     client_messenger->shutdown();
     client_messenger->wait();
     return -1;
   }
 
+  dout(1) << "Initial monmap built successfully" << dendl;
   monc.sub_want("NVMeofGw", 0, 0);
   monc.set_want_keys(CEPH_ENTITY_TYPE_MON|CEPH_ENTITY_TYPE_OSD);
   monc.set_messenger(client_messenger.get());
+  dout(1) << "MonClient configured" << dendl;
 
   // We must register our config callback before calling init(), so
   // that we see the initial configuration message
@@ -154,7 +163,9 @@ int NVMeofGwMonitorClient::init()
     });
   dout(4) << "nvmeof Registered monc callback" << dendl;
 
+  dout(1) << "About to call monc.init()" << dendl;
   int r = monc.init();
+  dout(1) << "monc.init() returned: " << r << dendl;
   if (r < 0) {
     monc.shutdown();
     client_messenger->shutdown();
@@ -163,7 +174,9 @@ int NVMeofGwMonitorClient::init()
   }
   dout(10) << "nvmeof Registered monc callback" << dendl;
 
+  dout(1) << "About to call monc.authenticate()" << dendl;
   r = monc.authenticate();
+  dout(1) << "monc.authenticate() returned: " << r << dendl;
   if (r < 0) {
     derr << "Authentication failed, did you specify an ID with a valid keyring?" << dendl;
     monc.shutdown();
@@ -171,7 +184,7 @@ int NVMeofGwMonitorClient::init()
     client_messenger->wait();
     return r;
   }
-  dout(10) << "monc.authentication done" << dendl;
+  dout(1) << "monc.authentication done" << dendl;
   monc.set_passthrough_monmap();
 
   client_t whoami = monc.get_global_id();
@@ -180,14 +193,23 @@ int NVMeofGwMonitorClient::init()
   objecter.init();
   objecter.enable_blocklist_events();
   objecter.start();
+  dout(1) << "Starting timer initialization" << dendl;
   timer.init();
 
   {
     std::lock_guard bl(beacon_lock);
-    tick();
+    // Initialize timer state for exact frequency timing
+    next_tick_time = ceph::mono_clock::now();
+    auto tick_period = g_conf().get_val<std::chrono::seconds>("nvmeof_mon_client_tick_period");
+    dout(1) << "Initializing timer with period " << tick_period.count() << " seconds" << dendl;
   }
 
-  dout(10) << "Complete." << dendl;
+  dout(1) << "Monitor client initialization completed successfully" << dendl;
+  
+  // Start the timer after full initialization is complete
+  dout(1) << "Starting timer after full initialization" << dendl;
+  start_timer();
+  
   return 0;
 }
 
@@ -288,14 +310,64 @@ void NVMeofGwMonitorClient::tick()
   disconnect_panic();
   send_beacon();
   first_beacon = false;
-  timer.add_event_after(
-      g_conf().get_val<std::chrono::seconds>("nvmeof_mon_client_tick_period").count(),
-      new LambdaContext([this](int r){
-          tick();
-      }
-  ));
+
+  // Schedule next tick with exact frequency timing
+  schedule_next_tick();
+}
+
+void NVMeofGwMonitorClient::start_timer()
+{
+  std::lock_guard bl(beacon_lock);
+  dout(1) << "start_timer() called" << dendl;
+  
+  dout(1) << "About to call schedule_next_tick() from start_timer()" << dendl;
+  schedule_next_tick();
+  dout(1) << "schedule_next_tick() completed successfully from start_timer()" << dendl;
+}
+
+void NVMeofGwMonitorClient::schedule_next_tick()
+{
+  ceph_assert(ceph_mutex_is_locked_by_me(beacon_lock));
+  dout(1) << "schedule_next_tick() called" << dendl;
+
+  // Calculate next tick time based on configured interval
+  auto tick_period = g_conf().get_val<std::chrono::seconds>("nvmeof_mon_client_tick_period");
+  next_tick_time += tick_period;
+
+  // Get current time to check for drift
+  auto now = ceph::mono_clock::now();
+
+  // If we're behind schedule, adjust next_tick_time to prevent drift accumulation
+  if (next_tick_time < now) {
+    dout(1) << "Timer drift detected, adjusting next_tick_time from "
+             << next_tick_time << " to " << now << dendl;
+    next_tick_time = now;
+  }
+
+  // Schedule the next tick
+  auto callback = new LambdaContext([this](int r) {
+    std::lock_guard bl(beacon_lock);
+    tick();
+  });
+
+  auto tick_time = next_tick_time;
+
+  // Call timer.add_event_at() while holding the lock (standard Ceph pattern)
+  // The timer requires the lock to be held per ceph_assert in Timer.cc
+  dout(1) << "About to call timer.add_event_at()" << dendl;
+  if (!timer.add_event_at(tick_time, callback)) {
+    dout(1) << "Failed to schedule timer event (timer shutting down)" << dendl;
+    return;
+  }
+  dout(1) << "timer.add_event_at() completed successfully" << dendl;
+  
+  auto delay_ns = (next_tick_time - now).count();
+  dout(1) << "Rescheduled next tick at " << next_tick_time
+          << " (delay: " << delay_ns << " ns, "
+          << (delay_ns / 1000000.0) << " ms)" << dendl;
 }
 
+
 void NVMeofGwMonitorClient::shutdown()
 {
   std::lock_guard l(lock);

diff --git a/src/nvmeof/NVMeofGwMonitorClient.h b/src/nvmeof/NVMeofGwMonitorClient.h
index b1ca5c94debb1b0a85b09de2b9234ab3d49a2aca..3bfe44d24239a20a1bdf59990d5bbd7e03910e90 100644 (file)
--- a/src/nvmeof/NVMeofGwMonitorClient.h
+++ b/src/nvmeof/NVMeofGwMonitorClient.h
@@ -21,6 +21,7 @@
 #include "common/Finisher.h"
 #include "common/Timer.h"
 #include "common/LogClient.h"
+#include "common/ceph_time.h"
 
 #include "mon/MonClient.h"
 #include "osdc/Objecter.h"
@@ -71,11 +72,18 @@ protected:
   ceph::mutex beacon_lock = ceph::make_mutex("NVMeofGw::beacon_lock");
   SafeTimer timer;
 
+  // Timer state for exact frequency timing
+  ceph::mono_clock::time_point next_tick_time;
+
   int orig_argc;
   const char **orig_argv;
 
   void send_config_beacon(); 
   void send_beacon();
+
+  // Timer management for exact frequency
+  void start_timer();
+  void schedule_next_tick();
  
 public:
   NVMeofGwMonitorClient(int argc, const char **argv);