diff --git a/apps/studio/src/orisys_studio/app_window.py b/apps/studio/src/orisys_studio/app_window.py index 1af3ba4..c039080 100644 --- a/apps/studio/src/orisys_studio/app_window.py +++ b/apps/studio/src/orisys_studio/app_window.py @@ -197,6 +197,9 @@ class StudioMainWindow(QMainWindow): #: Was the most recent readout valid? ``None`` before the first sample. self._last_sample_valid: bool | None = None self._latest_fps: float | None = None + #: What the last frame cost to acquire and process, in milliseconds — the + #: other half of the frame-rate reading. + self._latest_process_ms: float | None = None #: Last coefficients file written by the calibration panel (not applied). self._last_calibration_export = "" self._depth_range_value: tuple[float, float] | None = None @@ -1357,6 +1360,11 @@ class StudioMainWindow(QMainWindow): detail = t("status.rail_video_name", name=Path(path).name) if self._show_fps and self._latest_fps is not None: fps = f"{self._latest_fps:.1f} FPS" + # The cost goes next to the rate because one without the other cannot + # be read: "16.7 FPS" is either a slow camera or a pipeline that + # cannot keep up, and only this number tells the two apart. + if self._latest_process_ms: + fps = f"{fps} · {self._latest_process_ms:.0f} ms" detail = f"{detail} · {fps}" if detail else fps self.toolbar.set_source_summary(detail) # The full path and the replay's notes do not fit on a 30 px rail, so @@ -2111,6 +2119,7 @@ class StudioMainWindow(QMainWindow): self._last_display_available = None self._last_sample_valid = None self._latest_fps = None + self._latest_process_ms = None self._depth_range_value = None self._last_depth_frame = None # The new session's store is cleared *before* the charts are attached to @@ -2197,6 +2206,7 @@ class StudioMainWindow(QMainWindow): if not keep_frame: self.arrow_panel.clear_preview(t("panels.arrow_empty")) self._latest_fps = None + self._latest_process_ms = None self._last_sample_valid = None self._last_display_fallback = None self._last_display_available = None @@ -2365,6 +2375,7 @@ class StudioMainWindow(QMainWindow): self._render_run_image(packet) if is_new: self._latest_fps = getattr(packet, "fps", None) + self._latest_process_ms = getattr(packet, "process_ms", None) # The rail carries the live telemetry (fps, validity, calibration) and # the record strip its own numbers. Both compare before repainting, so # this is safe on a 16 ms timer. diff --git a/apps/studio/tests/test_ui_smoke.py b/apps/studio/tests/test_ui_smoke.py index dcd48df..751ece1 100644 --- a/apps/studio/tests/test_ui_smoke.py +++ b/apps/studio/tests/test_ui_smoke.py @@ -2105,6 +2105,29 @@ def test_the_status_bar_is_a_notice_line_not_a_state_line(make_window): _finish(window, stuck) +def test_the_rail_reads_the_rate_and_what_it_cost(qt_app, make_window): + """A frame rate alone cannot say whether we or the camera are the slow part. + + ``packet.process_ms`` is the whole per-frame cost, so the rail shows it next + to the rate: "16.7 FPS · 58 ms" means the loop cannot keep up, while + "16.7 FPS · 6 ms" means the camera is only delivering 16.7. + """ + window = make_window() + window._show_fps = True + window._latest_fps = 16.67 + window._latest_process_ms = 58.4 + window._refresh_status_rail() + text = window.toolbar.source_summary.text() + assert "16.7 FPS" in text, text + assert "58 ms" in text, text + + # Without a measured cost the rate is still shown, on its own. + window._latest_process_ms = None + window._refresh_status_rail() + assert window.toolbar.source_summary.text().strip().endswith("FPS") + window.close() + + # ------------------------------------------------------- plot settings dialog def test_the_chart_gear_opens_the_settings_dialog(qt_app, make_window): """The gear is the one place the filters can be changed from the UI.""" diff --git a/shared/src/orisys_app_shared/acquisition/sdk_worker.py b/shared/src/orisys_app_shared/acquisition/sdk_worker.py index 983402b..5591490 100644 --- a/shared/src/orisys_app_shared/acquisition/sdk_worker.py +++ b/shared/src/orisys_app_shared/acquisition/sdk_worker.py @@ -735,6 +735,11 @@ class SdkAcquisitionWorker(RecordSinkMixin): break t0 = time.perf_counter() + # ``t0`` is when this frame was *collected*: the device's own rate + # and the frame's acquisition time are measured from here, not + # from the end of its processing (that would report how long the + # pipeline took, dressed up as a frame rate). + # # ``CaptureSource.read_latest`` hands back the newest frame and, # until the pipeline produces another one, that **same** frame # again. Treating the repeat as a new sample doubled every @@ -772,7 +777,7 @@ class SdkAcquisitionWorker(RecordSinkMixin): compute_error = "" # The frame's acquisition time, so an event that happens on this # frame is dated when it happened rather than when it was queued. - frame_mono = max(0.0, time.perf_counter() - self._mono_t0) + frame_mono = max(0.0, t0 - self._mono_t0) try: # Applying new coefficients is reported separately from the # compute chain: a rejected document is an operator error, @@ -797,7 +802,11 @@ class SdkAcquisitionWorker(RecordSinkMixin): chain_depth, chain_error = process_chain(sensor) compute_error = compute_error or chain_error t1 = time.perf_counter() - frame_times.append(t1) + # The rate is measured between *collections* (``t0``), so it is + # the rate the frames arrived at. Measuring it after the compute + # chain instead made the rail report the loop's own cost as if it + # were the device's rate. + frame_times.append(t0) cutoff = t1 - FPS_WINDOW_S frame_times = [t for t in frame_times if t >= cutoff] # A *rate*, not a count: counting arrivals in a one-second window @@ -807,6 +816,10 @@ class SdkAcquisitionWorker(RecordSinkMixin): span = frame_times[-1] - frame_times[0] if len(frame_times) > 1 else 0.0 fps = (len(frame_times) - 1) / span if span > 0.0 else 0.0 forces = read_forces_from_sensor(sensor, config_ref=mode.config_ref) + # Everything this frame cost, including the force readout — the + # number that says whether the loop can still keep up with the + # device, which the frame rate alone cannot. + t_done = time.perf_counter() invalid_reason = forces.get("invalid_reason") or compute_error raw_frame = _ensure_bgr(raw) # The frame the chain above actually consumed, kept as the @@ -825,10 +838,10 @@ class SdkAcquisitionWorker(RecordSinkMixin): mono_t=( frame_id * frame_period if is_file - else max(0.0, t1 - self._mono_t0) + else max(0.0, t0 - self._mono_t0) ), fps=fps, - process_ms=(t1 - t0) * 1000.0, + process_ms=(t_done - t0) * 1000.0, normal_force=forces["normal_force"], shear_x=forces["shear_x"], shear_y=forces["shear_y"], @@ -857,7 +870,10 @@ class SdkAcquisitionWorker(RecordSinkMixin): self._emit(packet) frame_id += 1 saw_frame = True - last_frame_mono = t1 + last_frame_mono = t0 + # The pacing phase reference stays the end of the compute chain: + # the loop waits out the rest of the frame period from there, and + # that is the behaviour the frame-rate tests pin. last_frame_at = t1 except Exception as exc: self._set_end_reason("error")