pyrpl-fpga / pyrpl

pyrpl turns your RedPitaya into a powerful DSP device, especially suitable as a lockbox in quantum optics experiments.
http://lneuhaus.github.io/pyrpl/
MIT License
139 stars 110 forks source link

Reading from Red Pitaya occasionally use 300 ms instead of 3 ms #486

Open abregnsbo opened 2 years ago

abregnsbo commented 2 years ago

The p.rp.scope._reads() function to get scope data normally uses 1-3 ms, but occasionally uses 310 ms. I suspect similar large delay where PyRPL reads any register from Red Pitaya (RP).

Anybody knows what causes these large occasional delays ? and how to suppress them ?

Background: I have a Python loop that controls RP's and also need to empty a fifo every 10 ms to avoid overrun. However when the Python code includes code that retrieve scope data, the occasional 310 ms delay violate my required realtime response time.

Below code runs a tight loop for a specified duration, and registers the max time each loop iteration takes. This is repeated 10 times and the min and max value of the 10 max-delays are listed below. They are typical below 20 ms, but when reading scope data, some loop durations use 310 ms. This is the output when running on my Windows 10, HP ZBook Fury, PyCharm 2022:

# 0.1 sec 'scope': loop duration 3.3 - 319.4 ms
# 0.2 sec 'scope': loop duration 3.4 - 316.5 ms
# 1.0 sec 'scope': loop duration 7.9 - 315.1 ms

# 0.1 sec 'numpy': loop duration 1.1 - 7.0 ms
# 0.2 sec 'numpy': loop duration 1.1 - 1.5 ms
# 1.0 sec 'numpy': loop duration 1.2 - 1.5 ms
import time
import numpy as np
from pyrpl import Pyrpl

def test(run_time=1.0, op='np'):
    global p
    time_start = time.time()
    time_prev = time_start
    max_lat = 0.0
    while (time_prev - time_start < run_time):
        # doing calculations does not affect OS interrupt time. At one point I did observe calculations substantially
        # influence OS interrupt time, but that was due to test code was allocation memory while it executed.
        if op == 'numpy':
            # Max loop latency 20 ms
            np.linalg.det(np.random.rand(100,100))
        if op == 'scope':
            # Max loop latency jumps to 310 ms
            p.rp.scope._reads(0x10000, 10000)
        time_now = time.time()
        lat = 1000*(time_now - time_prev)
        if lat > max_lat:
            max_lat = lat
        time_prev = time_now
    return max_lat

def run(op='numpy', runs_per_rt=10):
    global p
    if 'p' not in globals() and op == 'scope':
        p = Pyrpl(hostname="rp-f09c46.local", config='latency', source=None)
    stats = []
    rt_lst = (0.1, 0.2, 1.0)
    for idx, rt in enumerate(rt_lst):
        print("%4.1f sec '%s': "%(rt, op), end='')
        stats.append([])
        for i in range(runs_per_rt):
            stats[idx].append( test(rt, op) )
        s = stats[idx]
        print("loop duration %.1f - %.1f ms"%(min(s),max(s)))

run(op='scope')
run(op='numpy')
SamuelDeleglise commented 2 years ago

Are you sure this has anything to do with windows 10 ? Was it really faster on some other OS (windows 7 ?) ? I am not so surprised that some TCPIP operations can be much longer than average. I have also noticed sometimes that in some networks, the refresh rate of the scope was quite erratic... usually, the problem can be solved by replacing the switch to which the redpitaya is plugged

abregnsbo commented 2 years ago

Not sure it is Windows 10 related, will try Linux. The Red Pitaya is connected directly to my laptop with an UTP cable, i.e. no Ethernet switch between my laptop and Red Pitaya. The sudden delay increase is mostly in the narrow interval 310 - 319 ms. My guess is that some well defined software process gets in the way.

abregnsbo commented 2 years ago

Have now tried on Linux Ubuntu 18.04.6 LTS. The real-time behavior is clearly better: no large 300 ms when running for 1 second. However, when increasing the runtime to 5 seconds I also see on Linux see sudden delay increases. However the delay increase are not constant 300 ms as in Windows 10, but different/random values.

# Reading 20k word from RP scope in each loop iteration. Each test run the loop for 1 or 5 seconds, and report the
# maximum single loop delay seen. Test is repeated 10 times and min and max values of these 10 max-delays are listed 
# below.

# Windows 10, pc connected directly to RP.
#
# 1.0 sec 'scope': loop duration 16.2 - 328.7 ms
# 1.0 sec 'scope': loop duration 16.3 - 317.1 ms
# 5.0 sec 'scope': loop duration 18.4 - 322.2 ms
# 5.0 sec 'scope': loop duration 17.4 - 320.1 ms
# 5.0 sec 'scope': loop duration 18.5 - 322.6 ms

# Linux Ubuntu, 18.04.6 LTS, pc connected to RP through unloaded Ethernet switch. When loop run time is only 1 sec, 
# the large delays are seldom seen.
#
# 5.0 sec 'scope': loop duration 4.9 - 36.0 ms
# 5.0 sec 'scope': loop duration 4.8 - 208.9 ms
# 5.0 sec 'scope': loop duration 4.8 - 5.5 ms
# 5.0 sec 'scope': loop duration 4.8 - 66.0 ms
# 5.0 sec 'scope': loop duration 4.9 - 152.6 ms