Skip to content
This repository has been archived by the owner on Apr 19, 2024. It is now read-only.

guard slit motors sometimes stuck in MOVING state #253

Closed
prjemian opened this issue Jun 18, 2019 · 48 comments
Closed

guard slit motors sometimes stuck in MOVING state #253

prjemian opened this issue Jun 18, 2019 · 48 comments
Assignees
Labels
bug Something isn't working

Comments

@prjemian
Copy link
Contributor

prjemian commented Jun 18, 2019

@kmpeters We are still having troubles with the guard slit motors getting stuck in MOVING state. Sometimes, we find this while running bluesky, sometimes while moving them from caQtDM. Always, this involves a session where we are using both tools.

Tried adding an explicit caput MOTOR.STUP 1 (status update) for each motor 9idcLAX:max:c0:m{3,4,5,6] but that did not help us. (EDIT: Actually, the set to .STUP provoked an additional problem. Seems to be a distraction.)

@prjemian prjemian added the bug Something isn't working label Jun 18, 2019
@prjemian prjemian added this to the 2019-06 beam time milestone Jun 18, 2019
@prjemian prjemian self-assigned this Jun 18, 2019
prjemian added a commit that referenced this issue Jun 18, 2019
@kmpeters
Copy link

Are these the only motors that have this issue? If so, the problem is likely to be in the 4slit support rather than the motor support.

@kmpeters
Copy link

What is the state of the following PVs when the motors get stuck in the moving state?

$ caget 9idcLAX:GSlit1{H,V}:gate{,Open}
9idcLAX:GSlit1H:gate           Closed
9idcLAX:GSlit1H:gateOpen       Closed
9idcLAX:GSlit1V:gate           Closed
9idcLAX:GSlit1V:gateOpen       Closed

@prjemian
Copy link
Contributor Author

These are the only motors we are having troubles with. I agree that the problem is in the EPICS IOC layer, not bluesky, since we also see the problem using a GUI. Your suggestion of the 4slit support seems a good place to look.

It will take a bit to run the diagnostics since users are measuring data now. We'll get to it but with some delay.

@prjemian
Copy link
Contributor Author

prjemian commented Jun 21, 2019

If the problem is with the 4slit database, this can be run offline in a softIOC that simulates the guard slits.

See the documentation. We are using the 2slit_soft database that uses soft motors rather than ao records.

@prjemian
Copy link
Contributor Author

prjemian commented Jun 24, 2019

I've got a softIOC ready to test this:

caget gov:Slit1{H,V}{size,center,x{n,p}} and related PVs

gov:Slit1Hsize                 0
gov:Slit1Hcenter               0
gov:Slit1Hxn                   0
gov:Slit1Hxp                   0
gov:Slit1Vsize                 0
gov:Slit1Vcenter               0
gov:Slit1Vxn                   0
gov:Slit1Vxp                   0
  • EPICS /APSshare/epics/base-3.14.12.5
  • synApps /APSshare/epics/synApps_5_8/support
  • OPTICS $(synApps)/optics-2-9-3
  • db 2slit_soft.db

Note that there are later updates to this support that might need an IOC update to apply:

  • SUPPORT /APSshare/epics/synApps_6_0/support
  • EPICS_BASE /APSshare/epics/base-3.15.6
  • OPTICS $(synApps)/optics-R2-13-1
  • db 2slit_soft.vdb

@prjemian
Copy link
Contributor Author

prjemian commented Jun 26, 2019

correction:

  • synApps 5.7: /net/s9dserv/xorApps/epics/synApps_5_7/ioc/9idcLAX/iocBoot/ioc9idcLAX/st.cmd
  • 2slit (not 2slit_soft):
dbLoadRecords("$(OPTICS)/opticsApp/Db/2slit.db","P=9idcLAX:,SLIT=GSlit1H:,mXp=mxv:c0:m3,mXn=mxv:c0:m4")
dbLoadRecords("$(OPTICS)/opticsApp/Db/2slit.db","P=9idcLAX:,SLIT=GSlit1V:,mXp=mxv:c0:m5,mXn=mxv:c0:m6")
  • SUPPORT=/APSshare/epics/synApps_5_7/support
  • EPICS_BASE=/APSshare/epics/base-3.14.12.3
  • OPTICS=$(SUPPORT)/optics-2-9-1
  • 2slit.db

@prjemian
Copy link
Contributor Author

The softIOC is not ready for testing now due to IT maintenance. The complete IOC software stack must be rebuilt after the workstation has moved to a new subnet.

@kmpeters
Copy link

What are the symptoms that tell you the complete IOC software stack must be rebuilt?

@prjemian
Copy link
Contributor Author

prjemian commented Sep 18, 2019 via email

@prjemian
Copy link
Contributor Author

Restarting this:

  • EPICS R7.0.4
  • synApps 6.1 (all modules from github master branch when possible)

@prjemian
Copy link
Contributor Author

(base) prjemian@poof ~/.../ioclax/softioc $ caget lax:Slit1{H,V}{size,center,x{n,p}} 
lax:Slit1Hsize                 0
lax:Slit1Hcenter               0
lax:Slit1Hxn                   0
lax:Slit1Hxp                   0
lax:Slit1Vsize                 0
lax:Slit1Vcenter               0
lax:Slit1Vxn                   0
lax:Slit1Vxp                   0

@prjemian
Copy link
Contributor Author

stopping the current retest, since the motor stuck problem is not found with this configuration

@prjemian
Copy link
Contributor Author

prjemian commented Aug 23, 2020

For the record, started scanning again with a revised algorithm to prune old data from the plots. The new algorithm is working but needs more testing. No observations of the original problem (motor stuck in moving state).

Still, the retest here stopped (during iteration 129) with the same timeout error when trying to read scaler0 channel 4, as shown. That is disturbing since it has happened twice in the same way (see previous) and it interrupts our testing of the original problem.

console output from just before error through to command line prompt
I Sun-06:15:30 - guard_slit_top: scan from 0.1 to -0.4
Transient Scan ID: 2479     Time: 2020-08-23 06:15:44
Persistent Unique Scan ID: '65dd2420-e345-426b-bfb0-50f3563f991c'
New stream: 'primary'                                                                                                                                                                          
+-----------+------------+----------------+------------+
|   seq_num |       time | guard_slit_top |       upd2 |
+-----------+------------+----------------+------------+
|         1 | 06:15:47.2 |        0.10000 |          1 |
|         2 | 06:15:48.6 |        0.09000 |          1 |                                                                                                                                       
|         3 | 06:15:51.3 |        0.08000 |          2 |                                                                                                                                       
|         4 | 06:15:53.9 |        0.08000 |          1 |                                                                                                                                       
|         5 | 06:15:57.8 |        0.07000 |          2 |                                                                                                                                       
|         6 | 06:16:01.4 |        0.06000 |          1 |                                                                                                                                       
|         7 | 06:16:05.0 |        0.05000 |          2 |                                                                                                                                       
|         8 | 06:16:08.7 |        0.04000 |          2 |                                                                                                                                       
|         9 | 06:16:13.4 |        0.03000 |          1 |                                                                                                                                       
|        10 | 06:16:17.5 |        0.03000 |          2 |                                                                                                                                       
|        11 | 06:16:21.5 |        0.02000 |          2 |                                                                                                                                       
|        12 | 06:16:24.8 |        0.01000 |          3 |                                                                                                                                       
|        13 | 06:16:28.4 |        0.00000 |          1 |                                                                                                                                       
|        14 | 06:16:32.0 |       -0.01000 |          2 |                                                                                                                                       
|        15 | 06:16:36.1 |       -0.02000 |          1 |                                                                                                                                       
|        16 | 06:16:39.8 |       -0.02000 |          2 |                                                                                                                                       
|        17 | 06:16:43.7 |       -0.03000 |          1 |                                                                                                                                       
|        18 | 06:16:47.3 |       -0.04000 |          1 |                                                                                                                                       
|        19 | 06:16:50.2 |       -0.05000 |          2 |                                                                                                                                       
|        20 | 06:16:54.2 |       -0.06000 |          2 |                                                                                                                                       
|        21 | 06:16:58.3 |       -0.07000 |          2 |                                                                                                                                       
|        22 | 06:17:01.9 |       -0.07000 |          1 |                                                                                                                                       
|        23 | 06:17:06.0 |       -0.08000 |          1 |                                                                                                                                       
|        24 | 06:17:10.1 |       -0.09000 |          2 |                                                                                                                                       
|        25 | 06:17:13.2 |       -0.10000 |          1 |                                                                                                                                       
|        26 | 06:17:16.5 |       -0.11000 |          1 |                                                                                                                                       
|        27 | 06:17:20.8 |       -0.12000 |          2 |                                                                                                                                       
|        28 | 06:17:24.4 |       -0.12000 |          1 |                                                                                                                                       
                                                                                                                                                                                               
/home/prjemian/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/epics/ca.py:1524: UserWarning: ca.get('lax:scaler1.S4') timed out after 2.00 seconds.
  warnings.warn(msg % (name(chid), timeout))
Run aborted
Traceback (most recent call last):
  File "/home/prjemian/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/run_engine.py", line 1365, in _run
    msg = self._plan_stack[-1].send(resp)
  File "/home/prjemian/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py", line 1307, in __call__
    return (yield from plan)
  File "/home/prjemian/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py", line 1160, in baseline_wrapper
    return (yield from plan)
  File "/home/prjemian/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py", line 803, in monitor_during_wrapper
    return (yield from plan2)
  File "/home/prjemian/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py", line 170, in plan_mutator
    raise ex
  File "/home/prjemian/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py", line 123, in plan_mutator
    msg = plan_stack[-1].send(ret)
  File "/home/prjemian/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py", line 170, in plan_mutator
    raise ex
  File "/home/prjemian/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py", line 123, in plan_mutator
    msg = plan_stack[-1].send(ret)
  File "/home/prjemian/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py", line 861, in fly_during_wrapper
    return (yield from plan2)
  File "/home/prjemian/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py", line 170, in plan_mutator
    raise ex
  File "/home/prjemian/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py", line 123, in plan_mutator
    msg = plan_stack[-1].send(ret)
  File "/home/prjemian/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py", line 170, in plan_mutator
    raise ex
  File "/home/prjemian/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py", line 123, in plan_mutator
    msg = plan_stack[-1].send(ret)
  File "/home/prjemian/Documents/projects/instrument_poof/instrument/usaxs/issues.py", line 79, in issue253
    yield from bps.repeat(_full_guard_slits_tune_, num=times)
  File "/home/prjemian/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/plan_stubs.py", line 1185, in repeat
    return (yield from repeated_plan())
  File "/home/prjemian/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/plan_stubs.py", line 1168, in repeated_plan
    yield from ensure_generator(plan())
  File "/home/prjemian/Documents/projects/instrument_poof/instrument/usaxs/issues.py", line 70, in _full_guard_slits_tune_
    yield from tune_Gslits(md=_md)
  File "/home/prjemian/Documents/projects/instrument_poof/instrument/usaxs/tune_guard_slits.py", line 404, in tune_Gslits
    yield from tune_GslitsSize(md=_md)
  File "/home/prjemian/Documents/projects/instrument_poof/instrument/usaxs/tune_guard_slits.py", line 385, in tune_GslitsSize
    yield from _USAXS_tune_guardSlits()
  File "/home/prjemian/Documents/projects/instrument_poof/instrument/usaxs/tune_guard_slits.py", line 268, in _USAXS_tune_guardSlits
    yield from tune_blade_edge(
  File "/home/prjemian/Documents/projects/instrument_poof/instrument/usaxs/tune_guard_slits.py", line 226, in tune_blade_edge
    yield from tuner.tune(width=scan_width, num=steps+1)
  File "/home/prjemian/Documents/projects/apstools/apstools/plans.py", line 1148, in tune
    return (yield from _scan(md=_md))
  File "/home/prjemian/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/utils.py", line 1066, in dec_inner
    return (yield from plan)
  File "/home/prjemian/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py", line 382, in subs_wrapper
    return (yield from finalize_wrapper(_inner_plan(),
  File "/home/prjemian/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py", line 509, in finalize_wrapper
    ret = yield from plan
  File "/home/prjemian/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py", line 380, in _inner_plan
    return (yield from plan)
  File "/home/prjemian/Documents/projects/apstools/apstools/plans.py", line 1107, in _scan
    yield from bps.trigger_and_read(signal_list)
  File "/home/prjemian/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/plan_stubs.py", line 913, in trigger_and_read
    return (yield from rewindable_wrapper(inner_trigger_and_read(),
  File "/home/prjemian/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py", line 693, in rewindable_wrapper
    return (yield from plan)
  File "/home/prjemian/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/plan_stubs.py", line 907, in inner_trigger_and_read
    reading = (yield from read(obj))
  File "/home/prjemian/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/plan_stubs.py", line 95, in read
    return (yield Msg('read', obj))
  File "/home/prjemian/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py", line 195, in plan_mutator
    inner_ret = yield msg
  File "/home/prjemian/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py", line 195, in plan_mutator
    inner_ret = yield msg
  File "/home/prjemian/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py", line 195, in plan_mutator
    inner_ret = yield msg
  [Previous line repeated 1 more time]
  File "/home/prjemian/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/run_engine.py", line 1425, in _run
    new_response = await coro(msg)
  File "/home/prjemian/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/run_engine.py", line 1670, in _read
    ret = obj.read(*msg.args, **msg.kwargs)
  File "/home/prjemian/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/ophyd/device.py", line 1237, in read
    res.update(component.read())
  File "/home/prjemian/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/ophyd/device.py", line 1237, in read
    res.update(component.read())
  File "/home/prjemian/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/ophyd/device.py", line 1237, in read
    res.update(component.read())
  File "/home/prjemian/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/ophyd/utils/epics_pvs.py", line 198, in wrapper
    return fcn(self, *args, **kwargs)
  File "/home/prjemian/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/ophyd/signal.py", line 366, in read
    value = self.get()
  File "/home/prjemian/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/ophyd/signal.py", line 1095, in get
    info = self._get_with_timeout(
  File "/home/prjemian/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/ophyd/signal.py", line 1058, in _get_with_timeout
    raise ReadTimeoutError(
+-----------+------------+----------------+------------+1.S4 within 2.0 sec
generator TuneAxis.tune ['65dd2420'] (scan num: 2479)
---------------------------------------------------------------------------
ReadTimeoutError                          Traceback (most recent call last)
<ipython-input-2-af66e7d151cc> in <module>
----> 1 uids = RE(issue253(1000))

~/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/run_engine.py in __call__(self, *args, **metadata_kw)
    805             self._task_fut.add_done_callback(set_blocking_event)
    806 
--> 807         self._resume_task(init_func=_build_task)
    808 
    809         if self._interrupted:

~/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/run_engine.py in _resume_task(self, init_func)
    929                     if (exc is not None
    930                             and not isinstance(exc, _RunEnginePanic)):
--> 931                         raise exc
    932 
    933     def install_suspender(self, suspender):

~/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/run_engine.py in _run(self)
   1498             exit_reason = str(err)
   1499             self.log.exception("Run aborted")
-> 1500             raise err
   1501         finally:
   1502             if not exit_reason:

~/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/run_engine.py in _run(self)
   1363                     else:
   1364                         try:
-> 1365                             msg = self._plan_stack[-1].send(resp)
   1366                         # We have exhausted the top generator
   1367                         except StopIteration:

~/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py in __call__(self, plan)
   1305         plan = monitor_during_wrapper(plan, self.monitors)
   1306         plan = baseline_wrapper(plan, self.baseline)
-> 1307         return (yield from plan)
   1308 
   1309 

~/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py in baseline_wrapper(plan, devices, name)
   1158     if not devices:
   1159         # no-op
-> 1160         return (yield from plan)
   1161     else:
   1162         return (yield from plan_mutator(plan, insert_baseline))

~/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py in monitor_during_wrapper(plan, signals)
    801     plan1 = plan_mutator(plan, insert_after_open)
    802     plan2 = plan_mutator(plan1, insert_before_close)
--> 803     return (yield from plan2)
    804 
    805 

~/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py in plan_mutator(plan, msg_proc)
    168                     continue
    169                 else:
--> 170                     raise ex
    171         # if inserting / mutating, put new generator on the stack
    172         # and replace the current msg with the first element from the

~/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py in plan_mutator(plan, msg_proc)
    121             ret = result_stack.pop()
    122             try:
--> 123                 msg = plan_stack[-1].send(ret)
    124             except StopIteration as e:
    125                 # discard the exhausted generator

~/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py in plan_mutator(plan, msg_proc)
    168                     continue
    169                 else:
--> 170                     raise ex
    171         # if inserting / mutating, put new generator on the stack
    172         # and replace the current msg with the first element from the

~/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py in plan_mutator(plan, msg_proc)
    121             ret = result_stack.pop()
    122             try:
--> 123                 msg = plan_stack[-1].send(ret)
    124             except StopIteration as e:
    125                 # discard the exhausted generator

~/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py in fly_during_wrapper(plan, flyers)
    859     plan1 = plan_mutator(plan, insert_after_open)
    860     plan2 = plan_mutator(plan1, insert_before_close)
--> 861     return (yield from plan2)
    862 
    863 

~/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py in plan_mutator(plan, msg_proc)
    168                     continue
    169                 else:
--> 170                     raise ex
    171         # if inserting / mutating, put new generator on the stack
    172         # and replace the current msg with the first element from the

~/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py in plan_mutator(plan, msg_proc)
    121             ret = result_stack.pop()
    122             try:
--> 123                 msg = plan_stack[-1].send(ret)
    124             except StopIteration as e:
    125                 # discard the exhausted generator

~/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py in plan_mutator(plan, msg_proc)
    168                     continue
    169                 else:
--> 170                     raise ex
    171         # if inserting / mutating, put new generator on the stack
    172         # and replace the current msg with the first element from the

~/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py in plan_mutator(plan, msg_proc)
    121             ret = result_stack.pop()
    122             try:
--> 123                 msg = plan_stack[-1].send(ret)
    124             except StopIteration as e:
    125                 # discard the exhausted generator

~/Documents/projects/instrument_poof/instrument/usaxs/issues.py in issue253(times)
     77     _tune_number = 0
     78     _total_tunes = times
---> 79     yield from bps.repeat(_full_guard_slits_tune_, num=times)

~/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/plan_stubs.py in repeat(plan, num, delay)
   1183                     yield Msg('sleep', None, d)
   1184 
-> 1185     return (yield from repeated_plan())

~/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/plan_stubs.py in repeated_plan()
   1166             now = time.time()  # Intercept the flow in its earliest moment.
   1167             yield Msg('checkpoint')
-> 1168             yield from ensure_generator(plan())
   1169             try:
   1170                 d = next(delay)

~/Documents/projects/instrument_poof/instrument/usaxs/issues.py in _full_guard_slits_tune_()
     68     )
     69     logger.info("# tune number: %d", _tune_number)
---> 70     yield from tune_Gslits(md=_md)
     71     trim_all()
     72 

~/Documents/projects/instrument_poof/instrument/usaxs/tune_guard_slits.py in tune_Gslits(md)
    402     _md.update(md or {})
    403     yield from tune_GslitsCenter(md=_md)
--> 404     yield from tune_GslitsSize(md=_md)

~/Documents/projects/instrument_poof/instrument/usaxs/tune_guard_slits.py in tune_GslitsSize(md)
    383     # yield from autoscale_amplifiers([upd_controls, I0_controls, I00_controls])
    384     try:
--> 385         yield from _USAXS_tune_guardSlits()
    386         yield from bps.mv(
    387             # ti_filter_shutter, "close",

~/Documents/projects/instrument_poof/instrument/usaxs/tune_guard_slits.py in _USAXS_tune_guardSlits(md)
    266     logger.info("*** 1. tune top guard slits")
    267     try:
--> 268         yield from tune_blade_edge(
    269             guard_slit.top,
    270             original_position["top"] + guard_slit.v_step_away,

~/Documents/projects/instrument_poof/instrument/usaxs/tune_guard_slits.py in tune_blade_edge(axis, start, end, steps, ct_time, results)
    224 
    225         tuner = TuneAxis([scaler0], axis, signal_name=UPD_SIGNAL.chname.get())
--> 226         yield from tuner.tune(width=scan_width, num=steps+1)
    227 
    228         diff = abs(tuner.peaks.y_data[0] - tuner.peaks.y_data[-1])

~/Documents/projects/apstools/apstools/plans.py in tune(self, width, num, peak_factor, md)
   1146             results.report(stream_name)
   1147 
-> 1148         return (yield from _scan(md=_md))
   1149 
   1150 

~/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/utils.py in dec_inner(*inner_args, **inner_kwargs)
   1064                 plan = gen_func(*inner_args, **inner_kwargs)
   1065                 plan = wrapper(plan, *args, **kwargs)
-> 1066                 return (yield from plan)
   1067             return dec_inner
   1068         return dec

~/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py in subs_wrapper(plan, subs)
    380         return (yield from plan)
    381 
--> 382     return (yield from finalize_wrapper(_inner_plan(),
    383                                         _unsubscribe()))
    384 

~/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py in finalize_wrapper(plan, final_plan, pause_for_debug)
    507     cleanup = True
    508     try:
--> 509         ret = yield from plan
    510     except GeneratorExit:
    511         cleanup = False

~/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py in _inner_plan()
    378     def _inner_plan():
    379         yield from _subscribe()
--> 380         return (yield from plan)
    381 
    382     return (yield from finalize_wrapper(_inner_plan(),

~/Documents/projects/apstools/apstools/plans.py in _scan(md)
   1105             for pos in position_list:
   1106                 yield from bps.mv(self.axis, pos)
-> 1107                 yield from bps.trigger_and_read(signal_list)
   1108 
   1109             final_position = initial_position

~/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/plan_stubs.py in trigger_and_read(devices, name)
    911         return ret
    912     from .preprocessors import rewindable_wrapper
--> 913     return (yield from rewindable_wrapper(inner_trigger_and_read(),
    914                                           rewindable))
    915 

~/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py in rewindable_wrapper(plan, rewindable)
    691                                             restore_rewindable()))
    692     else:
--> 693         return (yield from plan)
    694 
    695 

~/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/plan_stubs.py in inner_trigger_and_read()
    905         ret = {}  # collect and return readings to give plan access to them
    906         for obj in devices:
--> 907             reading = (yield from read(obj))
    908             if reading is not None:
    909                 ret.update(reading)

~/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/plan_stubs.py in read(obj)
     93         Msg('read', obj)
     94     """
---> 95     return (yield Msg('read', obj))
     96 
     97 

~/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py in plan_mutator(plan, msg_proc)
    193         try:
    194             # yield out the 'current message' and collect the return
--> 195             inner_ret = yield msg
    196         except GeneratorExit:
    197             # special case GeneratorExit.  We must clean up all of our plans

~/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py in plan_mutator(plan, msg_proc)
    193         try:
    194             # yield out the 'current message' and collect the return
--> 195             inner_ret = yield msg
    196         except GeneratorExit:
    197             # special case GeneratorExit.  We must clean up all of our plans

~/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py in plan_mutator(plan, msg_proc)
    193         try:
    194             # yield out the 'current message' and collect the return
--> 195             inner_ret = yield msg
    196         except GeneratorExit:
    197             # special case GeneratorExit.  We must clean up all of our plans

~/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py in plan_mutator(plan, msg_proc)
    193         try:
    194             # yield out the 'current message' and collect the return
--> 195             inner_ret = yield msg
    196         except GeneratorExit:
    197             # special case GeneratorExit.  We must clean up all of our plans

~/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/run_engine.py in _run(self)
   1423                         # exceptions (coming in via throw) can be
   1424                         # raised
-> 1425                         new_response = await coro(msg)
   1426 
   1427                     # special case `CancelledError` and let the outer

~/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/run_engine.py in _read(self, msg)
   1668         obj = msg.obj
   1669         # actually _read_ the object
-> 1670         ret = obj.read(*msg.args, **msg.kwargs)
   1671 
   1672         if ret is None:

~/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/ophyd/device.py in read(self)
   1235 
   1236         for _, component in self._get_components_of_kind(Kind.normal):
-> 1237             res.update(component.read())
   1238         return res
   1239 

~/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/ophyd/device.py in read(self)
   1235 
   1236         for _, component in self._get_components_of_kind(Kind.normal):
-> 1237             res.update(component.read())
   1238         return res
   1239 

~/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/ophyd/device.py in read(self)
   1235 
   1236         for _, component in self._get_components_of_kind(Kind.normal):
-> 1237             res.update(component.read())
   1238         return res
   1239 

~/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/ophyd/utils/epics_pvs.py in wrapper(self, *args, **kwargs)
    196     def wrapper(self, *args, **kwargs):
    197         if self.connected:
--> 198             return fcn(self, *args, **kwargs)
    199         else:
    200             raise DisconnectedError('{} is not connected'.format(self.name))

~/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/ophyd/signal.py in read(self)
    364             dict
    365         '''
--> 366         value = self.get()
    367         return {self.name: {'value': value,
    368                             'timestamp': self.timestamp}}

~/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/ophyd/signal.py in get(self, as_string, timeout, connection_timeout, form, **kwargs)
   1093             as_string = self._string
   1094 
-> 1095         info = self._get_with_timeout(
   1096             self._read_pv, timeout, connection_timeout, as_string, form)
   1097 

~/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/ophyd/signal.py in _get_with_timeout(self, pv, timeout, connection_timeout, as_string, form)
   1056 
   1057         if info is None:
-> 1058             raise ReadTimeoutError(
   1059                 f"Failed to read {pv.pvname} "
   1060                 f"within {timeout:.2} sec")

ReadTimeoutError: Failed to read lax:scaler1.S4 within 2.0 sec

In [3]: !code ~/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/ophyd/signal.py                                                                                                  

In [4]:                                                                                                                                                                                        

It's not obvious why a timeout of 2.0 is used since the session is setup with a default timeout of 10 s:

# set default timeout for all EpicsSignal connections & communications
import ophyd
ophyd.EpicsSignal.set_default_timeout(timeout=10, connection_timeout=5)

Will it help to run this with a source code debugger?

@prjemian
Copy link
Contributor Author

prjemian commented Aug 23, 2020

note:

  • there are six tune runs per iteration
  • it appears that scanning slows down as iterations continue
  • at time of failure, each iteration took about 21 minutes
  • earlier, each iteration took about 3 minutes

most recent

In [4]: listruns()                                                                                                                                                                             
========= ========================== ======= ======= ===============
short_uid date/time                  exit    scan_id command        
========= ========================== ======= ======= ===============
65dd242   2020-08-23 06:15:44.417392 fail    2479    TuneAxis.tune()
7f4700a   2020-08-23 06:13:45.642347 success 2478    TuneAxis.tune()
7206a3d   2020-08-23 06:10:29.685131 success 2477    TuneAxis.tune()
ab04155   2020-08-23 06:06:38.189935 success 2476    TuneAxis.tune()
1ea8cb6   2020-08-23 06:02:34.551020 success 2475    TuneAxis.tune()
3b9feca   2020-08-23 05:58:53.458207 success 2474    TuneAxis.tune()
ab5cd73   2020-08-23 05:54:45.410560 success 2473    TuneAxis.tune()
911c29b   2020-08-23 05:52:51.053878 success 2472    TuneAxis.tune()
b11e0bd   2020-08-23 05:49:34.790318 success 2471    TuneAxis.tune()
a1a2390   2020-08-23 05:45:49.648252 success 2470    TuneAxis.tune()
1265bda   2020-08-23 05:41:50.911482 success 2469    TuneAxis.tune()
a300f19   2020-08-23 05:38:14.831474 success 2468    TuneAxis.tune()
cc62439   2020-08-23 05:34:42.922256 success 2467    TuneAxis.tune()
ac3ee28   2020-08-23 05:32:44.164961 success 2466    TuneAxis.tune()
d81e702   2020-08-23 05:29:27.946097 success 2465    TuneAxis.tune()
0889aae   2020-08-23 05:25:27.914168 success 2464    TuneAxis.tune()
b8ea250   2020-08-23 05:21:46.173780 success 2463    TuneAxis.tune()
330d983   2020-08-23 05:17:47.310145 success 2462    TuneAxis.tune()
8e551f6   2020-08-23 05:14:02.351603 success 2461    TuneAxis.tune()
3c30115   2020-08-23 05:12:15.506111 success 2460    TuneAxis.tune()
========= ========================== ======= ======= ===============

earlier

In [10]: listruns(since="2020-08-22 18:00", until="2020-08-22 20:00", num=500)                                                                                                                 
========= ========================== ======= ======= ===============
short_uid date/time                  exit    scan_id command        
========= ========================== ======= ======= ===============
bc41f27   2020-08-22 19:59:26.340894 success 1923    TuneAxis.tune()
1a3a2d3   2020-08-22 19:58:53.600618 success 1922    TuneAxis.tune()
19a8e8d   2020-08-22 19:58:20.561002 success 1921    TuneAxis.tune()
fc00c84   2020-08-22 19:57:53.047963 success 1920    TuneAxis.tune()
1e0e812   2020-08-22 19:57:24.238159 success 1919    TuneAxis.tune()
987a139   2020-08-22 19:56:44.182615 success 1918    TuneAxis.tune()
a12b1ca   2020-08-22 19:56:02.041611 success 1917    TuneAxis.tune()
6152143   2020-08-22 19:55:28.115208 success 1916    TuneAxis.tune()
3c499be   2020-08-22 19:54:54.482183 success 1915    TuneAxis.tune()
c2831b3   2020-08-22 19:54:27.667671 success 1914    TuneAxis.tune()
f5508a2   2020-08-22 19:53:57.840107 success 1913    TuneAxis.tune()
6d89216   2020-08-22 19:53:17.999206 success 1912    TuneAxis.tune()
79ff6ec   2020-08-22 19:52:35.957178 success 1911    TuneAxis.tune()
f01e0b1   2020-08-22 19:52:01.717868 success 1910    TuneAxis.tune()
d7c5a2c   2020-08-22 19:51:28.089083 success 1909    TuneAxis.tune()
1b1c0c7   2020-08-22 19:51:01.066627 success 1908    TuneAxis.tune()
6b84591   2020-08-22 19:50:30.542737 success 1907    TuneAxis.tune()
c099e9d   2020-08-22 19:49:50.306522 success 1906    TuneAxis.tune()
c152c42   2020-08-22 19:49:10.051640 success 1905    TuneAxis.tune()
08d9281   2020-08-22 19:48:33.941363 success 1904    TuneAxis.tune()
9da2777   2020-08-22 19:47:59.904498 success 1903    TuneAxis.tune()
260bd86   2020-08-22 19:47:33.370215 success 1902    TuneAxis.tune()
927fb06   2020-08-22 19:47:02.466176 success 1901    TuneAxis.tune()
84dc3bf   2020-08-22 19:46:22.212566 success 1900    TuneAxis.tune()
669cf83   2020-08-22 19:45:42.070315 success 1899    TuneAxis.tune()
5e512ad   2020-08-22 19:45:05.430382 success 1898    TuneAxis.tune()
5fa44b7   2020-08-22 19:44:31.403128 success 1897    TuneAxis.tune()
55c12e3   2020-08-22 19:44:05.079829 success 1896    TuneAxis.tune()
4d95315   2020-08-22 19:43:35.095725 success 1895    TuneAxis.tune()
fd33ccc   2020-08-22 19:42:54.913613 success 1894    TuneAxis.tune()
9ba6b2e   2020-08-22 19:42:14.481993 success 1893    TuneAxis.tune()
59e8c5a   2020-08-22 19:41:39.351986 success 1892    TuneAxis.tune()
734a372   2020-08-22 19:41:05.611772 success 1891    TuneAxis.tune()
0bf240a   2020-08-22 19:40:39.076774 success 1890    TuneAxis.tune()
ec848db   2020-08-22 19:40:09.106630 success 1889    TuneAxis.tune()
1e56f8c   2020-08-22 19:39:29.014258 success 1888    TuneAxis.tune()
bf6b8c6   2020-08-22 19:38:48.974646 success 1887    TuneAxis.tune()
ea4a7bf   2020-08-22 19:38:12.557459 success 1886    TuneAxis.tune()
73938ff   2020-08-22 19:37:37.219563 success 1885    TuneAxis.tune()
e0248df   2020-08-22 19:37:10.783193 success 1884    TuneAxis.tune()
b160e1d   2020-08-22 19:36:41.286328 success 1883    TuneAxis.tune()
29be6dd   2020-08-22 19:36:00.834770 success 1882    TuneAxis.tune()
aa6563f   2020-08-22 19:35:20.788660 success 1881    TuneAxis.tune()
e2f2c0f   2020-08-22 19:34:46.983395 success 1880    TuneAxis.tune()
b03ff8a   2020-08-22 19:34:10.017945 success 1879    TuneAxis.tune()
797159f   2020-08-22 19:33:43.604387 success 1878    TuneAxis.tune()
501f13e   2020-08-22 19:33:14.511510 success 1877    TuneAxis.tune()
0a09a56   2020-08-22 19:32:33.040468 success 1876    TuneAxis.tune()
e30c1bf   2020-08-22 19:31:52.902894 success 1875    TuneAxis.tune()
4aff105   2020-08-22 19:31:20.197561 success 1874    TuneAxis.tune()
c9bcfde   2020-08-22 19:30:41.433476 success 1873    TuneAxis.tune()
fabb059   2020-08-22 19:30:15.051185 success 1872    TuneAxis.tune()
02c5482   2020-08-22 19:29:46.398567 success 1871    TuneAxis.tune()
698b8ff   2020-08-22 19:29:04.651639 success 1870    TuneAxis.tune()
342c083   2020-08-22 19:28:24.404177 success 1869    TuneAxis.tune()
b500528   2020-08-22 19:27:51.482131 success 1868    TuneAxis.tune()
adc3e5f   2020-08-22 19:27:14.250870 success 1867    TuneAxis.tune()
fbd14be   2020-08-22 19:26:47.826565 success 1866    TuneAxis.tune()
7d0f09e   2020-08-22 19:26:18.992546 success 1865    TuneAxis.tune()
3931bea   2020-08-22 19:25:37.652217 success 1864    TuneAxis.tune()
9dae9fa   2020-08-22 19:24:57.616014 success 1863    TuneAxis.tune()
41ce468   2020-08-22 19:24:24.294093 success 1862    TuneAxis.tune()
f49ffe2   2020-08-22 19:23:48.449647 success 1861    TuneAxis.tune()
05f8dc2   2020-08-22 19:23:22.288676 success 1860    TuneAxis.tune()
0bee79c   2020-08-22 19:22:53.310264 success 1859    TuneAxis.tune()
8f05bdf   2020-08-22 19:22:13.562330 success 1858    TuneAxis.tune()
a32ec36   2020-08-22 19:21:32.415835 success 1857    TuneAxis.tune()
ca6f4d2   2020-08-22 19:20:59.788248 success 1856    TuneAxis.tune()
8952fda   2020-08-22 19:20:23.949795 success 1855    TuneAxis.tune()
1160fef   2020-08-22 19:19:57.933315 success 1854    TuneAxis.tune()
bd9476d   2020-08-22 19:19:28.809943 success 1853    TuneAxis.tune()
1c5cadd   2020-08-22 19:18:48.969631 success 1852    TuneAxis.tune()
6a6d3b6   2020-08-22 19:18:08.026241 success 1851    TuneAxis.tune()
42c6bb1   2020-08-22 19:17:34.982029 success 1850    TuneAxis.tune()
ce9d9bf   2020-08-22 19:16:58.460557 success 1849    TuneAxis.tune()
6d73ba5   2020-08-22 19:16:32.327246 success 1848    TuneAxis.tune()
029f3e1   2020-08-22 19:16:03.122649 success 1847    TuneAxis.tune()
e76105b   2020-08-22 19:15:21.852593 success 1846    TuneAxis.tune()
5694ff7   2020-08-22 19:14:41.615742 success 1845    TuneAxis.tune()
aa90705   2020-08-22 19:14:08.787225 success 1844    TuneAxis.tune()
432e5bc   2020-08-22 19:13:31.945860 success 1843    TuneAxis.tune()
4cec4fc   2020-08-22 19:13:05.312943 success 1842    TuneAxis.tune()
da9d254   2020-08-22 19:12:36.090077 success 1841    TuneAxis.tune()
3f963fb   2020-08-22 19:11:54.847178 success 1840    TuneAxis.tune()
5c86c8d   2020-08-22 19:11:14.616338 success 1839    TuneAxis.tune()
2153ed2   2020-08-22 19:10:41.787963 success 1838    TuneAxis.tune()
dc23dbb   2020-08-22 19:10:06.056757 success 1837    TuneAxis.tune()
811b7a0   2020-08-22 19:09:39.325369 success 1836    TuneAxis.tune()
2e15c84   2020-08-22 19:09:09.881455 success 1835    TuneAxis.tune()
08cb816   2020-08-22 19:08:29.459605 success 1834    TuneAxis.tune()
c8966e3   2020-08-22 19:07:48.815225 success 1833    TuneAxis.tune()
2ad607b   2020-08-22 19:07:15.796478 success 1832    TuneAxis.tune()
8d88576   2020-08-22 19:06:40.346429 success 1831    TuneAxis.tune()
dbbc42e   2020-08-22 19:06:14.127852 success 1830    TuneAxis.tune()
c47e7a5   2020-08-22 19:05:44.591928 success 1829    TuneAxis.tune()
dee15e7   2020-08-22 19:05:05.076282 success 1828    TuneAxis.tune()
fd7931f   2020-08-22 19:04:23.948315 success 1827    TuneAxis.tune()
5c7b86a   2020-08-22 19:03:50.697412 success 1826    TuneAxis.tune()
2e2a439   2020-08-22 19:03:16.767783 success 1825    TuneAxis.tune()
a8bb4b8   2020-08-22 19:02:49.632076 success 1824    TuneAxis.tune()
95b7e13   2020-08-22 19:02:19.716359 success 1823    TuneAxis.tune()
09d935a   2020-08-22 19:01:39.856899 success 1822    TuneAxis.tune()
4217c6a   2020-08-22 19:00:58.440878 success 1821    TuneAxis.tune()
6e82960   2020-08-22 19:00:25.085742 success 1820    TuneAxis.tune()
77610dc   2020-08-22 18:59:50.863639 success 1819    TuneAxis.tune()
feb69de   2020-08-22 18:59:24.139254 success 1818    TuneAxis.tune()
49e0e1c   2020-08-22 18:58:54.890481 success 1817    TuneAxis.tune()
849fc6c   2020-08-22 18:58:15.280392 success 1816    TuneAxis.tune()
20998f7   2020-08-22 18:57:34.032713 success 1815    TuneAxis.tune()
1ed35f3   2020-08-22 18:57:00.812285 success 1814    TuneAxis.tune()
2a9e0dc   2020-08-22 18:56:26.873003 success 1813    TuneAxis.tune()
2a8cc55   2020-08-22 18:55:58.653617 success 1812    TuneAxis.tune()
fc3759e   2020-08-22 18:55:28.627084 success 1811    TuneAxis.tune()
716b302   2020-08-22 18:54:48.771447 success 1810    TuneAxis.tune()
9909cb8   2020-08-22 18:54:07.350098 success 1809    TuneAxis.tune()
f882015   2020-08-22 18:53:33.907388 success 1808    TuneAxis.tune()
634cd5f   2020-08-22 18:53:00.478356 success 1807    TuneAxis.tune()
857695d   2020-08-22 18:52:33.477225 success 1806    TuneAxis.tune()
902fea8   2020-08-22 18:52:04.721049 success 1805    TuneAxis.tune()
6810153   2020-08-22 18:51:24.968403 success 1804    TuneAxis.tune()
2fa9e37   2020-08-22 18:50:43.537810 success 1803    TuneAxis.tune()
eacf238   2020-08-22 18:50:09.996134 success 1802    TuneAxis.tune()
d312000   2020-08-22 18:49:35.878396 success 1801    TuneAxis.tune()
8a2a54e   2020-08-22 18:49:08.548775 success 1800    TuneAxis.tune()
c3dedc0   2020-08-22 18:48:39.045874 success 1799    TuneAxis.tune()
34740df   2020-08-22 18:47:59.180326 success 1798    TuneAxis.tune()
5f2df77   2020-08-22 18:47:17.839717 success 1797    TuneAxis.tune()
4d2acf3   2020-08-22 18:46:44.406358 success 1796    TuneAxis.tune()
7b32448   2020-08-22 18:46:10.663334 success 1795    TuneAxis.tune()
fa1df42   2020-08-22 18:45:43.438117 success 1794    TuneAxis.tune()
9d79115   2020-08-22 18:45:13.933571 success 1793    TuneAxis.tune()
c51d407   2020-08-22 18:44:34.369030 success 1792    TuneAxis.tune()
617e13f   2020-08-22 18:43:52.640879 success 1791    TuneAxis.tune()
3eb19e7   2020-08-22 18:43:18.903098 success 1790    TuneAxis.tune()
3c99070   2020-08-22 18:42:44.683732 success 1789    TuneAxis.tune()
cb11c4d   2020-08-22 18:42:17.437566 success 1788    TuneAxis.tune()
b3fd8c2   2020-08-22 18:41:48.304822 success 1787    TuneAxis.tune()
405e986   2020-08-22 18:41:08.362134 success 1786    TuneAxis.tune()
b580fde   2020-08-22 18:40:27.420173 success 1785    TuneAxis.tune()
0a3a64c   2020-08-22 18:39:54.484952 success 1784    TuneAxis.tune()
70655ae   2020-08-22 18:39:18.656368 success 1783    TuneAxis.tune()
7242c59   2020-08-22 18:38:52.430363 success 1782    TuneAxis.tune()
4f80dc8   2020-08-22 18:38:22.818099 success 1781    TuneAxis.tune()
7e65a2c   2020-08-22 18:37:42.461271 success 1780    TuneAxis.tune()
fd4a073   2020-08-22 18:37:02.524135 success 1779    TuneAxis.tune()
69c62a9   2020-08-22 18:36:29.191732 success 1778    TuneAxis.tune()
d8d074d   2020-08-22 18:35:53.257685 success 1777    TuneAxis.tune()
9c3d2f9   2020-08-22 18:35:27.132164 success 1776    TuneAxis.tune()
f158564   2020-08-22 18:34:58.015868 success 1775    TuneAxis.tune()
4523b49   2020-08-22 18:34:18.070080 success 1774    TuneAxis.tune()
4292f75   2020-08-22 18:33:37.624493 success 1773    TuneAxis.tune()
7941552   2020-08-22 18:33:04.593688 success 1772    TuneAxis.tune()
03572c1   2020-08-22 18:32:29.451162 success 1771    TuneAxis.tune()
abef2af   2020-08-22 18:32:03.127695 success 1770    TuneAxis.tune()
bca9f4f   2020-08-22 18:31:34.206118 success 1769    TuneAxis.tune()
4e3be1a   2020-08-22 18:30:53.660782 success 1768    TuneAxis.tune()
6c8e25a   2020-08-22 18:30:13.719976 success 1767    TuneAxis.tune()
ff41e46   2020-08-22 18:29:40.579100 success 1766    TuneAxis.tune()
d1a147b   2020-08-22 18:29:04.447548 success 1765    TuneAxis.tune()
6256336   2020-08-22 18:28:37.616261 success 1764    TuneAxis.tune()
67768e8   2020-08-22 18:28:08.589824 success 1763    TuneAxis.tune()
880be4a   2020-08-22 18:27:27.150211 success 1762    TuneAxis.tune()
5803306   2020-08-22 18:26:47.113241 success 1761    TuneAxis.tune()
a5567f8   2020-08-22 18:26:14.177238 success 1760    TuneAxis.tune()
7ab4da1   2020-08-22 18:25:37.345675 success 1759    TuneAxis.tune()
6f54a1a   2020-08-22 18:25:11.213303 success 1758    TuneAxis.tune()
0864ae0   2020-08-22 18:24:42.174963 success 1757    TuneAxis.tune()
6afa27f   2020-08-22 18:24:00.944685 success 1756    TuneAxis.tune()
101d0a5   2020-08-22 18:23:20.828397 success 1755    TuneAxis.tune()
664bf23   2020-08-22 18:22:47.473417 success 1754    TuneAxis.tune()
3335452   2020-08-22 18:22:09.722365 success 1753    TuneAxis.tune()
1bb164b   2020-08-22 18:21:42.803702 success 1752    TuneAxis.tune()
0793364   2020-08-22 18:21:12.781601 success 1751    TuneAxis.tune()
3724553   2020-08-22 18:20:31.625249 success 1750    TuneAxis.tune()
1700d7d   2020-08-22 18:19:51.697415 success 1749    TuneAxis.tune()
69c99a7   2020-08-22 18:19:17.662637 success 1748    TuneAxis.tune()
c0fa246   2020-08-22 18:18:40.414573 success 1747    TuneAxis.tune()
a99e790   2020-08-22 18:18:14.097231 success 1746    TuneAxis.tune()
3bcb3dd   2020-08-22 18:17:44.866581 success 1745    TuneAxis.tune()
78bc00c   2020-08-22 18:17:04.017954 success 1744    TuneAxis.tune()
0af61ba   2020-08-22 18:16:23.889975 success 1743    TuneAxis.tune()
996547a   2020-08-22 18:15:48.545574 success 1742    TuneAxis.tune()
c0fd158   2020-08-22 18:15:12.023340 success 1741    TuneAxis.tune()
66fe62d   2020-08-22 18:14:44.485444 success 1740    TuneAxis.tune()
4f8b1f6   2020-08-22 18:14:15.479148 success 1739    TuneAxis.tune()
35a4258   2020-08-22 18:13:35.126355 success 1738    TuneAxis.tune()
009c395   2020-08-22 18:12:55.270653 success 1737    TuneAxis.tune()
f4906ba   2020-08-22 18:12:18.748894 success 1736    TuneAxis.tune()
b08671b   2020-08-22 18:11:44.005082 success 1735    TuneAxis.tune()
44d9477   2020-08-22 18:11:17.782194 success 1734    TuneAxis.tune()
d045c27   2020-08-22 18:10:47.755662 success 1733    TuneAxis.tune()
da6d1a3   2020-08-22 18:10:08.014350 success 1732    TuneAxis.tune()
7828db8   2020-08-22 18:09:27.974815 success 1731    TuneAxis.tune()
f296a44   2020-08-22 18:08:50.737559 success 1730    TuneAxis.tune()
a8175dc   2020-08-22 18:08:16.293891 success 1729    TuneAxis.tune()
1f28676   2020-08-22 18:07:49.931701 success 1728    TuneAxis.tune()
4ba7815   2020-08-22 18:07:20.247881 success 1727    TuneAxis.tune()
c38c790   2020-08-22 18:06:40.596084 success 1726    TuneAxis.tune()
a18a979   2020-08-22 18:06:00.567867 success 1725    TuneAxis.tune()
fad0f5e   2020-08-22 18:05:23.934835 success 1724    TuneAxis.tune()
46972c3   2020-08-22 18:04:49.897088 success 1723    TuneAxis.tune()
5b46a43   2020-08-22 18:04:23.472221 success 1722    TuneAxis.tune()
9011e72   2020-08-22 18:03:53.033297 success 1721    TuneAxis.tune()
452d947   2020-08-22 18:03:13.388930 success 1720    TuneAxis.tune()
4fa951d   2020-08-22 18:02:31.851049 success 1719    TuneAxis.tune()
d6c24c5   2020-08-22 18:01:57.418595 success 1718    TuneAxis.tune()
5eab5cb   2020-08-22 18:01:23.487058 success 1717    TuneAxis.tune()
cb76ba8   2020-08-22 18:00:56.653969 success 1716    TuneAxis.tune()
5b365f5   2020-08-22 18:00:27.192942 success 1715    TuneAxis.tune()
========= ========================== ======= ======= ===============

In this summary plot, the orange points show the time (seconds) for each tune run, the blue points show the time (minutes) for a set of six tune runs (one iteration). The horizontal axis is the iteration counter before the current (so older runs to the left, newer increasing to the right). The start of iterations is on the left.

Clipboard01

Scan times start increasing noticeably about 4.5 hours after start.

script to get start time of each run:

t0 = None
for i, run in enumerate(db[-1000:]):
    t = run.start["time"]
    dt = (t0 or t) - t
    print(f"{i}\t{dt:.2f}")
    t0 = t

Note: the db[-1000:] is very slow to execute (? faster with v2 API ?)

@prjemian
Copy link
Contributor Author

prjemian commented Aug 23, 2020

Another observation:

When exiting the ipython console session after this error, lots of error output on the console.

Suspect this is directly related to the timeout and the increasing scan time. 512 instances of RuntimeError: Expected CA context is unset.

@prjemian
Copy link
Contributor Author

Error comes from PyEpics:

    RuntimeError
        If the expected context (self.context) is unset (None), or the current
        thread cannot get a valid context.  Both conditions would normally
        result in a segmentation fault if left unchecked.
    '''
    @functools.wraps(func)
    def wrapped(self, *args, **kwargs):
        initial_context = ca.current_context()
        expected_context = self.context
        if expected_context is None:
            raise RuntimeError('Expected CA context is unset')
        elif expected_context == initial_context:
            return func(self, *args, **kwargs)```

@prjemian
Copy link
Contributor Author

called from ophyd.signal, this is one of the error reports:

set_and_wait(value=1, timeout=None, atol=None, rtol=None)
Traceback (most recent call last):
  File "/home/prjemian/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/ophyd/signal.py", line 268, in set_thread
    set_and_wait(self, value, timeout=timeout, atol=self.tolerance,
  File "/home/prjemian/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/ophyd/utils/epics_pvs.py", line 263, in set_and_wait
    current_value = signal.get()
  File "/home/prjemian/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/ophyd/signal.py", line 1095, in get
    info = self._get_with_timeout(
  File "/home/prjemian/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/ophyd/signal.py", line 1054, in _get_with_timeout
    info = pv.get_with_metadata(as_string=as_string, form=form, timeout=timeout)
  File "/home/prjemian/Apps/anaconda/envs/bluesky_2020_9/lib/python3.8/site-packages/epics/pv.py", line 46, in wrapped
    raise RuntimeError('Expected CA context is unset')
RuntimeError: Expected CA context is unset

@prjemian
Copy link
Contributor Author

Regarding the slow search as noted above, this is much faster (using the PyMongo API directly) but also might break in future versions of databroker:

def _get_run_starts(db, num=1, query=None):
    _query = query or {}
    mdb = db.v2._metadatastore_db
    collection = db.v2._metadatastore_db["run_start"]
    return collection.find(query).sort("time", -1).limit(num)


import datetime
t0 = None
for i, start in enumerate(_get_run_starts(db, 1000)):
    t = start["time"]
    dt = (t0 or t) - t
    print(f"{i}\t{dt:.2f}\t{datetime.datetime.fromtimestamp(t)}")
    t0 = t

@prjemian
Copy link
Contributor Author

@jilavsky : Can we run this kind of testing on the actual guard slit hardware now?

@jilavsky
Copy link
Contributor

jilavsky commented Sep 3, 2020

Sorry for missing this. We can run real hardware now. It is available. Well, motors are probably off at this time and no X-rays.

@prjemian
Copy link
Contributor Author

prjemian commented Sep 3, 2020 via email

@prjemian
Copy link
Contributor Author

prjemian commented Sep 3, 2020

test code installed at USAXS instrument (in data directory 2020-09/issue253.py):

"""
work on GitHub issue #253

%run -im issue253
uids = RE(issue253_plan(times=10))

* guard slit motors sometimes stuck in MOVING state
* https://github.com/APS-USAXS/ipython-usaxs/issues/253

Scan the guard slit motors repeatedly.
Ignore all the other activities associated when
guard slits are "tuned".  Use the "noisy" detector
from ophyd's simulators.

``
In [4]: wa gslit
gslit
  Positioner                     Value       Low Limit   High Limit  Offset
  guard_slit_bot                 -0.5        -11.3694    12.6306     -7.0664
  guard_slit_inb                 -0.5        -10.3912    13.6088     -33.0632
  guard_slit_outb                0.5         -9.403      14.597      507.34
  guard_slit_top                 0.5         -13.9196    10.0804     -1.8856
  guard_slit_x                   -1.105      -73.88      28.585      -42.65
  guard_slit_y                   14.6773     -17.92      59.00621    10.44885
``
"""

from instrument.session_logs import logger
logger.info(__file__)

from bluesky import plan_stubs as bps
from bluesky import plans as bp
from instrument.devices import guard_slit
from instrument.framework import bec, RE
import matplotlib.pyplot as plt
from ophyd.sim import noisy_det


_total_tunes = 0
_tune_number = 0


def scan_xy(detectors, md=None):
    _md = dict()
    _md.update(md or {})
    yield from bp.rel_scan(detectors, guard_slit.y, .1, -.1, 21, md=_md)
    yield from bp.rel_scan(detectors, guard_slit.x, .1, -.1, 21, md=_md)


def scan_opening(detectors, md=None):
    _md = dict()
    _md.update(md or {})
    yield from bp.rel_scan(detectors, guard_slit.top, .1, -.1, 21, md=_md)
    yield from bp.rel_scan(detectors, guard_slit.bot, -.1, .1, 21, md=_md)
    yield from bp.rel_scan(detectors, guard_slit.outb, .1, -.1, 21, md=_md)
    yield from bp.rel_scan(detectors, guard_slit.inb, -.1, .1, 21, md=_md)


def select_figure(x, y):
    figure_name = f"{y.name} vs {x.name}"
    if figure_name in plt.get_figlabels():
        print(figure_name)
        return plt.figure(figure_name)


def select_live_plot(bec, signal):
    for live_plot_dict in bec._live_plots.values():
        live_plot = live_plot_dict.get(signal.name)
        if live_plot is not None:
            return live_plot


def trim_plot(bec, n, x, y):
    liveplot = select_live_plot(bec, y)
    if liveplot is None:
        return
    fig = select_figure(x, y)
    if fig is None:
        return
    ax = fig.axes[0]
    while len(ax.lines) > n:
        try:
            ax.lines.pop(0).remove()
        except ValueError as exc:
            logger.warning(
                "%s vs %s: mpl remove() error: %s",
                y.name, x.name, str(exc))
    ax.legend()
    liveplot.update_plot()


def trim_all(n=3):
    for axis in "y x top bot outb inb".split():     # in order of tune
        trim_plot(bec, n, getattr(guard_slit, axis), noisy_det)


def scan_guard_slit(md=None):
    global _tune_number, _total_tunes
    _tune_number += 1
    _md = dict(
        purpose="test if guard slit motors sometimes stuck in MOVING state",
        URL="https://github.com/APS-USAXS/ipython-usaxs/issues/253",
        tune_number=_tune_number,
        tune=f"tune_Gslits() {_tune_number} of {_total_tunes}",
    )
    _md.update(md or {})
    logger.info("# tune number: %d", _tune_number)
    detectors = [noisy_det,]
    yield from scan_xy(detectors, md=_md)
    yield from scan_opening(detectors, md=_md)
    yield from bps.sleep(3.0)   # allow all plots to finish drawing
    trim_all()


def issue253_plan(times=1):
    """
    repeat the scans of the guard slit axes

    uids = RE(issue253_plan(times=2))
    """
    global _tune_number, _total_tunes
    logger.info("# ------- Testing for issue #253 with %d iterations", times)
    _tune_number = 0
    _total_tunes = times
    yield from bps.repeat(scan_guard_slit, num=times)

@prjemian
Copy link
Contributor Author

prjemian commented Sep 3, 2020

short test in progress to verify code operation:

Clipboard01

@prjemian
Copy link
Contributor Author

prjemian commented Sep 3, 2020

@jilavsky - I'll queue up 1000 repetitions of the six-motor "pseudo-tune" of the guard slits, looking for the original problem where one of the motors gets stuck in MOVING state. This should be run from the Jump session so you, too, can see what is happening.

@prjemian
Copy link
Contributor Author

prjemian commented Sep 3, 2020

Test of 1000 iterations started at ~18:28

Clipboard01

@prjemian
Copy link
Contributor Author

prjemian commented Sep 3, 2020

Note that old lines from each plot are discarded. At most, 3 or 4 lines on each.

@prjemian
Copy link
Contributor Author

prjemian commented Sep 4, 2020

172 iterations at 9:45 pm and no stuck MOVING (~52 iterations/hr, 1000 iterations should be complete by ~1:30 pm tomorrow)

@prjemian
Copy link
Contributor Author

prjemian commented Sep 4, 2020

664 iterations at 7:15 AM and no stuck MOVING

@prjemian
Copy link
Contributor Author

prjemian commented Sep 4, 2020

RunEngine stopped with an exception after 732 iterations, 8:34 AM with a UserWarning from PyEpics due to a timeout when waiting to get metadata for the next run (9id_bss:proposal_number is the PV).

A second exception ValueError was raised with a comment about an incorrect format specifier. In this case, the error is in ophyd.signal._get_with_timeout():

/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/ophyd/signal.py in _get_with_timeout(self, pv, timeout, connection_timeout, as_string, form)
   1057         if info is None:
   1058             raise ReadTimeoutError(
-> 1059                 f"Failed to read {pv.pvname} "
   1060                 f"within {timeout:.2} sec")
   1061 
generator rel_scan ['45678c24'] (scan num: 4584)
noisy_det vs guard_slit_y                                                                                                                   
W Fri-08:34:57 - noisy_det vs guard_slit_y: mpl remove() error: list.remove(x): x not in list
noisy_det vs guard_slit_x
W Fri-08:34:57 - noisy_det vs guard_slit_x: mpl remove() error: list.remove(x): x not in list
noisy_det vs guard_slit_top
W Fri-08:34:57 - noisy_det vs guard_slit_top: mpl remove() error: list.remove(x): x not in list
noisy_det vs guard_slit_bot
W Fri-08:34:57 - noisy_det vs guard_slit_bot: mpl remove() error: list.remove(x): x not in list
noisy_det vs guard_slit_outb
W Fri-08:34:57 - noisy_det vs guard_slit_outb: mpl remove() error: list.remove(x): x not in list
noisy_det vs guard_slit_inb
W Fri-08:34:57 - noisy_det vs guard_slit_inb: mpl remove() error: list.remove(x): x not in list
I Fri-08:34:57 - # tune number: 732


Transient Scan ID: 4585     Time: 2020-09-04 08:34:57
Persistent Unique Scan ID: 'eb48d18b-53b2-47e2-a6ed-d6ec72810331'
/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/epics/ca.py:1524: UserWarning: ca.get('9id_bss:proposal_number') timed out after 10.00 seconds.
  warnings.warn(msg % (name(chid), timeout))
Run aborted
Traceback (most recent call last):
  File "/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/run_engine.py", line 1365, in _run
    msg = self._plan_stack[-1].send(resp)
  File "/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py", line 1307, in __call__
    return (yield from plan)
  File "/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py", line 1162, in baseline_wrapper
    return (yield from plan_mutator(plan, insert_baseline))
  File "/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py", line 170, in plan_mutator
    raise ex
  File "/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py", line 123, in plan_mutator
    msg = plan_stack[-1].send(ret)
  File "/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py", line 803, in monitor_during_wrapper
    return (yield from plan2)
  File "/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py", line 170, in plan_mutator
    raise ex
  File "/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py", line 123, in plan_mutator
    msg = plan_stack[-1].send(ret)
  File "/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py", line 170, in plan_mutator
    raise ex
  File "/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py", line 123, in plan_mutator
    msg = plan_stack[-1].send(ret)
  File "/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py", line 861, in fly_during_wrapper
    return (yield from plan2)
  File "/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py", line 170, in plan_mutator
    raise ex
  File "/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py", line 123, in plan_mutator
    msg = plan_stack[-1].send(ret)
  File "/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py", line 170, in plan_mutator
    raise ex
  File "/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py", line 123, in plan_mutator
    msg = plan_stack[-1].send(ret)
  File "/share1/USAXS_data/2020-09/issue253.py", line 126, in issue253_plan
    _total_tunes = times
  File "/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/plan_stubs.py", line 1185, in repeat
    return (yield from repeated_plan())
  File "/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/plan_stubs.py", line 1168, in repeated_plan
    yield from ensure_generator(plan())
  File "/share1/USAXS_data/2020-09/issue253.py", line 110, in scan_guard_slit
    detectors = [noisy_det,]
  File "/share1/USAXS_data/2020-09/issue253.py", line 47, in scan_xy
    yield from bp.rel_scan(detectors, guard_slit.y, .1, -.1, 21, md=_md)
  File "/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/plans.py", line 1390, in rel_scan
    return (yield from inner_rel_scan())
  File "/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/utils.py", line 1066, in dec_inner
    return (yield from plan)
  File "/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py", line 1119, in reset_positions_wrapper
    return (yield from finalize_wrapper(plan_mutator(plan, insert_reads),
  File "/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py", line 509, in finalize_wrapper
    ret = yield from plan
  File "/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py", line 78, in plan_mutator
    msg = plan_stack[-1].throw(exception)
  File "/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/utils.py", line 1066, in dec_inner
    return (yield from plan)
  File "/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py", line 1075, in relative_set_wrapper
    return (yield from plan)
  File "/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py", line 245, in msg_mutator
    ret = yield msg
  File "/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py", line 195, in plan_mutator
    inner_ret = yield msg
  File "/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py", line 78, in plan_mutator
    msg = plan_stack[-1].throw(exception)
  File "/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/utils.py", line 141, in single_gen
    return (yield msg)
  File "/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py", line 195, in plan_mutator
    inner_ret = yield msg
  File "/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py", line 195, in plan_mutator
    inner_ret = yield msg
  File "/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py", line 78, in plan_mutator
    msg = plan_stack[-1].throw(exception)
  File "/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/utils.py", line 141, in single_gen
    return (yield msg)
  File "/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py", line 195, in plan_mutator
    inner_ret = yield msg
  File "/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py", line 195, in plan_mutator
    inner_ret = yield msg
  File "/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py", line 78, in plan_mutator
    msg = plan_stack[-1].throw(exception)
  File "/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/plan_stubs.py", line 913, in trigger_and_read
    return (yield from rewindable_wrapper(inner_trigger_and_read(),
  File "/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py", line 693, in rewindable_wrapper
    return (yield from plan)
  File "/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/plan_stubs.py", line 907, in inner_trigger_and_read
    reading = (yield from read(obj))
  File "/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/plan_stubs.py", line 95, in read
    return (yield Msg('read', obj))
  File "/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py", line 195, in plan_mutator
    inner_ret = yield msg
  File "/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/run_engine.py", line 1425, in _run
    new_response = await coro(msg)
  File "/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/run_engine.py", line 1670, in _read
    ret = obj.read(*msg.args, **msg.kwargs)
  File "/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/ophyd/device.py", line 1237, in read
    res.update(component.read())
  File "/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/ophyd/utils/epics_pvs.py", line 198, in wrapper
    return fcn(self, *args, **kwargs)
  File "/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/ophyd/signal.py", line 366, in read
    value = self.get()
  File "/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/ophyd/signal.py", line 1095, in get
    info = self._get_with_timeout(
  File "/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/ophyd/signal.py", line 1059, in _get_with_timeout
    f"Failed to read {pv.pvname} "
ValueError: Precision not allowed in integer format specifier
---------------------------------------------------------------------------
ValueError                                Traceback (most recent call last)
/share1/USAXS_data/2020-09/issue253.py in <module>
----> 1 uids = RE(issue253_plan(times=1000))

/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/run_engine.py in __call__(self, *args, **metadata_kw)
    805             self._task_fut.add_done_callback(set_blocking_event)
    806 
--> 807         self._resume_task(init_func=_build_task)
    808 
    809         if self._interrupted:

/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/run_engine.py in _resume_task(self, init_func)
    929                     if (exc is not None
    930                             and not isinstance(exc, _RunEnginePanic)):
--> 931                         raise exc
    932 
    933     def install_suspender(self, suspender):

/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/run_engine.py in _run(self)
   1498             exit_reason = str(err)
   1499             self.log.exception("Run aborted")
-> 1500             raise err
   1501         finally:
   1502             if not exit_reason:

/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/run_engine.py in _run(self)
   1363                     else:
   1364                         try:
-> 1365                             msg = self._plan_stack[-1].send(resp)
   1366                         # We have exhausted the top generator
   1367                         except StopIteration:

/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py in __call__(self, plan)
   1305         plan = monitor_during_wrapper(plan, self.monitors)
   1306         plan = baseline_wrapper(plan, self.baseline)
-> 1307         return (yield from plan)
   1308 
   1309 

/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py in baseline_wrapper(plan, devices, name)
   1160         return (yield from plan)
   1161     else:
-> 1162         return (yield from plan_mutator(plan, insert_baseline))
   1163 
   1164 

/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py in plan_mutator(plan, msg_proc)
    168                     continue
    169                 else:
--> 170                     raise ex
    171         # if inserting / mutating, put new generator on the stack
    172         # and replace the current msg with the first element from the

/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py in plan_mutator(plan, msg_proc)
    121             ret = result_stack.pop()
    122             try:
--> 123                 msg = plan_stack[-1].send(ret)
    124             except StopIteration as e:
    125                 # discard the exhausted generator

/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py in monitor_during_wrapper(plan, signals)
    801     plan1 = plan_mutator(plan, insert_after_open)
    802     plan2 = plan_mutator(plan1, insert_before_close)
--> 803     return (yield from plan2)
    804 
    805 

/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py in plan_mutator(plan, msg_proc)
    168                     continue
    169                 else:
--> 170                     raise ex
    171         # if inserting / mutating, put new generator on the stack
    172         # and replace the current msg with the first element from the

/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py in plan_mutator(plan, msg_proc)
    121             ret = result_stack.pop()
    122             try:
--> 123                 msg = plan_stack[-1].send(ret)
    124             except StopIteration as e:
    125                 # discard the exhausted generator

/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py in plan_mutator(plan, msg_proc)
    168                     continue
    169                 else:
--> 170                     raise ex
    171         # if inserting / mutating, put new generator on the stack
    172         # and replace the current msg with the first element from the

/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py in plan_mutator(plan, msg_proc)
    121             ret = result_stack.pop()
    122             try:
--> 123                 msg = plan_stack[-1].send(ret)
    124             except StopIteration as e:
    125                 # discard the exhausted generator

/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py in fly_during_wrapper(plan, flyers)
    859     plan1 = plan_mutator(plan, insert_after_open)
    860     plan2 = plan_mutator(plan1, insert_before_close)
--> 861     return (yield from plan2)
    862 
    863 

/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py in plan_mutator(plan, msg_proc)
    168                     continue
    169                 else:
--> 170                     raise ex
    171         # if inserting / mutating, put new generator on the stack
    172         # and replace the current msg with the first element from the

/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py in plan_mutator(plan, msg_proc)
    121             ret = result_stack.pop()
    122             try:
--> 123                 msg = plan_stack[-1].send(ret)
    124             except StopIteration as e:
    125                 # discard the exhausted generator

/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py in plan_mutator(plan, msg_proc)
    168                     continue
    169                 else:
--> 170                     raise ex
    171         # if inserting / mutating, put new generator on the stack
    172         # and replace the current msg with the first element from the

/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py in plan_mutator(plan, msg_proc)
    121             ret = result_stack.pop()
    122             try:
--> 123                 msg = plan_stack[-1].send(ret)
    124             except StopIteration as e:
    125                 # discard the exhausted generator

/share1/USAXS_data/2020-09/issue253.py in issue253_plan(times)
    124     logger.info("# ------- Testing for issue #253 with %d iterations", times)
    125     _tune_number = 0
--> 126     _total_tunes = times
    127     yield from bps.repeat(scan_guard_slit, num=times)

/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/plan_stubs.py in repeat(plan, num, delay)
   1183                     yield Msg('sleep', None, d)
   1184 
-> 1185     return (yield from repeated_plan())

/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/plan_stubs.py in repeated_plan()
   1166             now = time.time()  # Intercept the flow in its earliest moment.
   1167             yield Msg('checkpoint')
-> 1168             yield from ensure_generator(plan())
   1169             try:
   1170                 d = next(delay)

/share1/USAXS_data/2020-09/issue253.py in scan_guard_slit(md)
    108     _md.update(md or {})
    109     logger.info("# tune number: %d", _tune_number)
--> 110     detectors = [noisy_det,]
    111     yield from scan_xy(detectors, md=_md)
    112     yield from scan_opening(detectors, md=_md)

/share1/USAXS_data/2020-09/issue253.py in scan_xy(detectors, md)
     45     _md = dict()
     46     _md.update(md or {})
---> 47     yield from bp.rel_scan(detectors, guard_slit.y, .1, -.1, 21, md=_md)
     48     yield from bp.rel_scan(detectors, guard_slit.x, .1, -.1, 21, md=_md)
     49 

/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/plans.py in rel_scan(detectors, num, per_step, md, *args)
   1388                                 per_step=per_step, md=_md))
   1389 
-> 1390     return (yield from inner_rel_scan())
   1391 
   1392 

/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/utils.py in dec_inner(*inner_args, **inner_kwargs)
   1064                 plan = gen_func(*inner_args, **inner_kwargs)
   1065                 plan = wrapper(plan, *args, **kwargs)
-> 1066                 return (yield from plan)
   1067             return dec_inner
   1068         return dec

/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py in reset_positions_wrapper(plan, devices)
   1117         yield Msg('wait', None, group=blk_grp)
   1118 
-> 1119     return (yield from finalize_wrapper(plan_mutator(plan, insert_reads),
   1120                                         reset()))
   1121 

/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py in finalize_wrapper(plan, final_plan, pause_for_debug)
    507     cleanup = True
    508     try:
--> 509         ret = yield from plan
    510     except GeneratorExit:
    511         cleanup = False

/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py in plan_mutator(plan, msg_proc)
     76             # if we have a stashed exception, pass it along
     77             try:
---> 78                 msg = plan_stack[-1].throw(exception)
     79             except StopIteration as e:
     80                 # discard the exhausted generator

/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/utils.py in dec_inner(*inner_args, **inner_kwargs)
   1064                 plan = gen_func(*inner_args, **inner_kwargs)
   1065                 plan = wrapper(plan, *args, **kwargs)
-> 1066                 return (yield from plan)
   1067             return dec_inner
   1068         return dec

/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py in relative_set_wrapper(plan, devices)
   1073     plan = plan_mutator(plan, insert_reads)
   1074     plan = msg_mutator(plan, rewrite_pos)
-> 1075     return (yield from plan)
   1076 
   1077 

/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py in msg_mutator(plan, msg_proc)
    243                 ret = None
    244                 continue
--> 245             ret = yield msg
    246         except StopIteration as e:
    247             return e.value

/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py in plan_mutator(plan, msg_proc)
    193         try:
    194             # yield out the 'current message' and collect the return
--> 195             inner_ret = yield msg
    196         except GeneratorExit:
    197             # special case GeneratorExit.  We must clean up all of our plans

/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py in plan_mutator(plan, msg_proc)
     76             # if we have a stashed exception, pass it along
     77             try:
---> 78                 msg = plan_stack[-1].throw(exception)
     79             except StopIteration as e:
     80                 # discard the exhausted generator

/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/utils.py in single_gen(msg)
    139         the input message
    140     '''
--> 141     return (yield msg)
    142 
    143 

/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py in plan_mutator(plan, msg_proc)
    193         try:
    194             # yield out the 'current message' and collect the return
--> 195             inner_ret = yield msg
    196         except GeneratorExit:
    197             # special case GeneratorExit.  We must clean up all of our plans

/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py in plan_mutator(plan, msg_proc)
    193         try:
    194             # yield out the 'current message' and collect the return
--> 195             inner_ret = yield msg
    196         except GeneratorExit:
    197             # special case GeneratorExit.  We must clean up all of our plans

/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py in plan_mutator(plan, msg_proc)
     76             # if we have a stashed exception, pass it along
     77             try:
---> 78                 msg = plan_stack[-1].throw(exception)
     79             except StopIteration as e:
     80                 # discard the exhausted generator

/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/utils.py in single_gen(msg)
    139         the input message
    140     '''
--> 141     return (yield msg)
    142 
    143 

/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py in plan_mutator(plan, msg_proc)
    193         try:
    194             # yield out the 'current message' and collect the return
--> 195             inner_ret = yield msg
    196         except GeneratorExit:
    197             # special case GeneratorExit.  We must clean up all of our plans

/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py in plan_mutator(plan, msg_proc)
    193         try:
    194             # yield out the 'current message' and collect the return
--> 195             inner_ret = yield msg
    196         except GeneratorExit:
    197             # special case GeneratorExit.  We must clean up all of our plans

/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py in plan_mutator(plan, msg_proc)
     76             # if we have a stashed exception, pass it along
     77             try:
---> 78                 msg = plan_stack[-1].throw(exception)
     79             except StopIteration as e:
     80                 # discard the exhausted generator

/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/plan_stubs.py in trigger_and_read(devices, name)
    911         return ret
    912     from .preprocessors import rewindable_wrapper
--> 913     return (yield from rewindable_wrapper(inner_trigger_and_read(),
    914                                           rewindable))
    915 

/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py in rewindable_wrapper(plan, rewindable)
    691                                             restore_rewindable()))
    692     else:
--> 693         return (yield from plan)
    694 
    695 

/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/plan_stubs.py in inner_trigger_and_read()
    905         ret = {}  # collect and return readings to give plan access to them
    906         for obj in devices:
--> 907             reading = (yield from read(obj))
    908             if reading is not None:
    909                 ret.update(reading)

/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/plan_stubs.py in read(obj)
     93         Msg('read', obj)
     94     """
---> 95     return (yield Msg('read', obj))
     96 
     97 

/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/preprocessors.py in plan_mutator(plan, msg_proc)
    193         try:
    194             # yield out the 'current message' and collect the return
--> 195             inner_ret = yield msg
    196         except GeneratorExit:
    197             # special case GeneratorExit.  We must clean up all of our plans

/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/run_engine.py in _run(self)
   1423                         # exceptions (coming in via throw) can be
   1424                         # raised
-> 1425                         new_response = await coro(msg)
   1426 
   1427                     # special case `CancelledError` and let the outer

/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/bluesky/run_engine.py in _read(self, msg)
   1668         obj = msg.obj
   1669         # actually _read_ the object
-> 1670         ret = obj.read(*msg.args, **msg.kwargs)
   1671 
   1672         if ret is None:

/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/ophyd/device.py in read(self)
   1235 
   1236         for _, component in self._get_components_of_kind(Kind.normal):
-> 1237             res.update(component.read())
   1238         return res
   1239 

/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/ophyd/utils/epics_pvs.py in wrapper(self, *args, **kwargs)
    196     def wrapper(self, *args, **kwargs):
    197         if self.connected:
--> 198             return fcn(self, *args, **kwargs)
    199         else:
    200             raise DisconnectedError('{} is not connected'.format(self.name))

/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/ophyd/signal.py in read(self)
    364             dict
    365         '''
--> 366         value = self.get()
    367         return {self.name: {'value': value,
    368                             'timestamp': self.timestamp}}

/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/ophyd/signal.py in get(self, as_string, timeout, connection_timeout, form, **kwargs)
   1093             as_string = self._string
   1094 
-> 1095         info = self._get_with_timeout(
   1096             self._read_pv, timeout, connection_timeout, as_string, form)
   1097 

/share1/bluesky/conda_envs/bluesky_2020_9/lib/python3.8/site-packages/ophyd/signal.py in _get_with_timeout(self, pv, timeout, connection_timeout, as_string, form)
   1057         if info is None:
   1058             raise ReadTimeoutError(
-> 1059                 f"Failed to read {pv.pvname} "
   1060                 f"within {timeout:.2} sec")
   1061 

ValueError: Precision not allowed in integer format specifier

In [3]:                                                                                                                                     

@prjemian
Copy link
Contributor Author

prjemian commented Sep 4, 2020

Ouch. Stopped our test cold. But, @jilavsky @kmpeters would you both conclude that we are not seeing the original problem (guard slit motors sometimes stuck in MOVING state) now? Could it be the problem is resolved (by other software changes) or is there something to be changed in the test method here?

@jilavsky
Copy link
Contributor

jilavsky commented Sep 8, 2020

I agree, that we are not seeing motor hanging. I do not see (or cannot find) the code being run. Tuning GSlits involves multiple steps. Scanning up to 6 motors. Obviously, that works, tested lots of times. Finding center positions (just code, cannot hang motors). And setting motors to proper positions. For x and y this is simple motor move to calculated center. But for slit blades this is using the epics soft slits record or whatever the name is. That last step was what we suspected from failing. Was that tested in these scans? I am not sure how that is used in BS, would need to look at the code.

@prjemian
Copy link
Contributor Author

prjemian commented Sep 8, 2020

@jilavsky, @kmpeters : Thanks for your reviews.

The test code is in the Details dropdown of this message (above): #253 (comment)

The code was modeled after exactly the operations taken by the Tune_GuardSlits code. It scans all six motors in the same sequence (y, x, top, bottom, outboard, inboard). Since the result of each tune is unimportant, that was not done in the test code above. If the tunes had scanned (tuned) either slit's gap or center, that would have used part of the 2slit.db code. However, operation of any of the real motors exercises the 2slit.db code as it evaluates the effects on the virtual motors.

@prjemian
Copy link
Contributor Author

prjemian commented Sep 9, 2020

Leave this issue open for now. If problem is not seen again, close automatically at next milestone. Moving to that milestone now.

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
bug Something isn't working
Projects
None yet
Development

No branches or pull requests

3 participants