Delay every 400ms when reading keys

[petrkr]

Some part of code causes keys are read like 7 times and then wait approx 400ms.

698416 reading pin NXT
698424 reading pin SEL

--- wait aprox 400ms ---

698787 reading pin NXT
698794 reading pin SEL
698863 reading pin NXT
698871 reading pin SEL
698940 reading pin NXT
698947 reading pin SEL
699016 reading pin NXT
699023 reading pin SEL
699091 reading pin NXT
699099 reading pin SEL
699168 reading pin NXT
699175 reading pin SEL
699243 reading pin NXT
699250 reading pin SEL

--- wait aprox 400 ms ---

699613 reading pin NXT
699621 reading pin SEL
699690 reading pin NXT
699697 reading pin SEL
699767 reading pin NXT
699774 reading pin SEL
699842 reading pin NXT
699850 reading pin SEL
699918 reading pin NXT
699926 reading pin SEL
699994 reading pin NXT
700001 reading pin SEL
700070 reading pin NXT
700077 reading pin SEL
.... and so on ...

That causes little-bit strange lags during pressing keys

for test code I've used simple class TestPin instead pin to print ticks and calling "value"

class TestPin():
    def __init__(self, name, value = 0):
        self._value = value
        self._name = name

    def value(self, value = None):
        if not value:
            print("{} reading pin {}".format(ticks_ms(), self._name))
            return self._value

        self._value = value

BTN_NXT = TestPin("NXT")
BTN_SEL = TestPin("SEL")

Using simple demo from chapter 1 as main.py using from drivers.st7735r.st7735r import ST7735R as SSD

[peterhinch]

The delay implies that something is blocking and preventing uasyncio from scheduling tasks. Assuming you have none of your own code doing this, the culprit is almost certainly ST775r.show(). This blocks for 36ms on a Pyboard D, but blocking will be longer on slower targets. 400ms does seem very long: what target are you using?

On some of my drivers for larger displays I provide an asynchronous do_refresh method to reduce blocking periods and maintain responsiveness but I didn't see a need on the smaller displays.

[petrkr]

Esp32 and i reducted own code just to HW setup and basic example from chapter 1. Nothing else. Even wifi is turned off.

[peterhinch]

I've tested this using the ESP32 reference board and an Adafruit 1.8" ST7735R display. I modified the driver's .show as below - you might want to do similar to verify the source of your latency:

    def show(self):  # Blocks 47ms on ESP32 reference board at stock frequency (160*128)
        t = ticks_ms()  # Added
        wd = self.width
        ht = self.height
        lb = self._linebuf
        buf = self._mvb
        self._dc(0)
        self._cs(0)
        if self._spi_init:  # A callback was passed
            self._spi_init(self._spi)  # Bus may be shared
        self._spi.write(b'\x2c')  # RAMWR
        self._dc(1)
        for start in range(wd * (ht - 1), -1, - wd):  # For each line
            _lcopy(lb, buf[start :], wd)  # Copy and map colors (68us)
            self._spi.write(lb)
        self._cs(1)
        print(ticks_diff(ticks_ms(), t))  # Added

changing line 19 to read

from time import sleep_ms, ticks_ms, ticks_diff

This showed blocking times of around 47ms.

I suggest you check your SPI baudrate. My color_setup.py has

# Hardware SPI on native pins for performance. Check DRIVERS.md for optimum baudrate.
spi = SPI(1, 10_000_000, sck=Pin(14), mosi=Pin(13), miso=Pin(12))

I tested with release firmware build V1.18 and current drivers and code.

[petrkr]

I've got around 35ms

444170 reading pin NXT
444179 reading pin SEL
33
33
444555 reading pin NXT
444561 reading pin SEL
33
32

So this would not be source of blocking

[peterhinch]

In which case I'm baffled. A lot of my development work on this GUI was with ESP32 and I never observed this behaviour. I performed detailed measurement of real time performance. The only code in the GUI which blocks for any significant period is .show but you have proved that this is behaving as expected.

Not having the hardware in front of me means I'm guessing wildly, but I'd start on the assumption that the GUI might not be the cause. Check for power supply issues: ESP32's can draw substantial current when connecting to WiFi causing voltage drops and odd behaviour. I know you're not using WiFi, but have you disabled AP mode?

Another thing to try would be to write a simple uasyncio script, perhaps to flash an LED, and see if blocking is occurring.

I'm sorry I can't offer a clear solution to this. Something very odd is going on.

[petrkr]

Later I will try do clean flash, will try more revisions and will try to find it. Now I am at MicroPython v1.18-46-g21cb68478. Also I am using SPI RAM build because display use lots of RAM and in fact I can not use other needed libraries to work.

AP Mode I did not disable explicitly. I just did not done connect()

what minimal uasyncio I can try - that flash LED or even some While true: print(hello) sleep 50ms?

because if something will eat for 400ms time, it would be visible too.

[peterhinch]

SPIRAM can cause substantial latency when GC runs. I have measured 100ms on various targets. I suggest you try this:

from time import ticks_us, ticks_diff
import gc
def test():
    t = ticks_us()
    gc.collect()
    dt = ticks_diff(ticks_us(), t)
    print('GC time', dt)

[petrkr]

>>> test()
GC time 44293
>>> test()
GC time 43154
>>> test()
GC time 43127
>>> gc.mem_free()
4081616

[petrkr]

Well. if I will use stock stable 1.18 without SPIRAM then there is not that 400ms delay.

with my build without SPIRAM it is fine too... So it is caused by SPI RAM.

Now why? But I think we can close this issue, because it's not problem with micro-gui library

[petrkr]

one more test without SPI RAM

>>> test()
GC time 2461
>>> test()
GC time 2026
>>> test()
GC time 2014
>>> test()
GC time 2013

[petrkr]

Well I found it..

Do not know why, but gc.collect() which is called from asyncio task in ugui.py took almost 300ms. So that will be source of that delay. And it's run every 500ms. So that is the reason of that blocking calling...

But what now?

Do not call gc.collect() too offten if SPI RAM is used? Actually it is not needed to call it such often because there are lot of memory available.

495290 reading pin NXT
495297 reading pin SEL
31
GC time 286475
31
495654 reading pin NXT
495661 reading pin SEL
30
30
495729 reading pin NXT
495736 reading pin SEL
30
30
495803 reading pin NXT
495810 reading pin SEL
31
29
495878 reading pin NXT
495885 reading pin SEL
30
30
495953 reading pin NXT
495960 reading pin SEL
30
30
496027 reading pin NXT
496034 reading pin SEL
31
29
496102 reading pin NXT
496109 reading pin SEL
30
GC time 286492

    async def _garbage_collect(self):
        n = 0
        while True:
            await asyncio.sleep_ms(500)
            t = ticks_us() # Added
            gc.collect()
            gc.threshold(gc.mem_free() // 4 + gc.mem_alloc())
            n += 1
            n &= 0x1f
            dt = ticks_diff(ticks_us(), t)  # Added
            print('GC time', dt) # Added
            _vb and (not n) and print("Free RAM", gc.mem_free())

[peterhinch]

I raised this RFC regarding GC time with SPIRAM. I think it's a big problem.

The reason I explicitly run the ._garbage_collect method is that, on non-SPIRAM targets, it reduces the latency compared to waiting until MicroPython performs a GC. By then, fragmentation has accumulated, causing a longer delay. However this logic doesn't really work with SPIRAM targets because GC takes forever even when there is no fragmentation.

You could simply not run .garbage_collect. Then you would no longer get the regular 400ms latency, but you might get a longer latency when MP gets round to doing its own GC. I haven't researched the behaviour of SPIRAM targets in the presence of fragmentation, so I don't have knowledge of the likely duration. I generally avoid SPIRAM targets for this reason.

Thank you for pointing out this issue, I'll make a note in the docs.

[petrkr]

For me is impossible run this project without RAM, because I use lot of cryptography libraries too, which took lot of resources aswell.

So maybe solution for this would be disable yhis GC every 500ms and call it by own code with some longer delay, like 'screensaver' or so.

In idle i have lot of time to do anything. But in user-input screens it must be responsive, so I can call gc collect when open some user interactive window, to prevent automatic upy collect.

Maybe would be nice to be able disable that task other way than just fork code

[peterhinch]

Agreed. [EDIT] I have pushed an update which lets the user take control. Edit hardware_setup.py to include

# code omitted
from gui.core.ugui import Display, Screen
Screen.do_gc = False
# ...

I've also updated the README. Please let me know what you think.

[petrkr]

Absolute good... I will monitor memory and how will work auto/manual gc.collect()

[peterhinch]

Thank you for pointing out this issue and for testing.