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 <noreply@anthropic.com>
This commit is contained in:
x12saandClaude Opus 5.5 committed
1 parent
a30bc8e5c5
commit
c75a170af3
2 files changed
+256
No files matched your search
@@ -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
|
||||
|
||||
@@ -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: <id> / 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.
|
||||
Reference in new issue
Block a user