search

NSLS-II / Bug-Reports

Unified issue-tracker for bugs in the data acquisition, management, and analysis software at NSLS-II
BSD 3-Clause "New" or "Revised" License
2 stars 5 forks source link

Killing motion because gs.PS issue with mov() and the problems it caused. Bluesky and CSS report different pgm_en. #113

Open ambarb opened 8 years ago

ambarb commented 8 years ago

This is a bit convoluted. I set up a definition.


def CuEscan():
    MonoClosedLoop()
    sleep(1)
    RE(ascan(pgm_en,920,960,40))
    mov(pgm_en,gs.PS.max[0]-1.4)
    scantype = 'CuEscan'
    sleep(2)

Executed it, and after the scan finished the energy was in a trapped state (no prompt return) 100eV away from where it should be (unexpected energy for this case). I fear that I should have added a wait time for the gs.PS to be calculated. I was doing this manually with no issues.

In [152]: CuEscan()
Transient Scan ID: 64589
Persistent Unique Scan ID: '3c0fc2f3-3bce-4397-a6bd-79f32c862d71'
+-----------+------------+------------+---------------------+------------------------+
|   seq_num |       time |     energy | pgm_energy_setpoint | pgm_energy_stop_signal |
+-----------+------------+------------+---------------------+------------------------+
|         1 | 23:37:14.0 |    959.507 |             921.000 |                      0 |
+-----------+------------+------------+---------------------+------------------------+------------+------------+------------+------------+------------+------------+------------+------------+---------------+
|   seq_num |       time |     energy | pgm_energy_setpoint | pgm_energy_stop_signal |   sclr_ch2 |   epu1_gap |   epu2_gap | mono_tempa | mono_tempb |  grt1_temp |  grt2_temp |  ring_curr | diag6_monitor |
+-----------+------------+------------+---------------------+------------------------+------------+------------+------------+------------+------------+------------+------------+------------+---------------+
|         1 | 23:37:25.1 |    920.000 |             920.000 |                      0 |       3816 |    23.4030 |    30.8352 |    302.750 |    302.747 |       31.8 |       28.6 |     170.02 |     161812907 |
|         2 | 23:37:35.0 |    920.988 |             921.000 |                      0 |       3828 |    23.4801 |    30.8541 |    302.750 |    302.747 |       31.8 |       28.8 |     169.96 |     162915716 |
|         3 | 23:37:45.0 |    922.130 |             922.000 |                      0 |       3846 |    23.5318 |    30.8725 |    302.750 |    302.750 |       31.8 |       28.7 |     169.90 |     162891219 |
|         4 | 23:37:55.0 |    923.065 |             923.000 |                      0 |       3865 |    23.5856 |    30.8911 |    302.750 |    302.751 |       31.8 |       28.7 |     169.84 |     161689031 |
|         5 | 23:38:05.2 |    924.118 |             924.000 |                      0 |       3923 |    23.6638 |    30.9096 |    302.748 |    302.750 |       31.7 |       28.8 |     171.16 |     162111096 |
|         6 | 23:38:14.9 |    925.176 |             925.000 |                      0 |       4028 |    23.7304 |    30.9282 |    302.749 |    302.743 |       31.8 |       28.7 |     171.10 |     162788825 |
|         7 | 23:38:24.4 |    926.054 |             926.000 |                      0 |       4296 |    23.7818 |    30.9467 |    302.750 |    302.744 |       31.8 |       28.7 |     171.04 |     162467668 |
|         8 | 23:38:34.1 |    926.950 |             927.000 |                      0 |       5912 |    23.8319 |    30.9653 |    302.752 |    302.756 |       31.8 |       28.7 |     170.98 |     163874912 |
|         9 | 23:38:36.0 |    930.882 |             928.000 |                      0 |      10239 |    23.8474 |    30.9653 |    302.753 |    302.757 |       31.8 |       28.8 |     170.98 |     170597944 |
|        10 | 23:38:46.0 |    928.983 |             929.000 |                      0 |      13161 |    23.9218 |    31.0024 |    302.748 |    302.747 |       31.7 |       28.7 |     170.92 |     161440941 |
|        11 | 23:38:55.6 |    930.111 |             930.000 |                      0 |      11051 |    23.9816 |    31.0208 |    302.748 |    302.744 |       31.8 |       28.7 |     170.86 |     163956872 |
|        12 | 23:39:05.2 |    930.945 |             931.000 |                      0 |       9988 |    24.0318 |    31.0394 |    302.752 |    302.754 |       31.8 |       28.8 |     170.80 |     163889319 |
|        13 | 23:39:15.0 |    931.864 |             932.000 |                      0 |       9825 |    24.0858 |    31.0579 |    302.750 |    302.749 |       31.7 |       28.7 |     170.74 |     164141073 |
logi|        14 | 23:39:25.0 |    932.816 |             933.000 |                      0 |       9392 |    24.1617 |    31.0765 |    302.749 |    302.749 |       31.8 |       28.9 |     170.68 |     162772629 |
t Starting overnight scr|        15 | 23:39:35.0 |    934.125 |             934.000 |                      0 |       8816 |    24.2306 |    31.0950 |    302.750 |    302.748 |       31.8 |       28.8 |     170.68 |     162904525 |
ipt with 20um pinole|        16 | 23:39:44.9 |    934.773 |             935.000 |                      0 |       8715 |    24.2818 |    31.1135 |    302.748 |    302.747 |       31.7 |       28.7 |     170.62 |     166299889 |
 at Slt:3|        17 | 23:39:54.5 |    936.050 |             936.000 |                      0 |       8642 |    24.3327 |    31.1321 |    302.749 |    302.753 |       31.7 |       28.7 |     170.56 |     166731686 |
|        18 | 23:40:04.0 |    936.819 |             937.000 |                      0 |       8537 |    24.3986 |    31.1505 |    302.750 |    302.755 |       31.8 |       28.7 |     170.50 |     165750805 |
|        19 | 23:40:13.9 |    937.988 |             938.000 |                      0 |       8469 |    24.4738 |    31.1691 |    302.750 |    302.750 |       31.7 |       28.7 |     170.44 |     164702963 |
|        20 | 23:40:23.5 |    938.810 |             939.000 |                      0 |       8479 |    22.4896 |    31.1876 |    302.753 |    302.749 |       31.7 |       28.8 |     170.38 |     164176751 |
.|        21 | 23:40:33.1 |    939.919 |             940.000 |                      0 |       8595 |    23.2408 |    31.2062 |    302.752 |    302.752 |       31.7 |       28.7 |     170.32 |     164026387 |
|        22 | 23:40:42.9 |    941.056 |             941.000 |                      0 |       8718 |    23.2402 |    31.2247 |    302.755 |    302.751 |       31.7 |       28.7 |     170.26 |     166240881 |
|        23 | 23:40:52.3 |    941.491 |             942.000 |                      0 |       8684 |    21.2404 |    31.2433 |    302.753 |    302.756 |       31.7 |       28.7 |     170.20 |     164757761 |
|        24 | 23:41:02.1 |    943.394 |             943.000 |                      0 |       8694 |    21.3041 |    31.2618 |    302.752 |    302.750 |       31.8 |       28.7 |     170.14 |     165307360 |
|        25 | 23:41:11.8 |    943.863 |             944.000 |                      0 |       8749 |    21.3803 |    31.2803 |    302.749 |    302.746 |       31.7 |       28.7 |     170.08 |     164858014 |
|        26 | 23:41:21.3 |    945.053 |             945.000 |                      0 |       9070 |    21.4398 |    31.2989 |    302.750 |    302.752 |       31.7 |       28.7 |     170.08 |     165477524 |
|        27 | 23:41:31.0 |    946.014 |             946.000 |                      0 |       9534 |    21.4902 |    31.3174 |    302.755 |    302.751 |       31.8 |       28.7 |     170.02 |     166257571 |
|        28 | 23:41:40.6 |    946.906 |             947.000 |                      0 |      11093 |    21.5410 |    31.3359 |    302.755 |    302.756 |       31.8 |       28.7 |     169.96 |     165907147 |
|        29 | 23:41:50.2 |    947.997 |             948.000 |                      0 |      12966 |    21.6058 |    31.3545 |    302.754 |    302.752 |       31.7 |       28.7 |     169.90 |     165385566 |
|        30 | 23:42:00.2 |    948.924 |             949.000 |                      0 |      12847 |    21.6825 |    31.3730 |    302.753 |    302.746 |       31.8 |       28.6 |     169.84 |     165922135 |

gs.PS.max[0]
|        31 | 23:42:09.9 |    950.064 |             950.000 |                      0 |      12398 |    21.7402 |    31.3916 |    302.753 |    302.758 |       31.8 |       28.7 |     169.78 |     166480945 |

gs.PS.max[0]-1.4

|        32 | 23:42:19.6 |    950.891 |             951.000 |                      0 |      12166 |    21.7903 |    31.4101 |    302.756 |    302.754 |       31.8 |       28.7 |     169.72 |     167365159 |
|        33 | 23:42:29.1 |    952.579 |             952.000 |                      0 |      12050 |    21.8443 |    31.4287 |    302.754 |    302.755 |       31.8 |       28.7 |     169.66 |     168575606 |
|        34 | 23:42:38.8 |    952.849 |             953.000 |                      0 |      11856 |    21.9187 |    31.4472 |    302.749 |    302.753 |       31.8 |       28.7 |     169.60 |     167695788 |
|        35 | 23:42:48.3 |    953.952 |             954.000 |                      0 |      11826 |    21.9854 |    31.4658 |    302.749 |    302.750 |       31.8 |       28.7 |     169.60 |     167186305 |
|        36 | 23:42:58.0 |    954.991 |             955.000 |                      0 |      11968 |    22.0402 |    31.4843 |    302.750 |    302.751 |       31.8 |       28.7 |     170.56 |     168828048 |
|        37 | 23:43:08.0 |    956.014 |             956.000 |                      0 |      12010 |    22.0903 |    31.5029 |    302.748 |    302.753 |       31.8 |       28.7 |     170.50 |     168325741 |
|        38 | 23:43:17.5 |    957.354 |             957.000 |                      0 |      12038 |    22.1472 |    31.5215 |    302.749 |    302.745 |       31.8 |       28.7 |     170.44 |     168332052 |
|        39 | 23:43:26.9 |    957.930 |             958.000 |                      0 |      12040 |    22.2200 |    31.5400 |    302.749 |    302.748 |       31.8 |       28.7 |     170.38 |     167980162 |
|        40 | 23:43:28.7 |    961.263 |             959.000 |                      0 |      12133 |    22.2381 |    31.5401 |    302.749 |    302.751 |       31.7 |       28.7 |     170.38 |     179824182 |
|        41 | 23:43:38.3 |    959.593 |             960.000 |                      0 |      12264 |    22.2902 |    31.5773 |    302.752 |    302.753 |       31.8 |       28.7 |     170.32 |     168862055 |
|         2 | 23:43:38.4 |    960.583 |             960.000 |                      0 |            |            |            |            |            |            |            |            |               |
+-----------+------------+------------+---------------------+------------------------+------------+------------+------------+------------+------------+------------+------------+------------+---------------+
generator ascan ['3c0fc2'] (scan num: 64589)

   pgm_en

This is where it was hung and oscillating around 840 eV (pgm_en) so I ^C^C^C. The bluesky printed 840ish. Did not look to see what PV (CSS screen) read as energy.

  [!!] ABORTED : Commanding all positioners to stop.
[--] Stopping pgm_en
---------------------------------------------------------------------------
KeyboardInterrupt                         Traceback (most recent call last)
<ipython-input-152-253806aface1> in <module>()
----> 1 CuEscan()

<ipython-input-141-c58e36c7a601> in CuEscan()
      2         MonoClosedLoop()
      3         RE(ascan(pgm_en,920,960,40))
----> 4         mov(pgm_en,gs.PS.max[0]-1.4)
      5         #olog('#{} CuEscan, MonoMode = {}'.format((db[-1].get('start').get('scan_id')),MonoMode)
      6         sleep(2)

/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/ophyd/commands.py in wrapper(*args, **kwargs)
    169                                     'an instance of {}'.format(n, t))
    170 
--> 171             f(*args, **kwargs)
    172         return wrapper
    173     return wrap

/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/ophyd/commands.py in mov(positioner, position)
    232             print('\n')
    233             print('\033[2A', end='')
--> 234             time.sleep(0.01)
    235             done = all(s.done for s in stat)
    236             if done:

KeyboardInterrupt: 

In [153]: 
KeyboardInterrupt

That aborted ok. Now see if PS is okay ,and it is. Then commanded to move where I want pgm_en

In [153]: gs.PS.max[0]
Out[153]: 928.98309689999996

In [154]:     mov(pgm_en,gs.PS.max[0]-1.4)

   pgm_en

Bluesky went crazy and this is where I could not get the command prompt back without the timeout messages.

/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/epics/ca.py:1245: UserWarning: ca.get('XF:23ID1-OP{Mono-Ax:MirP}Mtr.TDIR') timed out after 1.00 seconds.
  warnings.warn(msg % (name(chid), timeout))
/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/epics/ca.py:1245: UserWarning: ca.get('XF:23ID1-OP{Mono-Ax:MirP}Mtr.HLS') timed out after 1.00 seconds.
  warnings.warn(msg % (name(chid), timeout))
/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/epics/ca.py:1483: UserWarning: ca.get_timevars('XF:23ID1-OP{Mono}Enrgy-SP') timed out after 5.00 seconds.
  warnings.warn(msg % (name(chid), timeout))
    853.980926        

    853.980926        vs/collection/lib/python3.4/site-packages/epics/ca.py:1245: UserWarning: ca.get('XF:23ID1-OP{Mono-Ax:GrtP}Mtr.TDIR') timed out after 1.00 seconds.
  warnings.warn(msg % (name(chid), timeout))
  [!!] ABORTED : Commanding all positioners to stop.te-packages/epics/ca.py:1245: UserWarning: ca.get('XF:23ID1-OP{Mono-Ax:GrtP}Mtr.HLS') timed out after 1.00 seconds.
^C---------------------------------------------------------------------------
KeyboardInterrupt                         Traceback (most recent call last)
/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/ophyd/commands.py in catch_keyboard_interrupt(positioners)
    716     try:
--> 717         yield
    718     except KeyboardInterrupt:

/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/ophyd/commands.py in mov(positioner, position)
    233             print('\033[2A', end='')
--> 234             time.sleep(0.01)
    235             done = all(s.done for s in stat)

KeyboardInterrupt: 

During handling of the above exception, another exception occurred:

KeyboardInterrupt                         Traceback (most recent call last)
<ipython-input-154-1c44264d5844> in <module>()
----> 1 mov(pgm_en,gs.PS.max[0]-1.4)

/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/ophyd/commands.py in wrapper(*args, **kwargs)
    169                                     'an instance of {}'.format(n, t))
    170 
--> 171             f(*args, **kwargs)
    172         return wrapper
    173     return wrap

/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/ophyd/commands.py in mov(positioner, position)
    235             done = all(s.done for s in stat)
    236             if done:
--> 237                 flag += 1
    238 
    239     print(tc.Normal + '\n')

/home/xf23id1/conda_envs/collection/lib/python3.4/contextlib.py in __exit__(self, type, value, traceback)
     75                 value = type()
     76             try:
---> 77                 self.gen.throw(type, value, traceback)
     78                 raise RuntimeError("generator didn't stop after throw()")
     79             except StopIteration as exc:

/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/ophyd/commands.py in catch_keyboard_interrupt(positioners)
    720               ": Commanding all positioners to stop.")
    721         for p in positioners:
--> 722             p.stop()
    723             print("{}[--] Stopping {}{}".format(tc.Red, tc.LightRed, p.name))
    724         print(tc.Normal, end='')

/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/ophyd/pv_positioner.py in stop(self)
    235     def stop(self):
    236         if self.stop_signal is not None:
--> 237             self.stop_signal.put(self.stop_value, wait=False)
    238         super().stop()
    239 

/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/ophyd/signal.py in put(self, value, force, **kwargs)
    800             self._run_subs(sub_type=self.SUB_SETPOINT,
    801                            old_value=old_value, value=value,
--> 802                            timestamp=self.timestamp, **kwargs)
    803 
    804     def set(self, value, *, timeout=None, settle_time=None):

/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/ophyd/utils/epics_pvs.py in wrapper(self, *args, **kwargs)
    339     def wrapper(self, *args, **kwargs):
    340         if self.connected:
--> 341             return fcn(self, *args, **kwargs)
    342         else:
    343             raise DisconnectedError('{} is not connected'.format(self.name))

/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/ophyd/signal.py in timestamp(self)
    423         if not self._read_pv.auto_monitor:
    424             # force updating the timestamp when not using auto monitoring
--> 425             self._read_pv.get_timevars()
    426         return self._read_pv.timestamp
    427 

/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/epics/pv.py in get_timevars(self, timeout, warn)
    431         if not self.wait_for_connection():
    432             return None
--> 433         kwds = ca.get_timevars(self.chid, timeout=timeout, warn=warn)
    434         self._args.update(kwds)
    435         return kwds

/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/epics/ca.py in wrapper(*args, **kwds)
    414                                                         name(chid), timeout))
    415 
--> 416         return fcn(*args, **kwds)
    417     wrapper.__doc__ = fcn.__doc__
    418     wrapper.__name__ = fcn.__name__

/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/epics/ca.py in get_timevars(chid, timeout, warn)
   1477     t0 = time.time()
   1478     while ncache['time_value'] is GET_PENDING:
-> 1479         poll()
   1480         if time.time()-t0 > timeout:
   1481             if warn:

/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/epics/ca.py in wrapper(*args, **kwds)
    358         if libca is None:
    359             initialize_libca()
--> 360         return fcn(*args, **kwds)
    361     wrapper.__doc__ = fcn.__doc__
    362     wrapper.__name__ = fcn.__name__

/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/epics/ca.py in poll(evt, iot)
    763 
    764     """
--> 765     pend_event(evt)
    766     return pend_io(iot)
    767 

/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/epics/ca.py in pend_event(timeout)
    750 def pend_event(timeout=1.e-5):
    751     """polls CA for events """
--> 752     ret = libca.ca_pend_event(timeout)
    753     try:
    754         return PySEVCHK( 'pend_event', ret,  dbr.ECA_TIMEOUT)

KeyboardInterrupt: 

In [155]: 
KeyboardInterrupt

In [155]: abort()
---------------------------------------------------------------------------
TransitionError                           Traceback (most recent call last)
<ipython-input-155-2fe129fe422b> in <module>()
----> 1 abort()

/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/bluesky/global_state.py in abort()
    156     This function closes over the global RunEngine instance, gs.RE.
    157     """
--> 158     return gs.RE.abort()
    159 
    160 

/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/bluesky/run_engine.py in abort(self, reason)
    740         """
    741         if self.state.is_idle:
--> 742             raise TransitionError("RunEngine is already idle.")
    743         print("Aborting....")
    744         self._interrupted = True

TransitionError: RunEngine is already idle.

In [156]: /home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/epics/ca.py:1245: UserWarning: ca.get('XF:23ID1-OP{Mono-Ax:MirP}Mtr.TDIR') timed out after 1.00 seconds.
  warnings.warn(msg % (name(chid), timeout))
/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/epics/ca.py:1245: UserWarning: ca.get('XF:23ID1-OP{Mono-Ax:MirP}Mtr.HLS') timed out after 1.00 seconds.
  warnings.warn(msg % (name(chid), timeout))
/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/epics/ca.py:1245: UserWarning: ca.get('XF:23ID1-OP{Mono-Ax:GrtP}Mtr.TDIR') timed out after 1.00 seconds.
  warnings.warn(msg % (name(chid), timeout))
/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/epics/ca.py:1245: UserWarning: ca.get('XF:23ID1-OP{Mono-Ax:GrtP}Mtr.HLS') timed out after 1.00 seconds.
  warnings.warn(msg % (name(chid), timeout))

In [156]: 

In [156]: /home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/epics/ca.py:1245: UserWarning: ca.get('XF:23ID1-OP{Mono-Ax:MirP}Mtr.TDIR') timed out after 1.00 seconds.
  warnings.warn(msg % (name(chid), timeout))
/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/epics/ca.py:1245: UserWarning: ca.get('XF:23ID1-OP{Mono-Ax:MirP}Mtr.HLS') timed out after 1.00 seconds.
  warnings.warn(msg % (name(chid), timeout))
a/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/epics/ca.py:1245: UserWarning: ca.get('XF:23ID1-OP{Mono-Ax:GrtP}Mtr.TDIR') timed out after 1.00 seconds.
  warnings.warn(msg % (name(chid), timeout))
b/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/epics/ca.py:1245: UserWarning: ca.get('XF:23ID1-OP{Mono-Ax:GrtP}Mtr.HLS') timed out after 1.00 seconds.
  warnings.warn(msg % (name(chid), timeout))
ort()
---------------------------------------------------------------------------
TransitionError                           Traceback (most recent call last)
<ipython-input-156-2fe129fe422b> in <module>()
----> 1 abort()

/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/bluesky/global_state.py in abort()
    156     This function closes over the global RunEngine instance, gs.RE.
    157     """
--> 158     return gs.RE.abort()
    159 
    160 

/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/bluesky/run_engine.py in abort(self, reason)
    740         """
    741         if self.state.is_idle:
--> 742             raise TransitionError("RunEngine is already idle.")
    743         print("Aborting....")
    744         self._interrupted = True

TransitionError: RunEngine is already idle.

In [157]: 

In [157]: /home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/epics/ca.py:1245: UserWarning: ca.get('XF:23ID1-OP{Mono-Ax:MirP}Mtr.HLS') timed out after 1.00 seconds.
  warnings.warn(msg % (name(chid), timeout))
/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/epics/ca.py:1245: UserWarning: ca.get('XF:23ID1-OP{Mono-Ax:GrtP}Mtr.TDIR') timed out after 1.00 seconds.
  warnings.warn(msg % (name(chid), timeout))

KeyboardInterrupt

In [157]: /home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/epics/ca.py:1245: UserWarning: ca.get('XF:23ID1-OP{Mono-Ax:GrtP}Mtr.HLS') timed out after 1.00 seconds.
  warnings.warn(msg % (name(chid), timeout))
/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/epics/ca.py:1245: UserWarning: ca.get('XF:23ID1-OP{Mono-Ax:MirP}Mtr.TDIR') timed out after 1.00 seconds.
  warnings.warn(msg % (name(chid), timeout))

In [157]: /home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/epics/ca.py:1245: UserWarning: ca.get('XF:23ID1-OP{Mono-Ax:GrtP}Mtr.TDIR') timed out after 1.00 seconds.
  warnings.warn(msg % (name(chid), timeout))

KeyboardInterrupt

In [157]: /home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/epics/ca.py:1245: UserWarning: ca.get('XF:23ID1-OP{Mono-Ax:GrtP}Mtr.HLS') timed out after 1.00 seconds.
  warnings.warn(msg % (name(chid), timeout))

KeyboardInterrupt

In [157]: 
KeyboardInterrupt

In [157]: 
KeyboardInterrupt

In [157]: 
KeyboardInterrupt

In [157]: /home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/epics/ca.py:1245: UserWarning: ca.get('XF:23ID1-OP{Mono-Ax:MirP}Mtr.TDIR') timed out after 1.00 seconds.
  warnings.warn(msg % (name(chid), timeout))

KeyboardInterrupt

In [157]: 
KeyboardInterrupt

In [157]: 
KeyboardInterrupt

In [157]: 
KeyboardInterrupt

In [157]: /home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/epics/ca.py:1245: UserWarning: ca.get('XF:23ID1-OP{Mono-Ax:MirP}Mtr.HLS') timed out after 1.00 seconds.
  warnings.warn(msg % (name(chid), timeout))

Eventually those timeout messages stop (ca.get is back). Cursor is also gone. This is not the first time that the cursor has disappear. Have to restart collection to get it back when this happens, but I did not do that here as I wanted to see what was happening with the first issue.

In [157]: gs.PS.max[0]
Out[157]: 928.98309689999996

In [158]: gs.PS.max[0]-1.4
Out[158]: 927.58309689999999

In [159]: abort()
---------------------------------------------------------------------------
TransitionError                           Traceback (most recent call last)
<ipython-input-159-2fe129fe422b> in <module>()
----> 1 abort()

/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/bluesky/global_state.py in abort()
    156     This function closes over the global RunEngine instance, gs.RE.
    157     """
--> 158     return gs.RE.abort()
    159 
    160 

/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/bluesky/run_engine.py in abort(self, reason)
    740         """
    741         if self.state.is_idle:
--> 742             raise TransitionError("RunEngine is already idle.")
    743         print("Aborting....")
    744         self._interrupted = True

TransitionError: RunEngine is already idle.

In [160]:

Kept trying to move the energy in bluesky and still getting stuck. Bluesky pgm_en and CSS pgm_en do not match. Energy Scan status is "moving' even thought the motors are just in a stabilized mode. Able to get a screenshot (1st image). At that time, the time out measages happned all in a row and ended on their own. Now Bluesky and CSS match. Took a screen capture of this (second attachment). I have olog entries of these. Search "crazyenergy" in olog (commissioning).

This has happened to @cmazzoli a few times as well. I am not sure how he resolved it.

In [165]: mov(pgm_en,927)

   pgm_en             

/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/epics/ca.py:1245: UserWarning: ca.get('XF:23ID1-OP{Mono-Ax:MirP}Mtr.TDIR') timed out after 1.00 seconds.
  warnings.warn(msg % (name(chid), timeout))
/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/epics/ca.py:1245: UserWarning: ca.get('XF:23ID1-OP{Mono-Ax:MirP}Mtr.HLS') timed out after 1.00 seconds.
  warnings.warn(msg % (name(chid), timeout))
/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/epics/ca.py:1245: UserWarning: ca.get('XF:23ID1-OP{Mono-Ax:GrtP}Mtr.TDIR') timed out after 1.00 seconds.
  warnings.warn(msg % (name(chid), timeout))
/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/epics/ca.py:1432: UserWarning: ca.get_ctrlvars('XF:23ID1-OP{Mono}Enrgy-SP') timed out after 5.00 seconds.
  warnings.warn(msg % (name(chid), timeout))
/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/epics/ca.py:1245: UserWarning: ca.get('XF:23ID1-OP{Mono-Ax:GrtP}Mtr.HLS') timed out after 1.00 seconds.
  warnings.warn(msg % (name(chid), timeout))
^C[!!] ABORTED : Commanding all positioners to stop.
^C---------------------------------------------------------------------------
KeyboardInterrupt                         Traceback (most recent call last)
/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/ophyd/commands.py in catch_keyboard_interrupt(positioners)
    716     try:
--> 717         yield
    718     except KeyboardInterrupt:

/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/ophyd/commands.py in mov(positioner, position)
    219         stat = [p.move(v, wait=False) for p, v in
--> 220                 zip(positioner, position)]
    221 

/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/ophyd/commands.py in <listcomp>(.0)
    218     with catch_keyboard_interrupt(positioner):
--> 219         stat = [p.move(v, wait=False) for p, v in
    220                 zip(positioner, position)]

/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/ophyd/pv_positioner.py in move(self, position, wait, timeout, moved_cb)
    188         '''
--> 189         status = super().move(position, timeout=timeout, moved_cb=moved_cb)
    190 

/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/ophyd/positioner.py in move(self, position, moved_cb, timeout)
    114 
--> 115         self.check_value(position)
    116 

/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/ophyd/pv_positioner.py in check_value(self, pos)
    127         if self.limits is not None:
--> 128             low, high = self.limits
    129             if low != high and not (low <= pos <= high):

/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/ophyd/pv_positioner.py in limits(self)
    250         else:
--> 251             return self.setpoint.limits
    252 

/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/ophyd/utils/epics_pvs.py in wrapper(self, *args, **kwargs)
    340         if self.connected:
--> 341             return fcn(self, *args, **kwargs)
    342         else:

/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/ophyd/signal.py in limits(self)
    716         pv = self._write_pv
--> 717         pv.get_ctrlvars()
    718         return (pv.lower_ctrl_limit, pv.upper_ctrl_limit)

/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/epics/pv.py in get_ctrlvars(self, timeout, warn)
    424             return None
--> 425         kwds = ca.get_ctrlvars(self.chid, timeout=timeout, warn=warn)
    426         self._args.update(kwds)

/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/epics/ca.py in wrapper(*args, **kwds)
    415 
--> 416         return fcn(*args, **kwds)
    417     wrapper.__doc__ = fcn.__doc__

/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/epics/ca.py in get_ctrlvars(chid, timeout, warn)
   1427     while ncache['ctrl_value'] is GET_PENDING:
-> 1428         poll()
   1429         if time.time()-t0 > timeout:

/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/epics/ca.py in wrapper(*args, **kwds)
    359             initialize_libca()
--> 360         return fcn(*args, **kwds)
    361     wrapper.__doc__ = fcn.__doc__

/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/epics/ca.py in poll(evt, iot)
    765     pend_event(evt)
--> 766     return pend_io(iot)
    767 

/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/epics/ca.py in wrapper(*args, **kwds)
    357         global libca
--> 358         if libca is None:
    359             initialize_libca()

KeyboardInterrupt: 

During handling of the above exception, another exception occurred:

KeyboardInterrupt                         Traceback (most recent call last)
<ipython-input-165-1065f75a331e> in <module>()
----> 1 mov(pgm_en,927)

/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/ophyd/commands.py in wrapper(*args, **kwargs)
    169                                     'an instance of {}'.format(n, t))
    170 
--> 171             f(*args, **kwargs)
    172         return wrapper
    173     return wrap

/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/ophyd/commands.py in mov(positioner, position)
    235             done = all(s.done for s in stat)
    236             if done:
--> 237                 flag += 1
    238 
    239     print(tc.Normal + '\n')

/home/xf23id1/conda_envs/collection/lib/python3.4/contextlib.py in __exit__(self, type, value, traceback)
     75                 value = type()
     76             try:
---> 77                 self.gen.throw(type, value, traceback)
     78                 raise RuntimeError("generator didn't stop after throw()")
     79             except StopIteration as exc:

/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/ophyd/commands.py in catch_keyboard_interrupt(positioners)
    720               ": Commanding all positioners to stop.")
    721         for p in positioners:
--> 722             p.stop()
    723             print("{}[--] Stopping {}{}".format(tc.Red, tc.LightRed, p.name))
    724         print(tc.Normal, end='')

/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/ophyd/pv_positioner.py in stop(self)
    235     def stop(self):
    236         if self.stop_signal is not None:
--> 237             self.stop_signal.put(self.stop_value, wait=False)
    238         super().stop()
    239 

/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/ophyd/signal.py in put(self, value, force, **kwargs)
    800             self._run_subs(sub_type=self.SUB_SETPOINT,
    801                            old_value=old_value, value=value,
--> 802                            timestamp=self.timestamp, **kwargs)
    803 
    804     def set(self, value, *, timeout=None, settle_time=None):

/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/ophyd/utils/epics_pvs.py in wrapper(self, *args, **kwargs)
    339     def wrapper(self, *args, **kwargs):
    340         if self.connected:
--> 341             return fcn(self, *args, **kwargs)
    342         else:
    343             raise DisconnectedError('{} is not connected'.format(self.name))

/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/ophyd/signal.py in timestamp(self)
    423         if not self._read_pv.auto_monitor:
    424             # force updating the timestamp when not using auto monitoring
--> 425             self._read_pv.get_timevars()
    426         return self._read_pv.timestamp
    427 

/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/epics/pv.py in get_timevars(self, timeout, warn)
    431         if not self.wait_for_connection():
    432             return None
--> 433         kwds = ca.get_timevars(self.chid, timeout=timeout, warn=warn)
    434         self._args.update(kwds)
    435         return kwds

/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/epics/ca.py in wrapper(*args, **kwds)
    414                                                         name(chid), timeout))
    415 
--> 416         return fcn(*args, **kwds)
    417     wrapper.__doc__ = fcn.__doc__
    418     wrapper.__name__ = fcn.__name__

/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/epics/ca.py in get_timevars(chid, timeout, warn)
   1477     t0 = time.time()
   1478     while ncache['time_value'] is GET_PENDING:
-> 1479         poll()
   1480         if time.time()-t0 > timeout:
   1481             if warn:

/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/epics/ca.py in wrapper(*args, **kwds)
    358         if libca is None:
    359             initialize_libca()
--> 360         return fcn(*args, **kwds)
    361     wrapper.__doc__ = fcn.__doc__
    362     wrapper.__name__ = fcn.__name__

/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/epics/ca.py in poll(evt, iot)
    763 
    764     """
--> 765     pend_event(evt)
    766     return pend_io(iot)
    767 

/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/epics/ca.py in pend_event(timeout)
    750 def pend_event(timeout=1.e-5):
    751     """polls CA for events """
--> 752     ret = libca.ca_pend_event(timeout)
    753     try:
    754         return PySEVCHK( 'pend_event', ret,  dbr.ECA_TIMEOUT)

KeyboardInterrupt: 

In [166]: mov(pgm_en,928)

   pgm_en             

/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/epics/ca.py:1245: UserWarning: ca.get('XF:23ID1-OP{Mono-Ax:MirP}Mtr.TDIR') timed out after 1.00 seconds.
  warnings.warn(msg % (name(chid), timeout))
/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/epics/ca.py:1245: UserWarning: ca.get('XF:23ID1-OP{Mono-Ax:MirP}Mtr.HLS') timed out after 1.00 seconds.
  warnings.warn(msg % (name(chid), timeout))
/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/epics/ca.py:1245: UserWarning: ca.get('XF:23ID1-OP{Mono-Ax:GrtP}Mtr.TDIR') timed out after 1.00 seconds.
  warnings.warn(msg % (name(chid), timeout))
/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/epics/ca.py:1245: UserWarning: ca.get('XF:23ID1-OP{Mono-Ax:GrtP}Mtr.HLS') timed out after 1.00 seconds.
  warnings.warn(msg % (name(chid), timeout))
/home/xf23id1/conda_envs/collection/lib/python3.4/site-packages/epics/ca.py:1483: UserWarning: ca.get_timevars('XF:23ID1-OP{Mono}Enrgy-SP') timed out after 5.00 seconds.
  warnings.warn(msg % (name(chid), timeout))
    860.949522         

t
In [167]: wh_pos(pgm_energy)
---------------------------------------------------------------------------
NameError                                 Traceback (most recent call last)
<ipython-input-167-5e643d417d26> in <module>()
----> 1 wh_pos(pgm_energy)

NameError: name 'pgm_energy' is not defined

In [168]: wh_pos(pgm_en)

+------------+-----------+-----------+------------+
| Positioner |     Value | Low Limit | High Limit |
+------------+-----------+-----------+------------+
| pgm_en     | 928.01865 | 200.00000 | 2000.00000 |
+------------+-----------+-----------+------------+

In [169]: mov(pgm_en,927)

   pgm_en             

    926.978116        

In [170]: mov(pgm_en,gs.PS.max[0]-1.4)

   pgm_en             

    927.483237        

In [171]:
tacaswell commented 8 years ago

attn @klauer @stuwilkins this look the issue is in ophyd.commands.mov and/or the IOC that is running the mono.

When you are using mov you are not using the runengine at all (which is why ^C does not quite work as expected and abort is always raising that the runegine is in a paused state).

You should probaly be writting this as:

def CuEscan():
    # I assume this just turns on the active feedback loop?
    MonoClosedLoop()
    yield from bp.sleep(1)
    yield from ascan(pgm_en,920,960,40, md={'plan_name':'CuEscan'})
    yield from bp.abs_set(pgm_en, gs.PS.max[0]-1.4, wait=True)
    yield from bp.sleep(2)

RE(CuEscan())
ambarb commented 8 years ago

I like what you did with md. Are you saying that I can ^C if I write the definition in the way you propose or is this the way you would write it?

From: Thomas A Caswell [notifications@github.com] Sent: Sunday, June 05, 2016 1:42 PM To: NSLS-II/Bug-Reports Cc: Barbour, Andi; Author Subject: Re: [NSLS-II/Bug-Reports] Killing motion because gs.PS issue with mov() and the problems it caused. Bluesky and CSS report different pgm_en. (#113)

attn @klauerhttps://github.com/klauer @stuwilkinshttps://github.com/stuwilkins this look the issue is in ophyd.commands.mov and/or the IOC that is running the mono.

When you are using mov you are not using the runengine at all (which is why ^C does not quite work as expected and abort is always raising that the runegine is in a paused state).

You should probaly be writting this as:

def CuEscan():

I assume this just turns on the active feedback loop?

MonoClosedLoop()
yield from bp.sleep(1)
yield from ascan(pgm_en,920,960,40, md={'scantype':'CuEscan'})
yield from bp.abs_set(pgm_en, gs.PS.max[0]-1.4, wait=True)
yield from bp.sleep(2)

RE(CuEscan())

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHubhttps://github.com/NSLS-II/Bug-Reports/issues/113#issuecomment-223826510, or mute the threadhttps://github.com/notifications/unsubscribe/AM_7GaUWtLZl6q3UTSu0lV9b6eN_MJD5ks5qIwptgaJpZM4IuRtD.

tacaswell commented 8 years ago

^C will behave in a more consistent way this way, but I strongly suspect that the IOC that is running your mono is having issues (which is the source of all of those user warnings) and things at the ophyd/bs layer are not doing a good enough job coping with the hardware not operating properly.

klauer commented 8 years ago

I'm more inclined to believe this is a pyepics poor cache handling-related issue masquerading as a timeout error. I wish we had something repeatable to test, as I don't really see anything in this report I can use...