Significant differences in the performance of read requests from a Sardana MotorController DS and from PyTango DS
akessler avatar
AlexK
I have measured the read time of the position of a motor which is implemented as a child class of the Sardana MotorController. I have used %%timeit in a jupyter notebook. Although there is no communication with the HW, the query takes 6.8 msec, that is very slow in my opinion. In contrast, reading a double attribute of a pure PyTango DS takes only 0.25 msec.
is it normal behavior of Sardana or is something wrong in my setup?
I use Sardana 3.5.0 and PyTango 9.4.1 in a conda env on ubuntu 20.04.

How to reproduce:

mot = tango.DeviceProxy("mot_x")  #SARDANA Motor
—————-
%%timeit
mot.position

-> 6.79 ms ± 242 μs per loop (mean ± std. dev. of 7 runs, 100 loops each)

—————-

lvcam = tango.DeviceProxy("lv_test_cam")    # very simple pytango DS
—————
%%timeit
lvcam.timestamp_raw_image

-> 247 μs ± 68 μs per loop (mean ± std. dev. of 7 runs, 10,000 loops each)
avatar par défaut
Anton
Hi Alex

I tried the same thing, with Sardana and the other Tango device all running on the same computer. Timing from Spock. I also tried with a cppTango device server. I don't see much difference. The standard deviation is much lower with cppTango directly.


Door_local_1 [120]: %timeit mot01.position
127 μs ± 3.64 μs per loop (mean ± std. dev. of 7 runs, 1,000 loops each)

Door_local_1 [121]: %timeit mot01.position
138 μs ± 12.8 μs per loop (mean ± std. dev. of 7 runs, 1,000 loops each)

Door_local_1 [122]: %timeit mot01.position
162 μs ± 34.4 μs per loop (mean ± std. dev. of 7 runs, 1,000 loops each)

Door_local_1 [123]: %timeit mot01.position
148 μs ± 22.6 μs per loop (mean ± std. dev. of 7 runs, 1,000 loops each)

Door_local_1 [124]: %timeit mot01.position
142 μs ± 15.5 μs per loop (mean ± std. dev. of 7 runs, 1,000 loops each)

Door_local_1 [125]: cpptango_device = DeviceProxy("sys/tg_test/1")

Door_local_1 [126]: %timeit cpptango_device.double_scalar
128 μs ± 4.18 μs per loop (mean ± std. dev. of 7 runs, 10,000 loops each)

Door_local_1 [127]: %timeit cpptango_device.double_scalar
129 μs ± 2.23 μs per loop (mean ± std. dev. of 7 runs, 10,000 loops each)

Door_local_1 [128]: %timeit cpptango_device.double_scalar
126 μs ± 2.9 μs per loop (mean ± std. dev. of 7 runs, 10,000 loops each)

Door_local_1 [129]: pytango_device = DeviceProxy("train/ps/1")

Door_local_1 [130]: %timeit pytango_device.voltage
148 μs ± 3.75 μs per loop (mean ± std. dev. of 7 runs, 10,000 loops each)

Door_local_1 [131]: %timeit pytango_device.voltage
159 μs ± 19.4 μs per loop (mean ± std. dev. of 7 runs, 10,000 loops each)

Door_local_1 [132]: %timeit pytango_device.voltage
145 μs ± 5.61 μs per loop (mean ± std. dev. of 7 runs, 10,000 loops each)



Maybe there is a something else that is keeping your Sardana pool busy, and slowing down the responses from the motor?
akessler avatar
AlexK
Dear Anton,
Thank you for the quick reply. I observe the same behavior for Sardana Demo Motor. But for my MotorController it is much slower.


Door_playground_1 [42]: cpptango_device = DeviceProxy("sys/tg_test/1")

Door_playground_1 [43]: %timeit cpptango_device.double_scalar
The slowest run took 6.09 times longer than the fastest. This could mean that an intermediate result is being cached.
201 μs ± 149 μs per loop (mean ± std. dev. of 7 runs, 1,000 loops each)

Door_playground_1 [44]: %timeit cpptango_device.double_scalar
238 μs ± 46 μs per loop (mean ± std. dev. of 7 runs, 10,000 loops each)

Door_playground_1 [45]: %timeit mot01.position   # Sardana Demo Motor
821 μs ± 54.7 μs per loop (mean ± std. dev. of 7 runs, 1,000 loops each)

Door_playground_1 [46]: %timeit mot01.position   # Sardana Demo Motor
845 μs ± 73.3 μs per loop (mean ± std. dev. of 7 runs, 1,000 loops each)

Door_playground_1 [48]: %timeit myMotX.position  # MotorController <- OurHomeMadeController
6.54 ms ± 119 μs per loop (mean ± std. dev. of 7 runs, 100 loops each)

Door_playground_1 [49]: %timeit myMotX.position  # MotorController <- OurHomeMadeController
6.58 ms ± 130 μs per loop (mean ± std. dev. of 7 runs, 100 loops each)



I can't understand this, because in the ReadOne method I simply return a number just to be sure that there is no interaction with the hardware:


class HIJBahrmannSardanaController(MotorController):
    ctrl_properties =   {   'ip':{Type: str, Description: 'IP4 address of the Bahrmann SM controller', DefaultValue: '192.168.50.120'},
                            'port': {Type: int, Description: 'The port of the Bahrmann SM controller', DefaultValue: 5000 }
                        }

    axis_attributes = {
       …
       …
    }

    #———————————
    # SARDANA MotorController Inteface Methoden

    def __init__(self, inst, props, *args, **kwargs):
        super().__init__(inst, props, *args, **kwargs)
        try:
            self.sms = FSUBahrmannSMS(self.ip, self.port)
            print(f'Connected to Stepper Motor Controller at {self.ip} with serialnr: {self.sms.serial}')
        except Exception as e:
            # self.error_stream(e)  # xxx_stream funktioniert nicht, weil MotorController nicht von Device erbt…
            print(f"e")
   …
   …
   def ReadOne(self, axisNr):
        return 42.0
        # return self.sms.getPosition(axisNr) #BUT also here is no interaction with hardware, it is buffered
   …
   …


What could be the cause of this behavior?
avatar par défaut
Anton
Hi Alex

I tried with one of our custom motor controllers, also modified so ReadOne returns a fixed value. I noticed that reading position, also reads the state of the controller (so StateAll and StateOne get executed). That caused quite a delay, since Tango device it was connecting to was offline. After modifying the StateAll method to ignore the Tango device, the time per read dropped from about 1 millisecond to microseconds, similar to the dummy motor.

/Anton
akessler avatar
AlexK
Hello Anton,

thanks for the clarification. Indeed, mot.position triggers StateOne(). Why is this happening? According to this image in the Sardana docs, StartOne() should not be called. I am wondering, why should StateAll() (and ReadAll()) have an effect, because the implementation of Controller:StateAll is just “pass” and I did not override this method.
On the other hand, I wonder why StateOne() is not called when the motor controller is started.

That's what I want: StateOne() is called at startup and with a low repetition rate when the axis is stopped. When the axis is moving, StateOne() should be called frequently, that happens as expected. When I call mot.position, it should call ReadOne() use the cached value without HW access. Is it possible to achieve this behavior with a “pure” Sardana motor controller without interfacing a Tango DS?

A Q outside the topic: is in the Sardana MotorController class something like self.debug_stream() availiable? Can you give me a hint, which are the best practice how to debug sardana code?
Edited yesterday at 12h52
 
Register or login to create to post a reply.