Fix scalers with SAXS/WAXS

[jilavsky]

We have unexpected behavior of our S/WAXS code. We expect that scaler0 and scaler1 collect I0 (ungated and gated) during AD exposure.

In our scans.py our code sets time in lines 849-865 parameters needed for this collection. Lines 867/869 triggers the data collection on scaler0 and scaler1. Lines 865-899 stop counting and collect I0 values for AD to save in Nexus writer.

Unluckily, this fails: Currently we set the values and trigger the scalers counting, but BS seems to stop scaler0 and scaler1 counting during SAXS/SAXS AD data collection. So we hav eshort counting before AD triggers and short collection after it triggers, but we completely miss the time when we need these scalers to be collecting data.

I suspect that BS (bps.count) stops the scaler0 and scaler1 during the counting since it is not instructed to collect the data on them and does not ignore them as spec used to so (and BS used to do in prior incarnation) .

[prjemian]

Bluesky will not take control of any detector or other devices but described in the plan. With have to investigate the code to determine what is happening. I do not suspect bluesky is telling scalers not to count if they are not given as detectors in the plan.

On Sun, Oct 30, 2022, 12:53 PM Jan Ilavsky @.***> wrote:

Assigned #568 https://github.com/APS-USAXS/usaxs-bluesky/issues/568 to @prjemian https://github.com/prjemian.

— Reply to this email directly, view it on GitHub https://github.com/APS-USAXS/usaxs-bluesky/issues/568#event-7699498529, or unsubscribe https://github.com/notifications/unsubscribe-auth/AARMUMFA34ZJTXHKFBJ2NADWF2Y2NANCNFSM6AAAAAARSMOQJE . You are receiving this because you were assigned.Message ID: @.***>

[jilavsky]

Something is fishy here, this is how both scalers end after 20 seconds WAXS exposure. Also, we still have some issue with time, 20 seconds WAXS exposure takes 21.7 seconds. Even though this is 10th WAXS exposure in a row - with same times.

[jilavsky]

More observations. We get about 0.5 seconds collection before 20 second exposure then Scalers go to Done, then after exposure we get another 1-1.4 seconds separate count. While AD is Collecting, scalers are in Done state, something had to push Done button on them.

[jilavsky]

We are looking for two things:

1. Someone stops the Scalers after we start it before exposing AD
2. Someone again starts scalers after exposing AD....

Looking at SAXS (WAXS is same), this is in scans.py. None of these lines outside areaDetectorAcquire should have any impact on scalers...

    _md['plan_name'] = "SAXS"
    _md["hdf5_file"] = SAXS_file_name
    _md["hdf5_path"] = SAXSscan_path

    yield from record_sample_image_on_demand("saxs", scan_title_clean, _md)

    yield from areaDetectorAcquire(saxs_det, create_directory=-5, md=_md)
    ts = str(datetime.datetime.now())
    yield from bps.remove_suspender(suspend_BeamInHutch)

    saxs_det.hdf1.stage_sigs = old_det_stage_sigs    # TODO: needed? not even useful?

So we need to look inside area_detector.py in areaDetectorAcquire, but none of these look suspicious. The only actionable lines seem to be 68-70:

    bec.disable_table()
    yield from bp.count([det], md=_md)          # TODO: SPEC showed users incremental progress (1 Hz updates) #175
    bec.enable_table()

[prjemian]

Sounds like scalers are being staged for the AD image acquisition. Not what we want.

[prjemian]

These lines start the two scalers counting using ophyd methods (unknown to the RE). The stage()/unstage() process is not used. https://github.com/APS-USAXS/usaxs-bluesky/blob/a803031b8c806c74949ff53fab1ef4cc3cb2f678/instrument/plans/scans.py#L867-L871

[prjemian]

After the scalers are started counting: https://github.com/APS-USAXS/usaxs-bluesky/blob/a803031b8c806c74949ff53fab1ef4cc3cb2f678/instrument/plans/scans.py#L877-L881

then the scalers are stopped: https://github.com/APS-USAXS/usaxs-bluesky/blob/a803031b8c806c74949ff53fab1ef4cc3cb2f678/instrument/plans/scans.py#L885-L899

So far, no staging commands for either scaler.

[prjemian]

The text scaler does not occur in the file where record_sample_image_on_demand() is defined nor does it occur in the file whereareaDetectorAcquire() is defined.

This shoots down the theory that the RE might be staging the scalers. However, this can be checked in my simulators here.

[prjemian]

See a suggestion: https://github.com/APS-USAXS/usaxs-bluesky/issues/569#issuecomment-1296419097 and reply that follows.

[prjemian]

In my simulator, using scaler scaler and area detector adsimdet (with HDF plugin disabled),

test code

```python from bluesky import plan_stubs as bps from bluesky import plans as bp from bluesky import preprocessors as bpp from instrument.devices import adsimdet from instrument.devices import scaler1 for k in "acquire_time acquire_period".split(): if k in adsimdet.cam.stage_sigs: adsimdet.cam.stage_sigs.pop(k) def usaxs_issue_568(): @bpp.monitor_during_decorator([scaler1.count]) def _acquire_image(): yield from bp.count([adsimdet]) yield from bps.mv( scaler1.preset_time, 30, adsimdet.cam.acquire_time, 5, adsimdet.cam.acquire_period, 5.01, ) yield from bps.mv(scaler1.count, 1) yield from _acquire_image() yield from bps.mv(scaler1.count, 0) ```

this the test run:

In [6]: %run -i /tmp/usaxs_568.py

In [7]: RE(usaxs_issue_568())

Transient Scan ID: 366     Time: 2022-10-31 11:52:28
Persistent Unique Scan ID: '1464876a-7932-4975-a407-b4659169e710'
New stream: 'scaler1_count_monitor'
New stream: 'primary'
+-----------+------------+
|   seq_num |       time |
+-----------+------------+
|         1 | 11:52:33.2 |
+-----------+------------+
generator count ['1464876a'] (scan num: 366)
Out[7]: ('1464876a-7932-4975-a407-b4659169e710',)

In [8]: RE(usaxs_issue_568())

Transient Scan ID: 367     Time: 2022-10-31 11:52:40
Persistent Unique Scan ID: 'fbf66649-0f40-4563-8cf4-606c1bfb252c'
New stream: 'scaler1_count_monitor'
New stream: 'primary'
+-----------+------------+
|   seq_num |       time |
+-----------+------------+
|         1 | 11:52:45.5 |
+-----------+------------+
generator count ['fbf66649'] (scan num: 367)
Out[8]: ('fbf66649-0f40-4563-8cf4-606c1bfb252c',)

Now, examine the monitor stream to see if the scaler was stopped or restarted during area detector acquisition:

In [9]: run = cat[-1]

In [10]: run
Out[10]: 
BlueskyRun
  uid='fbf66649-0f40-4563-8cf4-606c1bfb252c'
  exit_status='success'
  2022-10-31 11:52:40.489 -- 2022-10-31 11:52:45.520
  Streams:
    * scaler1_count_monitor
    * primary

In [11]: run.scaler1_count_monitor.read()
Out[11]: 
<xarray.Dataset>
Dimensions:        (time: 1)
Coordinates:
  * time           (time) float64 1.667e+09
Data variables:
    scaler1_count  (time) int64 1

Only one event in the scaler's monitor stream, that's the initial value.

[prjemian]

note: If we add the scaler to the bp.count() call, then bluesky will wait until both adsimdet and scaler1 finish. not a good model of the original problem.

[prjemian]

So, our data acquisition procedure should be similar to this prototype I used for testing:

def usaxs_issue_568():
    @bpp.monitor_during_decorator([scaler1.count])
    def _acquire_image():
        yield from bp.count([adsimdet])

    yield from bps.mv(
        scaler1.preset_time, 30,
        adsimdet.cam.acquire_time, 5,
        adsimdet.cam.acquire_period, 5.01,
    )
    yield from bps.mv(scaler1.count, 1)
    logger.info("scaler1.time: %s", scaler1.time.get())

    yield from _acquire_image()
    logger.info("scaler1.time: %s", scaler1.time.get())

    yield from bps.mv(scaler1.count, 0)
    logger.info("scaler1.time: %s", scaler1.time.get())

[prjemian]

Also, code such as https://github.com/APS-USAXS/usaxs-bluesky/blob/a803031b8c806c74949ff53fab1ef4cc3cb2f678/instrument/plans/scans.py#L832-L834 and https://github.com/APS-USAXS/usaxs-bluesky/blob/a803031b8c806c74949ff53fab1ef4cc3cb2f678/instrument/plans/scans.py#L883

could be replaced with

@restorable_stage_sigs([saxs_det.hdf1])
def _inner_plan_steps():
    saxs_det.hdf1.stage_sigs["file_template"] = ad_file_template
    saxs_det.hdf1.stage_sigs["file_write_mode"] = "Single"
    saxs_det.hdf1.stage_sigs["blocking_callbacks"] = "No"
    # ...

where this is a new decorator I just developed:

def stage_sigs_wrapper(user_plan, devices):
    """
    Save stage_sigs from each device and restore after the user_plan.

    The user_plan is free to modify the stage_sigs of each device
    without further need to preserve original values.
    """
    def display(preface):
        for device in devices:
            logger.debug(
                "%s: %s.stage_sigs: %s", preface, device.name, device.stage_sigs
            )

    def _restore():
        for device in reversed(devices):
            device.stage_sigs = original[device].copy()
        display("AFTER restore")

    original = {}
    display("ORIGINAL")
    for device in devices:
        original[device] = device.stage_sigs.copy()

    try:
        display("BEFORE plan")
        yield from user_plan
        display("AFTER plan")
    finally:
        _restore()

restorable_stage_sigs = make_decorator(stage_sigs_wrapper)

[prjemian]

Code changes for this issue should be done in a branch, to allow immediate rollback (switching branches) until the code is accepted and merged.

[prjemian]

Aha! The shutters are controlled by a user transform in EPICS.

[prjemian]

[prjemian]

note: this was a copy of the settings from 9idcLAX:userTran1, the transform that is used.

[prjemian]

The values in the transform should be changed from 1 to 0, changing the logic of how the scalers are triggered (and fixing this issue). Because of this transform, it is not necessary for bluesky to trigger either scaler.

We plan to drop the branch and make this last change in master branch.

[prjemian]

The fix works as tested!