Hi @cyril.guilloud,
I put the log files in /tmp_14_days/bm32/
The log refers to scans launced on lbm32bliss, session 'gmt'.
The command was a dnscan on 6 axis (2 'normal' axis (hm, tri) plus 4 pseudos (mh1, vo1, mh2, vo2) moving in total 10 reals), all on iced326.
We also have the errors on others sessions, controllers, and on scans on less axis.
For information we replace the call to ?FSTATUS by ?STATUS in icepap state method and we did'nt observe (so far) the error anymore.
Lucio
Since the update to Bliss 2.0 (and at the same time switch to a new (faster?) control PC and firmware upgrade on icepas....) we start observing on BM32 some non-systemetic errors during scans on motors controlled by icepaps. Error message is :
"Cannot move axis 22: Axis is not ready (check http://wikiserv.esrf.fr/bliss/index.php/ICETIPS) command sent was: b'MOVE'".
We got a full debug log on an error, and it looks like the first status query (made with ?FSTATUS) after a MOVE command arrives before the state register on the master is set to moving. The motion is hence supposed as done, and if the next MOVE can eventually be sent when the axis is not yet ready.
From the log:
36,892 Icepap_d9e.Command DEBUG : write bytes=112 b'#MOVE GROUP 22 31342 28 -5 1 1006 2 -833 11 -1019 12 7624 13 7630 15 288082 16 740260 17 746065 5 42784 6 64851\n'
36,900 Icepap_d9e.Command DEBUG : readline bytes=7 b'MOVE OK'
36,901 Icepap_d9e.Command DEBUG : write bytes=12 b'?FSTATUS 22\n'
36,901 Icepap_d9e.Command DEBUG : write bytes=12 b'?FSTATUS 28\n'
.
.
.
36,902 Icepap_d9e.Command DEBUG : readline bytes=19 b'?FSTATUS 0x00A01203'
36,903 Icepap_d9e.Command DEBUG : readline bytes=19 b'?FSTATUS 0x00A00403'
....
The status code for axis 22 in the master register (0x00A01203) is still set as READY, so the motion is considered ad done and the status for this axis is not polled anymore, while the other axis (which are in MOVING state) do their job.
At the end of the previous movement a new MOVE is sent (in this case a backslash on some axis, including axis 22 which in reality is still moving) and we got the error:
45,392 Icepap_d9e.Command DEBUG : write bytes=36 b'#MOVE GROUP 22 31542 1 1056 5 41784\n'
45,396 Icepap_d9e.Command DEBUG : readline bytes=49 b'MOVE ERROR Cannot move axis 22: Axis is not ready'
45,397 Icepap_d9e.Command DEBUG : write bytes=12 b'STOP 22 1 5\n'
45,397 Icepap_d9e.Command DEBUG : write bytes=12 b'?FSTATUS 22\n'
45,397 Icepap_d9e.Command DEBUG : write bytes=11 b'?FSTATUS 1\n'
45,398 Icepap_d9e.Command DEBUG : write bytes=11 b'?FSTATUS 5\n'
45,431 Icepap_d9e.Command DEBUG : readline bytes=19 b'?FSTATUS 0x00A05403'
....
Note the status for axis 22 is 0x00A05403, so the axis were MOVING.
Would it be possible to force the synchronization of the master status registers after a MOVE command, or eventually use for the first query after the MOVE command ?STATUS instead of ?FSTATUS ?
If you need the full log file I can send it.
We observed a related problem on BM32 (on bliss 2.0.x):
After the scan on a pseudo (e.g slit offset) the other pseudo related to the same reals (slit gap) CHANGES, even if the controller don't say it:
GMT [77]: wm(vg2,vo2,*vg2.controller.reals)
vg2 vo2 su2 sd2
-------- ------ ------ ------- --------
User
High inf inf -inf -inf
Current 4.5000 2.0360 4.28597 0.21403
Low -inf -inf inf inf
Offset 0.0000 0.0000 8.78256 11.19652Dial
High inf inf inf inf
Current 4.5000 2.0360 4.49660 10.98249
Low -inf -inf -inf -inf
GMT [78]: dscan(vo2,0,2,3,0.1,monopt1)
GMT [79]: wm(vg2,vo2,*vg2.controller.reals)
vg2 vo2 su2 sd2
-------- ------ ------ ------- --------
User
High inf inf -inf -inf
Current 4.5000 2.0360 4.28597 0.21403
Low -inf -inf inf inf
Offset 0.0000 0.0000 8.78256 11.19652Dial
High inf inf inf inf
Current 4.5000 2.0360 4.49660 10.98249
Low -inf -inf -inf -inf
If at this point we call for a '0 motion', the reals move:
GMT [80]: umvr(vo2,0)
Moving vo2 from 2.0360 to 3.6198
vo2 su2 sd2
user 3.6197 4.28597 -2.95351
dial 3.6197 4.49660 14.15003
doing a "vo2.sync_hard()" after the scan avoid the problem.....
br
should use mv()
(printing from to )
ubr
should use umv()
(printing from to + positions update)
hscan
does not refresh scan line properly (line is duplicated instead of refreshed)
We observed on BM32 runtime errors due to a discrepancy on IcePap axes after a call to reset_closed_loop.
After some investigations we identified the origin of the problem: the sync_hard (on axis controlled by IcePaps) method get the current position using the ?FPOS command. For axes with 'autopower' set to False the call to sync_hard happens just after the set_position, and the position given by FPOS is not always updated to the new value.
We found the old delault informations provided by tqdm more pertinent for "standard" scans (providing the remaining time and the frame rate). Also, we suggest to add the information "infinite scan" based on the npoint and not the type of scan (it is possible to start a loopscan with npoints = 0).
We propose the following modifications on bliss/shell/data/display.py. Modifications are labeled as comments # BM32 - ...
class StepScanProgress(ScanProgress):
def __init__(self, tracked_channels=None, output=None):
super().__init__(tracked_channels)
self._output = output
def scan_new_callback(self):
npoints = self.scan_info["npoints"]
count_time = self.scan_info.get("count_time", 0.2)
if count_time == 0:
count_time = 0.2
fps = 1 / count_time
#if self.scan_type == "timescan": # infinite
if npoints == 0 : # BM32 - infinite scan based on npoints
total = 0
bar_format = " ===> Running infinite scan <=== (abort with Ctrl-c) [elapsed time {elapsed_s:.1f} s] "
elif self.scan_type == "ct": # based on count_time
total = count_time
self.__start = time.time()
self.__prev = self.__start
self.__end = self.__start + total
bar_format = (
"{l_bar}{bar} (abort with Ctrl-c) [elapsed time {elapsed_s:.1f} s] "
)
self._scan_renderer = ScanRenderer(self.scan_info)
fps = 10 / count_time
self._tracked_channels = (
"all" # listen all scan channels in order to display ct output
)
else: # based on npoints
self.__prev = 0
total = npoints
# bar_format = (
# "{l_bar}{bar} (abort with Ctrl-c) [elapsed time {elapsed_s:.1f}] "
# ) # bliss new format
bar_format = (
"{l_bar}{bar} [elapsed {elapsed_s:.1f} - remaining {remaining_s:.1f} s - {rate_fmt}] "
) # BM32 format
fps = max(1, fps)
self._frame_rate = min(10, fps)
self.__progress_bar = tqdm(
total=total,
unit_scale=True,
leave=False,
ascii=False,
bar_format=bar_format,
dynamic_ncols=True,
file=self._output, # stderr by default
)
def scan_end_callback(self):
self.__progress_bar.clear()
self.__progress_bar.close()
self.__progress_bar = None
if self.scan_type == "ct":
self._scan_renderer.print_table_header()
self._scan_renderer.append_data(self._data_dict)
self._scan_renderer.print_data_ct(None)
def progress_callback(self):
now = time.time()
#if self.scan_type == "timescan":
if self.scan_info["npoints"] == 0: # BM32 - infinite scan based on npoints
incr = 1
elif self.scan_type == "ct":
if now <= self.__end:
incr = now - self.__prev
else:
incr = 0
else: # based on point number
if not self._scan._acq_chain.iterators:
# not yet initialized
return
now = (
self._scan._acq_chain.iterators[0].sequence_index + 1
) # step_by_step scan has only one top_master
incr = now - self.__prev
self.__progress_bar.update(incr)
self.__prev = now