Interrupt/Call-Back delayed every 1.3s due to Garbage Collection #19676
|
I have a fairly complex application, which is using the PIOs which generate interrupts at around 120Hz. The interrupt code is as small as possible and uses Every 1.3s I am seeing that there is a significant delay in the callback, occasionally this is delayed enough that it is not called until the time where the following callback would be. My code can detect and protect itself from this delay, but I am interested in finding the cause. I am using the USB core to communicate with PC over USB-Midi, but I don't know whether that is a factor... I am also using threading to run a 2nd task (on other core) to keep the FIFOs to the PIOs filled - not a huge task. Any places I should look. Scope capture shows the top trace, which is a debug-PIO, actioned at the start of each callback. Call back completes in good time (and upping the CPU clock does not improve situation), only the interrupt route messes with the scheduler or disables the interrupts. |
Replies: 6 comments 5 replies
|
After a bit of digging, I confirmed that this delay is the garbage-colletor running, it seems the USB stack is using up the heap every 1.3s and the collector automatic runs. I can force collection to happen often/early. Here the callback runs 4 times every frame (30fps), and I force collection during the 3rd (of the 4) callback... but this has a similar delaying action for the 4th callback. Speeding up processor helps, but is there other steps I can take? Forcing collection does prevent lost callbacks, so even this is an improvement. I'd be willing to re-build the MicroPython image if having a smaller (or more) granular heap would help. |
|
Maybe if I mess with these.... https://github.com/micropython/micropython/blob/master/py/mpconfig.h#L250 |
|
I do not know if you can you run the callback with |
|
The interrupts are set up with The ISR uses The callback AFTER the one which runs the As it stands code is working, and the 4ms delay should not break the system. |
|
If you call One idea would be to disable GC. This should ensure that Failing that you might look at optimisation: reducing allocations, speeding all code that is triggered by the interrupt... |
|
I had cropped of the timing marks on the scope plot I posted, I can try disabling the automatic collections, using only the forced ones, and see if that makes any improvement. The posted scope plot is with 180MHz CPU and shows the force collection as a wide pulse on D2, the falling edge(s) of D3 are when the interrupts are called. With 240MHz CPU (can only use specific value due to project's requirements) speeds up the collection so that it completes faster (ie before the next IRQ), but I still see the delay. |
Probably the best thing you can do here is rewrite these parts of your code to not allocate as frequently. If you're using the micropython-lib usb-midi-device then this part shouldn't allocate too much, although there might be some allocation inside the library that's not obvious. Are you able to post the code you're using? The other thing you can do instead (or as well as) manual calls to |
No doubt I can (and probably should) sweep the code for 'wasteful' allocs. I printed out the available heap as the code counted the video frames. It looks like the consumption rate is ~4k per frame, which in turn is doing 4 callbacks and issuing 4 USB packets (each of 2 bytes of USB-midi data) to host PC.
The whole code base is on GitHub, specifically the callback code is: Assembling and sending the 'short packet' is: |
|
Actually, it seems that the frequency at which gc is called doesn't matter that much. In #!/micropython
# vim: fileencoding=utf-8: ts=4: sw=4: expandtab:
# Standard RP2040 @126MHz
# MicroPython v1.28.0 on 2026-04-06; Raspberry Pi Pico with RP2040
import gc
from time import ticks_us, ticks_diff
def gc_timing1():
min_ = 9e9
max_ = 0
sum_ = 0
for n in range(1000):
free1 = gc.mem_free()
t0 = ticks_us()
gc.collect()
t1 = ticks_us()
free2 = gc.mem_free()
td = ticks_diff(t1,t0)
min_,max_ = min(min_,td),max(max_,td)
sum_ += td
print(f'Freed:{free2-free1:5} B in {td:6} µs ({min_} |{round(sum_/(n+1))}| {max_})')
def gc_timing2():
CHUNK = 100 # in bytes
KEEP = 500 # max list length
min_ = 9e9
max_ = 0
sum_ = 0
z = [bytearray(CHUNK) for _ in range(KEEP)] # prefill
for n in range(1000):
z.pop(0)
z.append(bytearray(CHUNK))
free1 = gc.mem_free()
t0 = ticks_us()
gc.collect()
t1 = ticks_us()
free2 = gc.mem_free()
td = ticks_diff(t1,t0)
min_,max_ = min(min_,td),max(max_,td)
sum_ += td
print(f'Freed:{free2-free1:5} B in {td:6} µs ({min_} |{round(sum_/(n+1))}| {max_})')
# gc_timing1() # ~480 µs
gc_timing2() # ~12000 µs / ~10000µs swapped |
That makes sense, if there's a lot of memory allocated then the gc scan will always take some time. There are some early stage efforts to mark buffers which are pure data so that they can be skipped by the gc scan pass, see #19367 |
|
I've noted this as the answer, and look forward to it being in 'main' ;-) Where I've got to with the other suggestions is actually pretty good; I've tidied the code a bit, and disabled automatic GC during the time I have an active USB connection to PC. Then I force the This collection takes ~8ms (when CPU is clocked at 240MHz) and results in an additional 0.9ms delay to the 4th quarter USB packet (or the sending into the USB stack). Any additional time saving on the GC will only make this better.... 
|
That makes sense, if there's a lot of memory allocated then the gc scan will always take some time.
There are some early stage efforts to mark buffers which are pure data so that they can be skipped by the gc scan pass, see #19367