some changes and log fix

python_app/hardware_full/librevna_multi_device_driver/controller.py

@@ -131,7 +131,14 @@ class MultiDeviceVnaController:
         if not self._reference_configuration_applied:
             self._configure_reference_clocks()
 
-        self._drain_all_received_packets()
+        drain_started_seconds = time.monotonic()
+        drained_packet_count = self._drain_all_received_packets()
+        logger.debug(
+            "timing: drain discarded %d stale packet(s) in %.2f ms (t=%.1f ms)",
+            drained_packet_count,
+            (time.monotonic() - drain_started_seconds) * 1e3,
+            time.monotonic() * 1e3,
+        )
 
         if (
             self._sweep_is_running
@@ -334,12 +341,16 @@ class MultiDeviceVnaController:
         self._sweep_is_running = True
         logger.debug("Sweep settings applied to all devices; sweep running")
 
-    def _drain_all_received_packets(self) -> None:
+    def _drain_all_received_packets(self) -> int:
         """Empty every device's received-packet queue, in parallel for 2+ devices.
 
         Concurrent draining keeps cross-device timing skew small so a hardware
         cycle wrap cannot slip between per-device drains and desynchronize the
         cycle counters.
+
+        Returns the total number of discarded packets, which the caller logs: a large
+        count means the host was far behind the free-running stream, a near-zero count
+        means the drain landed right after a sweep boundary.
         """
         # Drain every device queue in parallel rather than one after another:
         # serial drain leaves up to a few hundred microseconds of skew between
@@ -349,22 +360,31 @@ class MultiDeviceVnaController:
         # so concurrent get_nowait calls do not contend. A single device case
         # just runs inline to avoid the thread-spawn overhead.
         if len(self._all_devices) < 2:
-            for device_connection in self._all_devices:
-                device_connection.drain_received_packets()
-            return
+            return sum(
+                len(device_connection.drain_received_packets())
+                for device_connection in self._all_devices
+            )
+
+        drained_counts = [0] * len(self._all_devices)
+
+        def drain_one_device(device_index: int, device_connection: LibreVnaUsbBulkConnection) -> None:
+            """Drain one device's queue and record how many packets it held."""
+            drained_counts[device_index] = len(device_connection.drain_received_packets())
 
         drain_threads = [
             threading.Thread(
-                target=device_connection.drain_received_packets,
+                target=drain_one_device,
+                args=(device_index, device_connection),
                 name=f"drain-{device_connection.serial_number}",
                 daemon=True,
             )
-            for device_connection in self._all_devices
+            for device_index, device_connection in enumerate(self._all_devices)
         ]
         for drain_thread in drain_threads:
             drain_thread.start()
         for drain_thread in drain_threads:
             drain_thread.join()
+        return sum(drained_counts)
 
     @staticmethod
     def _normalize_master_stimulus_ports(master_stimulus_ports: Sequence[int]) -> tuple[int, ...]:

python_app/hardware_full/librevna_multi_device_driver/cycle_collection.py

@@ -441,6 +441,7 @@ def collect_complete_running_sweep_cycles(
     def build_cycle_tracking_handler(
         cycle_aware_handler: Callable[[ParsedVnaDatapoint, int], None],
         device_state: _DeviceCollectionState,
+        device_label: str = "device",
     ) -> Callable[[ParsedVnaDatapoint], bool]:
         """Wrap a cycle-aware handler with cross-device cycle tracking.
 
@@ -462,6 +463,11 @@ def collect_complete_running_sweep_cycles(
         cycle_tracking_state = {
             "current_cycle_index": 0,
             "synchronized": False,
+            # How many mid-sweep points were thrown away before the anchor was found.
+            # Near zero means the drain landed on a sweep boundary — the case where a
+            # stale point 0 could still have been in flight; a large count means the
+            # remainder of the in-progress sweep was safely skipped.
+            "pre_anchor_skipped": 0,
         }
 
         def handle_datapoint(parsed_datapoint: ParsedVnaDatapoint) -> bool:
@@ -475,6 +481,7 @@ def collect_complete_running_sweep_cycles(
 
             if not cycle_tracking_state["synchronized"]:
                 if current_point_index != 0:
+                    cycle_tracking_state["pre_anchor_skipped"] += 1
                     return False
                 # Candidate cycle 0. Commit it only once every device confirms it
                 # observed point 0 of the SAME physical sweep; otherwise reject the
@@ -484,6 +491,14 @@ def collect_complete_running_sweep_cycles(
                     report_cycle_misalignment()
                     return False
                 cycle_tracking_state["synchronized"] = True
+                logger.debug(
+                    "timing: %s anchored cycle 0 after skipping %d mid-sweep point(s) of %d "
+                    "(t=%.1f ms)",
+                    device_label,
+                    cycle_tracking_state["pre_anchor_skipped"],
+                    point_count,
+                    time.monotonic() * 1e3,
+                )
                 cycle_aware_handler(parsed_datapoint, 0)
                 return True
 
@@ -493,6 +508,12 @@ def collect_complete_running_sweep_cycles(
             # spurious wrap and desynchronize the cycle counter.
             if current_point_index == 0:
                 cycle_tracking_state["current_cycle_index"] += 1
+                logger.debug(
+                    "timing: %s first point of NEXT sweep arrived (cycle -> %d, t=%.1f ms)",
+                    device_label,
+                    cycle_tracking_state["current_cycle_index"],
+                    time.monotonic() * 1e3,
+                )
             current_cycle_index = cycle_tracking_state["current_cycle_index"]
             if current_cycle_index >= cycle_count:
                 # The sweep just wrapped past the final requested cycle, closing its
@@ -505,6 +526,14 @@ def collect_complete_running_sweep_cycles(
                 return False
 
             cycle_aware_handler(parsed_datapoint, current_cycle_index)
+            if current_point_index == point_count - 1:
+                logger.debug(
+                    "timing: %s last point of cycle %d arrived (index=%d, t=%.1f ms)",
+                    device_label,
+                    current_cycle_index,
+                    current_point_index,
+                    time.monotonic() * 1e3,
+                )
             return True
 
         return handle_datapoint
@@ -587,7 +616,9 @@ def collect_complete_running_sweep_cycles(
                             point_index,
                         ] = port_receiver_value
 
-        return build_cycle_tracking_handler(handle_slave_datapoint, device_state)
+        return build_cycle_tracking_handler(
+            handle_slave_datapoint, device_state, device_label=f"slave{slave_index}"
+        )
 
     master_device_state = _DeviceCollectionState()
     collection_threads = [
@@ -595,7 +626,9 @@ def collect_complete_running_sweep_cycles(
             target=collect_datapoints_from_device,
             args=(
                 master_device_connection,
-                build_cycle_tracking_handler(handle_master_datapoint, master_device_state),
+                build_cycle_tracking_handler(
+                    handle_master_datapoint, master_device_state, device_label="master"
+                ),
                 master_device_state,
             ),
             daemon=True,

python_app/hardware_full/switched_matrix_radar_service.py

@@ -2,7 +2,7 @@
 
 from __future__ import annotations
 
-from dataclasses import dataclass, replace
+from dataclasses import dataclass, field, replace
 import logging
 import time
 
@@ -31,6 +31,10 @@ class SwitchedMatrixRadarService:
     inner_output_positions: int
     inner_input_positions: int
     settling_ms: int = 0
+    # Monotonic end of the previous inner collection, so the DEBUG timing trace can
+    # report how long the gap between "sweep collected" and "switch driven" really is
+    # — that gap is where a stale in-flight point 0 can still slip past the drain.
+    _last_inner_end_ns: int = field(init=False, default=0, repr=False)
 
     def open(self) -> None:
         """Open the inner radar and both switches."""
@@ -78,17 +82,37 @@ class SwitchedMatrixRadarService:
         slots: list[TraceData | None] = [None] * (total_inputs * total_outputs)
 
         for out_k in range(out_steps):
-            if self.output_switch is not None:
-                self.output_switch.switch_to(out_k)
             for in_k in range(in_steps):
+                step_start_ns = time.monotonic_ns()
+                if self.output_switch is not None:
+                    self.output_switch.switch_to(out_k)
                 if self.input_switch is not None:
                     self.input_switch.switch_to(in_k)
+                switched_ns = time.monotonic_ns()
                 # Settle AFTER the last switch change and BEFORE collecting, so the
                 # cycle we anchor on starts with the RF path already stable.
                 if self.settling_ms > 0:
                     time.sleep(self.settling_ms / 1000.0)
+                settled_ns = time.monotonic_ns()
 
                 sub = self.inner.acquire_collection(collection_id)
+                inner_end_ns = time.monotonic_ns()
+                logger.debug(
+                    "timing: collection %d step out=%d in=%d | gap_prev_collect_to_switch=%s ms, "
+                    "switch=%.3f ms, settle=%.2f ms, inner_collect=%.2f ms",
+                    collection_id,
+                    out_k,
+                    in_k,
+                    (
+                        f"{(step_start_ns - self._last_inner_end_ns) / 1e6:.2f}"
+                        if self._last_inner_end_ns
+                        else "n/a"
+                    ),
+                    (switched_ns - step_start_ns) / 1e6,
+                    (settled_ns - switched_ns) / 1e6,
+                    (inner_end_ns - settled_ns) / 1e6,
+                )
+                self._last_inner_end_ns = inner_end_ns
                 for trace in sub.traces:
                     input_pos = in_k * self.inner_input_positions + int(trace.combo.input)
                     output_pos = out_k * self.inner_output_positions + int(trace.combo.output)