Interrupt/Call-Back delayed every 1.3s due to Garbage Collection

[mungewell]

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 schedule() to defer to another (reasonably sized) piece of code.

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.

[mungewell]

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.

[mungewell]

Maybe if I mess with these....

https://github.com/micropython/micropython/blob/master/py/mpconfig.h#L250

#ifndef MICROPY_BYTES_PER_GC_BLOCK
#define MICROPY_BYTES_PER_GC_BLOCK (4 * MP_BYTES_PER_OBJ_WORD)
#endif

// Number of words allocated (in BSS) to the GC stack (minimum is 1)
#ifndef MICROPY_ALLOC_GC_STACK_SIZE
#define MICROPY_ALLOC_GC_STACK_SIZE (64)
#endif

[robert-hh]

I do not know if you can you run the callback with hard=True. If yes, it will not be delayed. But it has limitations, first of all it must not allocate memory.

[mungewell]

The interrupts are set up with hard=True and I believe that the ISR is NOT delayed, I record the usTick() value so I suppose I could validate this...

The ISR uses schedule() to call the larger block of code, and it is this which is being delayed.

The callback AFTER the one which runs the gc.collect() is being delayed by ~4ms. Looking at the scopes (another Pico with Pulseview) there is a gap between the two callbacks, so perhaps introducing some sleep(0) through-out the code might improve/remove the delay.

As it stands code is working, and the 4ms delay should not break the system.

[peterhinch]

If you call gc.collect() sufficiently regularly, the time with which it blocks reduces. I have got it down to just over 1ms, but obviously this depends on the frequency of calling and the application - how much work GC has to do when it runs .

One idea would be to disable GC. This should ensure that schedule() executes fast. Then, within your schedule() routine and after running your time critical code, execute gc.collect(). This will only work properly if the time taken by your schedule() code including the time taken by gc.collect() is less than the time between interrupts (otherwise the next call to schedule will be delayed).

Failing that you might look at optimisation: reducing allocations, speeding all code that is triggered by the interrupt...

[mungewell]

I had cropped of the timing marks on the scope plot I posted, gc.collect() is currently called every (video) frame at 30 times per second from within the callback (note 4x IRQ/callbacks per frame) and is taking ~8ms to complete. I tinkered building images with different heap settings, but no significant improvement.

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.