Garbage collect in run loop

[laurensvalk]

More weird behavior - any loop_time < 5 results in ~5ms delay.

EDIT: this was separate problem fixed by: https://github.com/pybricks/pybricks-micropython/commit/5a0c7d5944028730ad8110bb6f1b134185bfdcc9

Originally posted by @dlech in https://github.com/pybricks/support/issues/1775#issuecomment-2307976748

[laurensvalk]

I seem to recall that it was specifically added it to the loop to ensure a consistent time, avoiding an occasionally occurring longer gc collect operation. That is, a consistent delay < 10ms is sometimes better than an occasional > 50ms delay.

I think it was added in https://github.com/pybricks/pybricks-micropython/commit/8e6b96b6873d0dc8baae2f53b3cd1297f568008a, and later translated to C in https://github.com/pybricks/pybricks-micropython/commit/cb704441c1573f57859a225384f24a921f6a208d, keeping the collect call.

The run loop is modified to call the garbage collector after each loop. This helps keep memory from fragmenting and reduces time needed to allocate new memory in many cases.

Maybe we can do some testing. When running something like a balancing robot without repeated gc collect calls, how long does a collect operation take when it does occur? If it's on the same order of magnitude, I suppose it is OK to leave it out of the run loop. If not, maybe we can make it optional in run_task, and have the block language use a sensible default setting when it calls that.

[dlech]

This is one of the several variations of our balancing robot sample project that I tested with:

from pybricks.hubs import InventorHub
from pybricks.pupdevices import Motor, ColorSensor
from pybricks.parameters import Port, Direction
from pybricks.tools import wait, StopWatch, run_task, multitask
from pybricks.geometry import Axis

# Initialize motors.
left = Motor(Port.C, Direction.COUNTERCLOCKWISE)
right = Motor(Port.D)
left.reset_angle(0)
right.reset_angle(0)

# Initialize hub and color sensor.
# You can also use the TechnicHub and/or the ColorDistanceSensor
# instead.
hub = InventorHub()
sensor = ColorSensor(Port.A)

def count():
    n = 0
    while True:
        yield n
        n += 1

async def balance():
    # Initialize position buffer for speed calculation.
    DT = 5
    window = 300 // DT
    buf = [0] * window
    idx = 0
    angle = 0
    DRIVE_SPEED = 0
    PAUSE = 5000

    # Timer to generate reference position.
    watch = StopWatch()
    counter = count()

    while True:
        # Get angular rate and estimated angle.
        rate = hub.imu.angular_velocity(Axis.Y)
        angle += rate * DT / 1000

        # Get motor position.
        position = (left.angle() + right.angle()) / 2

        # Calculate motor speed.
        speed = (position - buf[idx]) / (window * DT) * 1000
        buf[idx] = position
        idx = (idx + 1) % window

        # Calculate reference position, which just grows linearly with
        # time.
        reference = -max(watch.time() - PAUSE, 0) / 1000 * DRIVE_SPEED

        # Calculate duty cycle.
        diff = position - reference
        duty = 0.018 * rate + 19 * angle + 0.45 * diff + 0.16 * speed

        # Account for battery level and type.
        duty *= 7200 / hub.battery.voltage()

        # Calculate steering.
        # reflection = await sensor.reflection()
        # steering = (reflection - 28) * 0.6
        steering = 0

        # Apply duty cycle for balancing and steering.
        left.dc(duty + steering)
        right.dc(duty - steering)

        c = next(counter)
        if c % 500 == 499:
            print(watch.time() / c)

        # this should be await wait(0), but that is a separate issue
        # actual delay between loops is 5 ms because of loop_time=5.
        await wait(1)

# async def sound():
#     # TODO - replace with actual code
#     while True:
#         await wait(1)

# async def main():
#     await multitask(balance(), sound())

run_task(balance(), loop_time=5)
# run_task(main())

With the current master branch, the average loop time is 5.013 ms and the robot seems to balance quite well.

[dlech]

I don't remember what kind of testing I did in the past, but I don't think it was with a realistic program. So I trust the more recent testing more.

Even for a modest size program, what I am measuring now is that each GC is close to but still greater than 10 ms. So I don't think the 10ms loop time is something that is actually going to give good results most of the time.

Instead, I'm thinking it would be better to set the default loop time to 0. (We also discussed before this could be beneficial for block coding where an await wait(0) might be automatically inserted at the end of any loop.)

I'm also thinking we should enable MICROPY_GC_ALLOC_THRESHOLD so that we can use gc.threshold() to trigger GC earlier so it doesn't take so long. This is better than calling gc.collect() on every loop IMHO.

[laurensvalk]

Even for a modest size program, what I am measuring now is that each GC is close to but still greater than 10 ms.

Is this for a "full" garbage collect, triggered by MicroPython automatically?

I'm curious for a rough worst-case estimate.

Or perhaps what kind of "controlled worse case" we can obtain with various of the suggestions you've made. 10 ms seems OK.

Instead, I'm thinking it would be better to set the default loop time to 0 (...) I'm also thinking we should enable MICROPY_GC_ALLOC_THRESHOLD so that we can use gc.threshold() to trigger GC earlier so it doesn't take so long. This is better than calling gc.collect() on every loop IMHO.

I'm all for this :+1: I wasn't really a fan of the gc in the loop or the 10 ms default loop, so this sounds good.

Thanks for looking into this!

[dlech]

Is this for a "full" garbage collect, triggered by MicroPython automatically?

No, this is for the manual gc.collect() in every loop.

I'm curious for a rough worst-case estimate.

Haven't measured this yet, but good idea. Will look into this later.

[dlech]

I'm also tempted to suggest taking out the loop time altogether. It really only works intuitively if you have a task simple loop with one await that actually yields. And it would make await wait(0) confusing because it would actually wait the loop time instead of resuming as soon as possible. So I'm not sure that it is actually all that useful.

[dlech]

I'm curious for a rough worst-case estimate.

Haven't measured this yet, but good idea. Will look into this later.

Worst-case will probably be a script that has a bunch of modules with classes that hold references to other classes, combinations of deep lists/dicts and things like that where the GC has to follow lots of chains of pointers. So we would have to experiment a bit to see how bad we can make it.

In the meantime, here is a variation of the balancing robot script that keeps track of each loop time.

from pybricks.hubs import InventorHub
from pybricks.pupdevices import Motor, ColorSensor
from pybricks.parameters import Port, Direction
from pybricks.tools import wait, StopWatch, run_task, multitask
from pybricks.geometry import Axis

# Initialize motors.
left = Motor(Port.C, Direction.COUNTERCLOCKWISE)
right = Motor(Port.D)
left.reset_angle(0)
right.reset_angle(0)

# Initialize hub and color sensor.
# You can also use the TechnicHub and/or the ColorDistanceSensor
# instead.
hub = InventorHub()
sensor = ColorSensor(Port.A)

def count():
    n = 0
    while True:
        yield n
        n += 1

def interval():
    timer = StopWatch()
    prev = 0

    while True:
        now = timer.time()
        yield now - prev
        prev = now

async def balance():
    # Initialize position buffer for speed calculation.
    DT = 5
    window = 300 // DT
    buf = [0] * window
    idx = 0
    angle = 0
    DRIVE_SPEED = 0
    PAUSE = 5000

    # Timer to generate reference position.
    watch = StopWatch()
    intervals = {}

    for c, dt in zip(count(), interval()):
        # Get angular rate and estimated angle.
        rate = hub.imu.angular_velocity(Axis.Y)
        angle += rate * DT / 1000

        # Get motor position.
        position = (left.angle() + right.angle()) / 2

        # Calculate motor speed.
        speed = (position - buf[idx]) / (window * DT) * 1000
        buf[idx] = position
        idx = (idx + 1) % window

        # Calculate reference position, which just grows linearly with
        # time.
        reference = -max(watch.time() - PAUSE, 0) / 1000 * DRIVE_SPEED

        # Calculate duty cycle.
        diff = position - reference
        duty = 0.018 * rate + 19 * angle + 0.45 * diff + 0.16 * speed

        # Account for battery level and type.
        duty *= 7200 / hub.battery.voltage()

        # Calculate steering.
        # reflection = await sensor.reflection()
        # steering = (reflection - 28) * 0.6
        steering = 0

        # Apply duty cycle for balancing and steering.
        left.dc(duty + steering)
        right.dc(duty - steering)

        intervals[dt] = intervals.get(dt, 0) + 1
        if c % 500 == 499:
            print(watch.time() / c, intervals)

        await wait(5)

# async def sound():
#     # TODO - replace with actual code
#     while True:
#         await wait(1)

# async def main():
#     await multitask(balance(), sound())

run_task(balance(), loop_time=0)
# run_task(main())

Last output after running it a long time was:

5.014591 {0: 1, 13: 31, 18: 148, 19: 160, 5: 1066782, 6: 153, 14: 1225}

0 can be ignored - that was the first loop.

By far, most of the time, we are getting the requested loop time (5 ms).

Typical GC time is making the loop about 14 ms. And occasionally we see 18 or 19 ms max. Longs loops only happen in 0.146% out of all loops.

Setting gc.threshold(8000), which can reduce GC time by keeping the watermark lower - meaning less memory to sweep, didn't actually have as much effect as I thought. It only saves about 4m per collection (and collections run more frequently). Using a threshold lower than that didn't change the time per collection and also caused the robot to no longer balance because GC collection was happening too frequently, causing the average loop time to go above 6ms instead of the expected 5.

The lower threshold is probably also a good approximation for hubs with less RAM.

[laurensvalk]

I'm also tempted to suggest taking out the loop time altogether. It really only works intuitively if you have a task simple loop with one await that actually yields. And it would make await wait(0) confusing because it would actually wait the loop time instead of resuming as soon as possible. So I'm not sure that it is actually all that useful.

Right, that's exactly https://github.com/pybricks/support/issues/1460. So let's fix all of them at once :smile:

Suggestion added to https://github.com/pybricks/pybricks-micropython/pull/263

[laurensvalk]

I'm also tempted to suggest taking out the loop time altogether. It really only works intuitively if you have a task simple loop with one await that actually yields. And it would make await wait(0) confusing because it would actually wait the loop time instead of resuming as soon as possible. So I'm not sure that it is actually all that useful.

Right, that's exactly #1460. So let's fix all of them at once 😄

Suggestion added to pybricks/pybricks-micropython#263

Since https://github.com/pybricks/pybricks-micropython/commit/261663efcb79bfc86de72df2589aa1d9d8c769ff, async programs cannot be stopped with the stop button.

Probably see https://github.com/pybricks/pybricks-micropython/commit/a017bae12586535eb6b8b80495fb9fc55dc89802#r146273777

[laurensvalk]

Everything here is done.