From c75a170af31112a9d659e0aae9c8a54a6c8e9d5a Mon Sep 17 00:00:00 2001 From: x12sa Date: Thu, 15 Oct 2026 15:25:53 +0200 Subject: [PATCH] docs(flomni): add scan overhead analysis from Oct 2026 beamtime logs Log analysis of the flOMNI beamtime 2026-10-07..12: time budget, per-point dead time, step-by-step scan-to-scan timeline mapped to code, analysis method/pitfalls, and ranked improvement ideas. Add TODO pointer. Co-Authored-By: Claude Opus 5.5 --- AGENTS_mirko.md | 6 + .../flomni/AI_docs/FLOMNI_SCAN_OVERHEAD.md | 250 ++++++++++++++++++ 2 files changed, 256 insertions(+) create mode 100644 csaxs_bec/bec_ipython_client/plugins/flomni/AI_docs/FLOMNI_SCAN_OVERHEAD.md diff --git a/AGENTS_mirko.md b/AGENTS_mirko.md index 36ad2608..074bf799 100644 --- a/AGENTS_mirko.md +++ b/AGENTS_mirko.md @@ -22,6 +22,12 @@ the repo when I ask for one. ## TODO +- 2026-10-15: reduce flOMNI scan overhead. Log analysis of the Oct 7–12 beamtime: ~3.4 s dead + time between projections plus ~30–50 ms per point; quick wins are the 1 s `status.done` + polling sleep in `scan_core`/`at_each_point` (also in lamni/omny fermat scans) and the + duplicate laser-tracker check. Findings, method and ranked ideas: + `csaxs_bec/bec_ipython_client/plugins/flomni/AI_docs/FLOMNI_SCAN_OVERHEAD.md`. + - 2026-09-21: port "always define `tomo_alignment_fit`" from Flomni to OMNY. Flomni is done (commit `5b688df`): `reset_tomo_alignment_fit()` writes zeros instead of deleting the global var, and `ensure_tomo_alignment_fit()` (called from `Flomni.__init__`) creates the zero fit diff --git a/csaxs_bec/bec_ipython_client/plugins/flomni/AI_docs/FLOMNI_SCAN_OVERHEAD.md b/csaxs_bec/bec_ipython_client/plugins/flomni/AI_docs/FLOMNI_SCAN_OVERHEAD.md new file mode 100644 index 00000000..7625e801 --- /dev/null +++ b/csaxs_bec/bec_ipython_client/plugins/flomni/AI_docs/FLOMNI_SCAN_OVERHEAD.md @@ -0,0 +1,250 @@ +# flOMNI tomography: where the time goes (scan overhead analysis) + +Written 2026-10-15 from the BEC logs of the flOMNI beamtime of **2026-10-07 08:46 to +2026-10-12 ~09:30** (setup changed to LamNI on 2026-10-12). Nothing proposed here has been +implemented yet. This is a findings + ideas document to pick the work up later. + +The code analysed is the production deployment that ran during that beamtime. It is identical to +the current one: `flomni_fermat_scan.py` and `rt_flomni_ophyd.py` were diffed against +`old_production_deployments/20261012T202711` with no differences. + +Data set: 10,403 completed + 365 aborted `flomni_fermat_scan`s, 120.8 h of wall time. +Sources: `/var/log/bec/{ScanServer,DeviceServer,ScanBundler,FileWriterManager}.*.log.gz`. + +## 1. Time budget (120.8 h) + +| Bucket | Hours | Share | +|---|---|---| +| Detector exposure (num_points × exp_time × frames_per_trigger) | 67.0 | 55 % | +| Per-point dead time inside the scan | ~19.5 | 16 % | +| Fixed per-scan setup/teardown inside open→closed (~4 s/scan) | ~11 | 9 % | +| Beam/shutter problems: aborted scans (3.9 h) + waiting for beam (6.4 h) | ~10.3 | 8.5 % | +| Long pauses without beam problem (manual work, `acquire` alignment, between tomograms) | ~7 | 6 % | +| Gaps between back-to-back scans (closed → next open, ~1 s) | 2.8 | 2.5 % | +| Eiger alarms after aborts, misc | ~1 | 1 % | + +- Interlocks: 106 "abort and repeat" restarts, mostly `shutter_es_device_within_limits_state` + and `shutter_device_within_limits_state`. +- 314 `EigerError` alarms on `eiger2_si_500k`. +- Worst single gap: 3 h starting 2026-10-10 07:33 (beam/interlock). + +"Fixed per-scan cost" plus "gaps between scans" together make up the scan-to-scan dead time +analysed in §3. The split between them is only the ScanServer's open/closed bookkeeping. + +## 2. Per-point dead time (largest loss overall, cause not yet understood) + +Real time per point, measured as open→closed / num_points: + +| exp_time × frames | nominal s/pt | real s/pt | dead time/pt | relative | +|---|---|---|---|---| +| 0.01 × 20 (n=8065) | 0.20 | 0.268 | 68 ms | +34 % | +| 0.1 × 1 (n=1633) | 0.10 | 0.197 | 97 ms | +97 % | +| 0.05 × 1 (n=656) | 0.05 | 0.143 | 93 ms | +186 % | + +These numbers still include the ~4 s fixed cost per scan spread over the points. The cadence of +`Read i out of N` during the scan gives 0.229 s/pt (mean) for 0.01×20, so the pure per-point +cost is **~30–50 ms**. It is roughly independent of exposure time, which points to a fixed +step/settle/trigger dead time in the RT controller point scan (`sd` command) or the trigger +chain (ddg1 external rising edge → Eiger). The BEC logs cannot resolve it. It needs RT +controller-side timing or a scope on the trigger lines. + +## 3. Scan-to-scan dead time (detailed) + +**True dead time from the last exposed point of projection N to the first exposed point of +N+1: 3.2 s median, 3.6 s mean.** About 10 h over the beamtime. + +Mean timestamps, relative to the last `Read i out of N` of the previous scan, over 9,876 +back-to-back transitions (gap < 5 s): + +| t [s] | Event (log marker) | Step duration | What happens / code | +|---|---|---|---| +| 0.00 | last `Read i out of N` (DeviceServer) | | readout thread `read_positions_from_sampler` finishes, `rt_flomni_ophyd.py:862` | +| 0.01 | `Flomni statistics` | | status of `complete(rt_positions)` set finished | +| 0.70 | MCS `Current data index … complete` | **0.69** | ScanServer still in the `at_each_point` `time.sleep(1)` loop (§5.1), then `post_scan`: rtx/rty/rtz move to end position + `complete_all_devices` | +| 1.16 | ScanServer `closed` | 0.46 | `post_scan` ddg1 → single shot, `unstage`, `close_scan` waits baseline readout | +| 2.17 | FileWriter `Finished writing file` | (1.0, in parallel) | does **not** block the next scan | +| 1.27 | client RPC `flomni_samples.sample_names.sample0.get` | | client loop between projections | +| 1.30 | client RPC `fsamroy.read` | | | +| 1.46 | client RPC `rtx.controller.laser_tracker_check_signalstrength` (queued as device_rpc) | | `flomni.py:3661` | +| 1.62 | ScanServer `Receiving scan request: flomni_fermat_scan` | **0.46 client side** | | +| 1.71 | `Fermat spiral sub-step offset` | | `prepare_scan` positions + corridor optimizer (3 ms) | +| 1.72 | DeviceServer `flomni scan stopped and deleted` | | `prepare_setup` → `clear_trajectory_generator` | +| 1.89 | `Rotating to requested angle` | | `flomni_rotation`, starts fsamroy move without waiting | +| 2.11 | ScanServer `open` | 0.49 since request | `prepare_scan` incl. rty move (`actions.set` waits) + baseline read | +| 2.16 | MCS on_stage done (0.05 s) | | `stage_all_devices` | +| 2.36 | ddg1 on_stage done (0.22 s) | | | +| 2.39 | Eiger `staged for scan` | | Eiger stage median 0.24 s, **mean 0.60 s** (long tail) | +| 2.66 | fupr `Move finished` | rotation ~0.8 s | `prepare_setup_part_2` waits for rotation | +| 3.15 | `Laser tracker running!` | **0.5** | `laser_tracker_on` → `laser_tracker_wait_on_target`; 0.87 s when it has to wait (28 % of scans, 0.5 s poll) | +| 3.29 | `Sending N positions took …` (0.15 s, thread) | | `add_pos_to_scan`, second `laser_tracker_check_signalstrength`, `move_samx_to_scan_region` | +| ~3.4 | first point exposed | | `kickoff`: wait buffer, `start_scan`, `sleep(0.1)` | +| (4.95) | first `Read 0 out of N` logged | | logged ~6 points late, see §4 | + +Rotation vs angle step (median Δangle between projections is 1.5°): + +| Δangle | n | rotation (stopdel→Move finished) | Ra→R0 (uncorrected, includes the ~1.5 s Read-0 offset) | +|---|---|---|---| +| < 1° | 1186 | 0.63 s | 4.65 s | +| 1–2° | 4818 | 0.76 s | 4.71 s | +| 2–5° | 2130 | 0.87 s | 4.78 s | +| 5–20° | 1497 | 1.25 s | 5.34 s | +| > 20° | 245 | 4.76 s | 10.32 s | + +For typical small steps the rotation largely overlaps staging and is not the bottleneck. The +dead time is dominated by serial bookkeeping: end-of-scan polling, close, client round-trip, +prepare, open, stage, then laser tracker. + +Precise sub-second numbers taken from the log text itself: +- Eiger stage: 0.596 mean / 0.240 median (0.21 s of it JungfrauJoch communication). +- ddg1 stage: 0.221 s. +- MCS stage: 0.052 s. +- Sending positions: 0.147 s. +- FileWriter master file: 1.0 s. + +## 4. Method and pitfalls (for re-running, e.g. on LamNI) + +- **Timestamps only have 1 s resolution.** Averaging `floor(t2) - floor(t1)` over thousands of + scans is unbiased, so use means; medians of individual differences are meaningless at this + resolution. +- **`Read 0 out of N` is logged late.** `read_positions_from_sampler` only starts reading once + `current_position_in_scan > 5` (`rt_flomni_ophyd.py:885`) and lags one point behind. True + scan start ≈ t(Read i₀) − (i₀ + 6) × per-point time, with the per-point time taken from the + Read cadence. Without this correction the gap looks ~1.5 s longer. +- At the end, after the controller mode drops to 0, the remaining points are read immediately, + so the last `Read` line ≈ the real end of exposure. +- **Markers used:** + - ScanServer: `New scan status: / open|closed|aborted` (also carries `num_points`, + `exp_time`, `frames_per_trigger`, `angle`), `Receiving scan request: {'scan_type': + 'flomni_fermat_scan'`, the client device_rpc requests, `Rotating to requested angle`, + `Requesting to abort and repeat`, `Alarm (MAJOR)`, `Beamline state … out of bounds`. + - DeviceServer: `Read i out of N`, `Flomni statistics`, `Current data index`, + `flomni scan stopped and deleted`, `on_stage completed in`, `staged for scan. Time spent`, + fupr `Move finished`, `Waiting for laser tracker`, `Laser tracker running`, + `positions took`. + - ScanBundler: `Sending point 0 for`. FileWriterManager: `[SUCCESS] | Finished writing file`. +- Use only consecutive *completed* scans with closed→open < 5 s for the transition analysis. + Larger gaps are user pauses, alignment or interlocks. + +Minimal snippet that rebuilds the §3 timeline (run from `/var/log/bec`, extend the marker list +as needed): + +```python +import gzip, glob, re, bisect, statistics as st, datetime as dt +from collections import defaultdict +T = lambda s: dt.datetime.strptime(s, "%Y-%m-%d %H:%M:%S").timestamp() +files = lambda p: sorted(glob.glob(f"{p}.2026-10-0[7-9]*.gz") + glob.glob(f"{p}.2026-10-1[0-2]*.gz")) +scans, ev = {}, defaultdict(list) +for f in files("ScanServer"): + for l in gzip.open(f, "rt", errors="replace"): + if l.startswith("2026") and "New scan status:" in l and "'flomni_fermat_scan'" in l: + m = re.search(r"New scan status: (\S+) / (\w+) /", l) + scans.setdefault(m[1], {}).setdefault(m[2], T(l[:19])) +markers = {"read": " out of ", "mcs": "Current data index", "eig": "staged for scan", + "rot": "fupr_ophyd | [INFO] | Move finished", "lt": "Laser tracker running", + "send": "positions took"} +for f in files("DeviceServer"): + for l in gzip.open(f, "rt", errors="replace"): + for k, v in markers.items(): + if l.startswith("2026") and v in l: + ev[k].append(T(l[:19])); break +for k in ev: ev[k].sort() +first = lambda k, a, b: next((t for t in ev[k][bisect.bisect_left(ev[k], a):] if t <= b), None) +def last(k, a, b): + i = bisect.bisect_right(ev[k], b) - 1 + return ev[k][i] if i >= 0 and ev[k][i] >= a else None +done = sorted((s for s in scans.values() if "open" in s and "closed" in s), key=lambda s: s["open"]) +rel = defaultdict(list) +for a, b in zip(done, done[1:]): + if b["open"] - a["closed"] > 5: continue + ra = last("read", a["open"], a["closed"]); r0 = first("read", b["open"], b["closed"]) + if not (ra and r0): continue + for k, t in [("mcs", last("mcs", a["open"], a["closed"])), ("closed", a["closed"]), + ("open", b["open"]), ("eig", first("eig", a["closed"], r0)), + ("rot", first("rot", a["closed"], r0)), ("lt", last("lt", a["closed"], r0)), + ("send", first("send", a["closed"], r0)), ("read0_logged", r0)]: + if t: rel[k].append(t - ra) +for k, v in rel.items(): print(f"{k:14s} {st.mean(v):6.2f} s n={len(v)}") +``` + +## 5. Improvement ideas (ranked by expected payoff per effort) + +### 5.1 End-of-scan polling sleep (~0.5 s/scan, ~1.4 h per beamtime). Easy. +`flomni_fermat_scan.py:233-254`: +```python +status = self.actions.complete(device=self.dev.rt_positions, wait=False) +while not status.done: + self.at_each_point() # read_monitored_devices(); time.sleep(1) +``` +The ScanServer checks `status.done` only once per second, so after the RT readout finishes it +idles 0–1 s (≈0.5 s mean) before `post_scan`. The 1 s sleep also sets the ~1 Hz monitored +readout rate (`num_monitored_readouts` ≈ scan duration in s), and that rate must be kept. Fix: +keep reading monitored devices every ~1 s but poll `done` finely, e.g. +```python +def at_each_point(self): + self.actions.read_monitored_devices() + t0 = time.time() + while time.time() - t0 < 1 and not self._rt_status.done: + time.sleep(0.02) +``` +or `status.wait(timeout=1)` if `ScanStubStatus` supports it (BEC core, not checked). +**The same pattern exists in `lamni_fermat_scan.py:225-227` and `omny_fermat_scan.py:202-203`** +(there the `sleep(1)` is in `scan_core`). Fix all three. + +### 5.2 Serial setup chain, starting the rotation earlier (~0.5–1 s). Medium. +The rotation only starts ~0.7 s after the previous scan closed (client round-trip + +`prepare_scan`), and the laser tracker, position upload and checks run only after staging and +rotation are done. Ideas: +- Start the fsamroy move to the next angle as early as possible. For example, the client could + send the next angle so the move overlaps the end of the previous scan, or a combined + multi-angle scan could run several projections inside one queue item. +- Overlap `laser_tracker_on`/`add_pos_to_scan` with staging where safe. Note that + `move_samx_to_scan_region` warns that an rtx move clears the trajectory, so ordering matters. +- `prepare_setup` moves rty with a blocking `actions.set`. Check whether it can overlap the + rotation. + +### 5.3 Duplicate laser-tracker signal check (~0.15–0.45 s). Easy. +The client calls `dev.rtx.controller.laser_tracker_check_signalstrength()` before every +projection (`flomni.py:3661`, queued as a device_rpc). The scan calls it again in +`prepare_setup_part_2` (`flomni_fermat_scan.py:360`), which already raises an alarm/abort on +low signal. Drop the client-side call in the per-projection path; keep it where it is used +interactively. The `flomni_samples` and `fsamroy.read` RPCs around it also cost round-trips. +Check whether they are needed per projection or can be cached. + +### 5.4 Laser tracker wait granularity (~0.2 s average on 28 % of scans). Easy. +`laser_tracker_wait_on_target` (`rt_flomni_ophyd.py:377-393`) sleeps 0.5 s between checks. +Use e.g. 0.05 s and scale `max_repeat` and the count==10 re-enable accordingly. The function is +also called twice per scan (`laser_tracker_on` and `laser_tracker_check_signalstrength`), and +each call does `laser_tracker_galil_enable()` plus a `Ts` query. + +### 5.5 Eiger staging tail. Investigate. +Median 0.24 s, mean 0.60 s, so some stages take seconds. Extract the +`staged for scan. Time spent X s` distribution and correlate with time and JungfrauJoch state. + +### 5.6 Small fixed sleeps +- `kickoff`: `shutdown_event.wait(0.1)` after `start_scan` (`rt_flomni_ophyd.py:963`). +- `move_samx_to_scan_region`: `sleep(0.05)` (`rt_flomni_ophyd.py:185`). +- `RtFlomniReadbackSignal._socket_get` has `sleep(0.1)` (`rt_flomni_ophyd.py:553`). Check how + often rt readbacks are read during the transition (e.g. `rty` set, baseline). + +### 5.7 Per-point dead time (§2). Biggest, hardest. +~30–50 ms/pt, i.e. 16 % of beamtime. Needs RT controller timing (step/settle time per point in +the `sd` point scan) and the trigger chain. Short exposures (0.05/0.1 s × 1 frame) are hit +hardest. Using more frames at shorter exposure (0.01 × 20) already amortizes it better. + +### 5.8 Interlock / Eiger-error recovery (~10 h) +Look at how long recovery after a shutter interlock takes vs the beam actually being back, +and why `EigerError` (314 alarms) happens. + +### 5.9 Better instrumentation +- Millisecond timestamps in the BEC log format would make §3 exact per scan. This is BEC core; + write it up rather than change it here. +- Alternatively, add `logger.info` lines with `time.perf_counter()` deltas inside + `FlomniFermatScan` hooks (prepare/stage/pre_scan/scan_core/post_scan/unstage/close). That is + csaxs_bec-local and enough to time every phase directly. +- Re-run the analysis on LamNI data (from 2026-10-12 on) for comparison. + +## 6. Ownership +Items in BEC core (`ScanStubStatus.wait`, log timestamp format) belong to the BEC core team. +Write them up rather than change them (see `AGENTS_mirko.md`). Everything in +`csaxs_bec/scans/*_fermat_scan.py`, `devices/omny/rt/` and the flomni client plugin can be +changed here.