benchmarking

server/src/loop.rs

@@ -3,9 +3,10 @@ use bitvec::prelude::*;
 use control_core::machines::connection::MachineConnection;
 use control_core::realtime::{set_core_affinity, set_realtime_priority};
 use std::sync::Arc;
+use std::sync::atomic::{AtomicU64, Ordering};
 use std::time::{Duration, Instant};
 use tracing::{instrument, trace_span};
-
+static LOOP_COUNTER: AtomicU64 = AtomicU64::new(0);
 pub fn init_loop(app_state: Arc<AppState>) -> Result<(), anyhow::Error> {
     // Start control loop
     std::thread::Builder::new()
@@ -130,8 +131,15 @@ pub async fn loop_once<'maindevice>(app_state: Arc<AppState>) -> Result<(), anyh
         smol::Timer::after(Duration::from_micros(500)).await;
     }
 
-    // execute machines
     {
+        let cycle = LOOP_COUNTER.fetch_add(1, Ordering::Relaxed);
+
+        let start = if cycle % 1000 == 0 {
+            Some(Instant::now())
+        } else {
+            None
+        };
+
         let span = trace_span!("loop_once_act");
         let _enter = span.enter();
 
@@ -141,16 +149,22 @@ pub async fn loop_once<'maindevice>(app_state: Arc<AppState>) -> Result<(), anyh
         for machine in machine_guard.iter() {
             let connection = &machine.1.lock_blocking().machine_connection;
             if let MachineConnection::Connected(machine) = connection {
-                // if the machine is currenlty locked (likely processing API call)
-                // we skip the machine
                 if let Some(mut machine_guard) = machine.try_lock() {
-                    let span = trace_span!("loop_once_act_machine",);
+                    let span = trace_span!("loop_once_act_machine");
                     let _enter = span.enter();
-                    // execute machine
                     machine_guard.act(now);
                 }
             }
         }
+
+        if let Some(start) = start {
+            let elapsed = start.elapsed();
+            tracing::info!(
+                "loop_once_act duration on cycle {}: {} ns",
+                cycle,
+                elapsed.as_nanos()
+            );
+        }
     }
 
     // only if we have an ethercat setup

server/src/machines/extruder1/act.rs

@@ -8,6 +8,10 @@ use std::time::{Duration, Instant};
 #[cfg(not(feature = "mock-machine"))]
 impl MachineAct for ExtruderV2 {
     fn act(&mut self, now: Instant) {
+        use std::sync::atomic::AtomicU64;
+        static CYCLE_COUNTER: AtomicU64 = AtomicU64::new(0);
+        let start = Instant::now();
+
         self.temperature_controller_back.update(now);
         self.temperature_controller_nozzle.update(now);
         self.temperature_controller_front.update(now);
@@ -29,14 +33,21 @@ impl MachineAct for ExtruderV2 {
             self.switch_to_heat();
         }
 
-        let now = Instant::now();
-
-        // more than 33ms have passed since last emit (30 "fps" target)
+        /*// emit state & live values every ~33ms
         if now.duration_since(self.last_measurement_emit) > Duration::from_secs_f64(1.0 / 30.0) {
-            self.maybe_emit_state_event();
-            // Emit live values at 30 FPS
+            // self.maybe_emit_state_event();
             self.emit_live_values();
             self.last_measurement_emit = now;
+        }*/
+
+        // End timer & log every 10 cycles
+        let elapsed = start.elapsed();
+        let count = CYCLE_COUNTER.fetch_add(1, std::sync::atomic::Ordering::Relaxed);
+        if count % 1000 == 0 {
+            tracing::info!(
+                "[ExtruderV2::act] Duration of act(): {} ns",
+                elapsed.as_nanos()
+            );
         }
     }
 }

server/src/machines/laser/act.rs

@@ -17,13 +17,32 @@ use std::time::{Duration, Instant};
 ///
 /// The method ensures that the diameter value is updated approximately 60 times per second.
 ///
+use std::sync::atomic::{AtomicU64, Ordering};
+
 impl MachineAct for LaserMachine {
     fn act(&mut self, now: Instant) {
+        // Start high-resolution timer
+        let start = Instant::now();
+
         self.update();
-        // more than 33ms have passed since last emit (30 "fps" target)
+
+        // emit live values every ~33ms
         if now.duration_since(self.last_measurement_emit) > Duration::from_secs_f64(1.0 / 30.0) {
             self.emit_live_values();
             self.last_measurement_emit = now;
         }
+
+        // End timer
+        let elapsed = start.elapsed();
+        static COUNTER: AtomicU64 = AtomicU64::new(0);
+        let count = COUNTER.fetch_add(1, Ordering::Relaxed);
+
+        // Log every 10th call to reduce spam
+        if count % 1000 == 0 {
+            tracing::info!(
+                "[LaserMachine::act] Duration of act(): {} ns",
+                elapsed.as_nanos()
+            );
+        }
     }
 }

server/src/machines/winder2/act.rs

@@ -1,29 +1,36 @@
 use super::Winder2;
 use control_core::machines::new::MachineAct;
+use std::sync::atomic::{AtomicU64, Ordering};
 use std::time::{Duration, Instant};
 
 impl MachineAct for Winder2 {
     fn act(&mut self, now: Instant) {
-        // sync the spool speed
+        static CYCLE_COUNTER: AtomicU64 = AtomicU64::new(0);
+        let start = Instant::now();
+
+        // original act code
         self.sync_spool_speed(now);
-
-        // sync the puller speed
         self.sync_puller_speed(now);
-
-        // sync the traverse speed
         self.sync_traverse_speed();
-
-        // automatically stops or pulls after N Meters if enabled
         self.stop_or_pull_spool(now);
 
         if self.traverse_controller.did_change_state() {
             self.emit_state();
         }
 
-        // more than 33ms have passed since last emit (30 "fps" target)
         if now.duration_since(self.last_measurement_emit) > Duration::from_secs_f64(1.0 / 30.0) {
             self.emit_live_values();
             self.last_measurement_emit = now;
         }
+
+        // increment and check counter
+        let cycle = CYCLE_COUNTER.fetch_add(1, Ordering::Relaxed);
+        if cycle % 1000 == 0 {
+            let duration = start.elapsed();
+            tracing::info!(
+                "[Winder2::act] Duration of act(): {} ns",
+                duration.as_nanos()
+            );
+        }
     }
 }

server/src/performance_metrics.rs

@@ -12,6 +12,7 @@ pub struct EthercatPerformanceMetrics {
     loop_times: VecDeque<Duration>,
     last_loop_start: Option<Instant>,
     last_log_time: Instant,
+    pub loop_count: u32,
 }
 
 impl Default for EthercatPerformanceMetrics {
@@ -27,6 +28,7 @@ impl EthercatPerformanceMetrics {
             txrx_times: VecDeque::with_capacity(METRICS_WINDOW_SIZE),
             loop_times: VecDeque::with_capacity(METRICS_WINDOW_SIZE),
             last_loop_start: None,
+            loop_count: 0,
             last_log_time: Instant::now(),
         }
     }