sardana-org / sardana

Moved to GitLab: https://gitlab.com/sardana-org/sardana
39 stars 52 forks source link

Pseudocounter in fly scan #1287

Open kklmn opened 4 years ago

kklmn commented 4 years ago

Hello,

We want to implement dead time correction for our 7-element fluorescence detector. We get 7 channels of ROI sums and 7 channels (from another controller) of dead time corrections. We have a pseudocounter that does the multiplication of them. In step scanning the pseudocounters work. In fly scanning they produce nans, although the contributing physical counters do have proper data.

It seems that pseudocounters are not prepared for fly scanning. Are they?

Could you please advise the best approach to create a channel that is a product of two other existing channels?

Thank you!

reszelaz commented 4 years ago

Hi Konstantin,

Pseudocounters which are base on other channels are supported in continuous scans. Pseudocounters which are not based on other channels i.e. just implement the calc method, are not supported yet.

But to be honest you must be the first one trying to use them. When implementing this we have just tested it on a very simple example: https://github.com/sardana-org/sardana/blob/049b4bfb645c6027f3fd0a5461019911d15b9a63/src/sardana/pool/poolcontrollers/IoverI0.py#L34 So, maybe you are hitting a bug?

I just tested it again on IoverI0 and they work:

# using software trigger synchronization

Door_zreszela_1 [5]: ct
Wed Feb 12 09:44:55 2020

     ct01  =         1.0
     ct02  =         2.0
  ioveri0  =         0.5

Door_zreszela_1 [6]: ascanct mot01 0 10 10 0.1
Operation will be saved in /tmp/test.h5 (HDF5::NXscan from NXscanH5_FileRecorder)
Scan #37 started at Wed Feb 12 09:45:20 2020. It will take at least 0:00:00
 #Pt No    mot01      ct01      ct02    ioveri0      dt   
Motor positions and relative timestamp (dt) columns contains theoretical values
   0         0        0.1       0.2       0.5        2    
   1         1        nan       nan       nan       2.1   
   2         2        nan       nan       nan       2.2   
   3         3        0.1       0.2       0.5       2.3   
   4         4        nan       nan       nan       2.4   
   5         5        0.1       0.2       0.5       2.5   
   6         6        nan       nan       nan       2.6   
   7         7        0.1       0.2       0.5       2.7   
   8         8        nan       nan       nan       2.8   
   9         9        nan       nan       nan       2.9   
   10        10       0.1       0.2       0.5        3    
Correcting overshoot...
Operation saved in /tmp/test.h5 (HDF5::NXscan)
Scan #37 ended at Wed Feb 12 09:45:28 2020, taking 0:00:08.583786. Dead time 100.0% (motion dead time 100.0%)

# using hardware trigger synchronization

Door_zreszela_1 [8]: ascanct mot01 0 10 10 0.1
Operation will be saved in /tmp/test.h5 (HDF5::NXscan from NXscanH5_FileRecorder)
Scan #38 started at Wed Feb 12 09:46:02 2020. It will take at least 0:00:00
 #Pt No    mot01      ct01      ct02    ioveri0      dt   
Motor positions and relative timestamp (dt) columns contains theoretical values
   0         0        0.1       0.2       0.5        2    
   1         1        0.1       0.2       0.5       2.1   
   2         2        0.1       0.2       0.5       2.2   
   3         3        0.1       0.2       0.5       2.3   
   4         4        0.1       0.2       0.5       2.4   
   5         5        0.1       0.2       0.5       2.5   
   6         6        0.1       0.2       0.5       2.6   
   7         7        0.1       0.2       0.5       2.7   
   8         8        0.1       0.2       0.5       2.8   
   9         9        0.1       0.2       0.5       2.9   
   10        10       0.1       0.2       0.5        3    
Correcting overshoot...
Operation saved in /tmp/test.h5 (HDF5::NXscan)
Scan #38 ended at Wed Feb 12 09:46:10 2020, taking 0:00:07.494845. Dead time 100.0% (motion dead time 100.0%)

To start diagnosing your problem I have few questions:

Thanks a lot!

kklmn commented 4 years ago

Hi Zibi,

Thanks for your reply!

We are now looking at the pseudocounter again, and probably the problem is not with it but rather with our understanding of timers in Sardana controllers.

Our pseudocounter followed an example with slits and it does work in step scan. Here it is attached (made by Juliano). Xspress3DeadTimeCorrection.txt

In fly scan:

a) By software triggering, same as in your test: where the real counters are not nan, the pseudocounter is also not nan. And also there are nans in the real counters. The values are displayed during the scan.

b) By hardware triggering we have no nans in the real counters but the pseutocounter is always nan. The values are only displayed after the scan. No error messages.

In our test measurement group we have two real counters but they are from two different controllers. Q1: Can this be a problem? One of them has 'counter' as the first channel (and this one is put as the 1st item in the mntgrp), the other controller (roi from a lima image) doesn't have a special 'counter' channel. Q2: Can this be a problem?

The Pool/Macro server logs are huge and therefore hardly usable. They have many errors from missing devices, most of the messages are icepap related. The dirty logs were my main reason to wish for cleanups at Balder's Sardana, which I wrote to you in another mail.

Thank you again! Konstantin

reszelaz commented 4 years ago

Hi Konstantin, I just tested your controller with 8 channels from one counter/timer controller and 8 from another counter/timer controller. And it works:

Door_zreszela_1 [4]: defctrl Xspress3DeadTimeCorrection xpress3dtcctrl ch1_roi=ct01 ch1_dtc=ct31 ch2_roi=ct02 ch2_dtc=ct32 ch3_roi=ct03 ch3_dtc=ct33 ch4_roi=ct04 ch4_dtc=ct
                ...: 34 ch5_roi=ct05 ch5_dtc=ct35 ch6_roi=ct06 ch6_dtc=ct36 ch7_roi=ct07 ch7_dtc=ct37 ch8_roi=ct08 ch8_dtc=ct38 ret1=ch1_roi ret2=ch2_roi ret3=ch3_roi ret4=
                ...: ch4_roi ret5=ch5_roi ret6=ch6_roi ret7=ch7_roi ret8=ch8_roi
Created xpress3dtcctrl

Door_zreszela_1 [6]: ascanct mot01 0 10 10 0.1
Operation will be saved in /tmp/test.h5 (HDF5::NXscan from NXscanH5_FileRecorder)
Scan #43 started at Mon Feb 17 17:29:47 2020. It will take at least 0:00:00
 #Pt No    mot01      ct01      ct02      ct03      ct04      ct05      ct06      ct07      ct08      ct31      ct32      ct33      ct34      ct35      ct36      ct37      ct38    ch1_roi   ch2_roi   ch3_roi   ch4_roi   ch5_roi   ch6_roi   ch7_roi   ch8_roi      dt   
Motor positions and relative timestamp (dt) columns contains theoretical values
   0         0        0.1       0.2       0.3       0.4       0.5       0.6       0.7       0.8       0.1       0.2       0.3       0.4       0.5       0.6       0.7       0.8       0.01      0.04      0.09      0.16      0.25      0.36      0.49      0.64       2    
   1         1        0.1       0.2       0.3       0.4       0.5       0.6       0.7       0.8       0.1       0.2       0.3       0.4       0.5       0.6       0.7       0.8       0.01      0.04      0.09      0.16      0.25      0.36      0.49      0.64      2.1   
   2         2        0.1       0.2       0.3       0.4       0.5       0.6       0.7       0.8       0.1       0.2       0.3       0.4       0.5       0.6       0.7       0.8       0.01      0.04      0.09      0.16      0.25      0.36      0.49      0.64      2.2   
   3         3        0.1       0.2       0.3       0.4       0.5       0.6       0.7       0.8       0.1       0.2       0.3       0.4       0.5       0.6       0.7       0.8       0.01      0.04      0.09      0.16      0.25      0.36      0.49      0.64      2.3   
   4         4        0.1       0.2       0.3       0.4       0.5       0.6       0.7       0.8       0.1       0.2       0.3       0.4       0.5       0.6       0.7       0.8       0.01      0.04      0.09      0.16      0.25      0.36      0.49      0.64      2.4   
   5         5        0.1       0.2       0.3       0.4       0.5       0.6       0.7       0.8       0.1       0.2       0.3       0.4       0.5       0.6       0.7       0.8       0.01      0.04      0.09      0.16      0.25      0.36      0.49      0.64      2.5   
   6         6        0.1       0.2       0.3       0.4       0.5       0.6       0.7       0.8       0.1       0.2       0.3       0.4       0.5       0.6       0.7       0.8       0.01      0.04      0.09      0.16      0.25      0.36      0.49      0.64      2.6   
   7         7        0.1       0.2       0.3       0.4       0.5       0.6       0.7       0.8       0.1       0.2       0.3       0.4       0.5       0.6       0.7       0.8       0.01      0.04      0.09      0.16      0.25      0.36      0.49      0.64      2.7   
   8         8        0.1       0.2       0.3       0.4       0.5       0.6       0.7       0.8       0.1       0.2       0.3       0.4       0.5       0.6       0.7       0.8       0.01      0.04      0.09      0.16      0.25      0.36      0.49      0.64      2.8   
   9         9        0.1       0.2       0.3       0.4       0.5       0.6       0.7       0.8       0.1       0.2       0.3       0.4       0.5       0.6       0.7       0.8       0.01      0.04      0.09      0.16      0.25      0.36      0.49      0.64      2.9   
   10        10       0.1       0.2       0.3       0.4       0.5       0.6       0.7       0.8       0.1       0.2       0.3       0.4       0.5       0.6       0.7       0.8       0.01      0.04      0.09      0.16      0.25      0.36      0.49      0.64       3    
Correcting overshoot...
Operation saved in /tmp/test.h5 (HDF5::NXscan)
Scan #43 ended at Mon Feb 17 17:29:57 2020, taking 0:00:09.720523. Dead time 100.0% (motion dead time 100.0%)

Hence Q1 answer - no it should not be a problem.

Can you please give more details:

One of them has 'counter' as the first channel (and this one is put as the 1st item in the mntgrp), the other controller (roi from a lima image) doesn't have a special 'counter' channel. Q2: Can this be a problem?

So, you have two controllers inheriting from CounterTimerController class? By 'counter' channel, you mean a channel which is just used for passing the integration time and which return integration time as result? We call them timer channels.

The Pool/Macro server logs are huge and therefore hardly usable. They have many errors from missing devices, most of the messages are icepap related.

You can control this with the controller's LogLevel attribute (something like 10 - debug, 20 - output, 30 - ...) but then you may miss some relevant information in logs which sometimes may help in debugging..

kklmn commented 4 years ago

Hi Zibi,

We call them timer channels.

Yes, right, this was it. Just our experimental channel for timer was named counter.

So, you have two controllers inheriting from CounterTimerController class?

Yes, like this: ROIs: LimaRoICounterCtrl(CounterTimerController) Xspress3 counter and dead time: LimaXspress3CTCtrl(LimaCoTiCtrl) LimaCoTiCtrl(CounterTimerController)

Here is how the mntgrp is defined (as a print screen because I can't find a command for a similar console output; does it exist?): image

... the door output: doorOutput.txt

... and the log after one continuous energy scan (>11000 lines resulted by one scan!): log.zip

Thank you for looking at it!

reszelaz commented 4 years ago

My TODOs:

From the log file we can see recurrent exceptions:

EventTH.W001   ERROR    2020-02-18 09:35:40,365 EventTH.EventTH.W001: Uncaught exception running job 'set_attribute_push' called from thread SardanaTP.W005:
  File "/usr/lib64/python2.7/threading.py", line 785, in __bootstrap
    self.__bootstrap_inner()
  File "/usr/lib64/python2.7/threading.py", line 812, in __bootstrap_inner
    self.run()
  File "/usr/lib/python2.7/site-packages/taurus/core/util/threadpool.py", line 142, in run
    cmd(*args, **kw)
  File "/usr/lib/python2.7/site-packages/sardana/pool/poolaction.py", line 454, in _asynch_action_loop
    self.action_loop()
  File "/usr/lib/python2.7/site-packages/taurus/core/util/log.py", line 196, in wrapper
    ret = f(*args, **kwargs)
  File "/usr/lib/python2.7/site-packages/sardana/pool/poolacquisition.py", line 1027, in action_loop
    acquirable.extend_value_buffer(value)
  File "/usr/lib/python2.7/site-packages/sardana/pool/poolbasechannel.py", line 322, in extend_value_buffer
    val_attr.set_value(values[-1], propagate=propagate)
  File "/usr/lib/python2.7/site-packages/sardana/sardanaattribute.py", line 127, in set_value
    propagate=propagate)
  File "/usr/lib/python2.7/site-packages/sardana/sardanaattribute.py", line 136, in _set_value
    self.fire_read_event(propagate=propagate)
  File "/usr/lib/python2.7/site-packages/sardana/sardanaattribute.py", line 285, in fire_read_event
    self.fire_event(evt_type, self)
  File "/usr/lib/python2.7/site-packages/sardana/sardanaevent.py", line 110, in fire_event
    self._fire_event(event_type, event_value, listeners=listeners)
  File "/usr/lib/python2.7/site-packages/sardana/sardanaevent.py", line 132, in _fire_event
    real_listener(self, event_type, event_value)
  File "/usr/lib/python2.7/site-packages/sardana/pool/poolpseudocounter.py", line 200, in on_change
    self.fire_read_event(propagate=evt_type.priority)
  File "/usr/lib/python2.7/site-packages/sardana/sardanaattribute.py", line 285, in fire_read_event
    self.fire_event(evt_type, self)
  File "/usr/lib/python2.7/site-packages/sardana/sardanaevent.py", line 110, in fire_event
    self._fire_event(event_type, event_value, listeners=listeners)
  File "/usr/lib/python2.7/site-packages/sardana/sardanaevent.py", line 132, in _fire_event
    real_listener(self, event_type, event_value)
  File "/usr/lib/python2.7/site-packages/sardana/pool/poolbasechannel.py", line 212, in on_change
    self.fire_event(evt_type, evt_value)
  File "/usr/lib/python2.7/site-packages/sardana/sardanabase.py", line 131, in fire_event
    listeners=listeners)
  File "/usr/lib/python2.7/site-packages/sardana/sardanaevent.py", line 110, in fire_event
    self._fire_event(event_type, event_value, listeners=listeners)
  File "/usr/lib/python2.7/site-packages/sardana/sardanaevent.py", line 132, in _fire_event
    real_listener(self, event_type, event_value)
  File "/usr/lib/python2.7/site-packages/sardana/tango/pool/PseudoCounter.py", line 98, in on_pseudo_counter_changed
    event_value)
  File "/usr/lib/python2.7/site-packages/sardana/tango/pool/PseudoCounter.py", line 158, in _on_pseudo_counter_changed
    priority=priority, error=error, synch=False)
  File "/usr/lib/python2.7/site-packages/sardana/tango/core/SardanaDevice.py", line 317, in set_attribute
    priority=priority, synch=synch)
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/taurus/core/util/threadpool.py", line 142, in run
    cmd(*args, **kw)
  File "/usr/lib/python2.7/site-packages/sardana/tango/core/SardanaDevice.py", line 329, in set_attribute_push
    error=error, priority=priority)
  File "/usr/lib/python2.7/site-packages/sardana/tango/core/SardanaDevice.py", line 426, in _set_attribute_push
    self.push_change_event(*args)
TypeError: Expecting a numeric type, but it is not. If you use a numpy type instead of python core types, then it must exactly match (ex: numpy.int32 for PyTango.DevLong)

I think this could either come from the Calc result or from some problem of internal buffers manipulation.

To discard the first one could you slightly modify the Calc method to log the values, sth like this:

    def Calc(self,index, counter_values):
        """ Return the ROI value corrected by dead time for each channel. """
        self._log.debug("Calc receives {} ({})".format(counter_values, type(counter_values)))
        ch1_roi, ch1_dtc, \
        ch2_roi, ch2_dtc, \
        ch3_roi, ch3_dtc, \
        ch4_roi, ch4_dtc, \
        ch5_roi, ch5_dtc, \
        ch6_roi, ch6_dtc, \
        ch7_roi, ch7_dtc, \
        ch8_roi, ch8_dtc = counter_values

        if index == 1:
            value = ch1_roi*ch1_dtc
        elif index == 2:
            value = ch2_roi*ch2_dtc
        elif index == 3:
            value = ch3_roi*ch3_dtc
        elif index == 4:
            value = ch4_roi*ch4_dtc
        elif index == 5:
            value = ch5_roi*ch5_dtc
        elif index == 6:
            value = ch6_roi*ch6_dtc
        elif index == 7:
            value = ch7_roi*ch7_dtc
        elif index == 8:
            value = ch8_roi*ch8_dtc
        self._log.debug("Calc returns {} ({})".format(value, type(value)))
        return value

and post back the new log file?

Thanks!

reszelaz commented 4 years ago

To discard the first one could you slightly modify the Calc method to log the values, sth like this:

Also types may be interesting, so sth like this:

self._log.debug("Calc receives {} ({})".format(counter_values, type(counter_values)))
self._log.debug("Calc returns {} ({})".format(value, type(value)))
kklmn commented 4 years ago

this one is with Calc logs: log.zip

reszelaz commented 4 years ago

Thanks!

I think the problem comes from the fact that you defined one controller class with all the channels (counters) and pseudo counters. So, in the case of this definitiion ret1 also depend on ch2_roi, ch2_dtc, ch3_roi, etc.. While in the reality the ret1 only depends on ch1_roi, ch1_dtc. This leads to unnecessary calculations and exceptions in the case when not all the channels are present in the measurement group (your case). If you add all to the measurement group this works but still there are unnecessary calculations...

I propose that you rewrite the pseudo controller class so it serves only for one pseudo axis, similarly to IoverI0 and then define 8 instances of this class in your Pool. Then you will be able to use them independently.

The above explanation may be easier to follow on the example of pseudo motors. For example, in the case of slits, we have one controller with two motors and two pseudo motors cause change of any blade causes changes in both pseudos: gap and offset. Similarly for a three-leg table we have one controller with 3 motors and 3 pseudo motors and changes of any of the jacks causes changes in all three pseudos: z, pitch and roll.

Please let me know if this worked for you.

Also, I think we need to add this to the documentation and change the XBPMPseudoCounterController controller example, where top and bottom changes should not trigger horizontal calculation.