Irregular processing power

[Kenneth]

As a proof of concept, I wrote a quick driver for SSD1306 compatible oled displays. As a sort of hello world, I have a horizontal and vertical line bouncing up/down and left/right, as fast as possible. While the calculations of drawing the lines might be a bit inefficient, I noticed that it seems that the processing power for calculating the new frame is irregular. Certain loops take 50-60ms, while some take 100ms.

A snippet of the code that updates the frames, and below that, an output of the print statements.

Code: Select all

...
x = 0
y = 0
direction_x = True
direction_y = True
prev_time = None
while True:
  prev_x = x
  prev_y = y
  # Move bars
  x += (1 if direction_x else -1)
  y += (1 if direction_y else -1)
  # Bounce back, if required
  if x == 128:
     direction_x = False
     x = 126
  elif x == -1:
     direction_x = True
     x = 1
  if y == 64:
     direction_y = False
     y = 63
  elif y == -1:
     direction_y = True
     y = 1
  # Draw new lines
  for i in range(64):
    display.set_pixel(prev_x, i, False)
    display.set_pixel(x, i, True)
  for i in range(128):
    display.set_pixel(i, prev_y, False)
    display.set_pixel(i, y, True)
  if prev_time is not None:
    print(pyb.millis() - prev_time)
  # Make sure the corners are active
  display.set_pixel(0,   0,  True)
  display.set_pixel(127, 0,  True)
  display.set_pixel(0,   63, True)
  display.set_pixel(127, 63, True)
  prev_time = pyb.millis()
  # Write display buffer
  display.display()
...

The output:

Code: Select all

...
104
82
29
37
42
47
53
59
64
70
76
81
86
92
97
103
94
28
35
41
47
52
57
63
69
74
79
86
91
97
102
107
27
34
40
46
52
57
62
68
73
79
84
90
96
101
107
37
33
39
45
51
56
61
67
72
78
84
89
95
100
106
49
32
39
44
49
55
60
66
72
77
83
89
94
99
105
62
31
37
43
48
54
60
66
71
77
82
88
93
98
105
74
30
37
42
48
53
59
64
70
...

Anybody an idea about how/why this happens, and how it can be prevented? It seems to me that even 30-40ms is quite a time to execute this loop (as it's even excluding the time it takes to SPI all the display bytes to the display) so the board might be doing a lot of other stuff.

[Kenneth]

Re-reading my post and taking a look at the exact timings may suggest that it's more a matter of garbage filling up or some kind of leak letting the code run slower and slower until garbage is collected and/or memory is freed.

[pfalcon]

Yes, GC is the usual suspect of such behavior. With latest uPy build, you can try to call gc.disable() and see if you app eventually crashes due to MemoryError. I don't see anything obvious which would produce more and more objects in the snippet you posted, but there's yet rest of code, and in general - we all yet need to learn how to run realtime-capable code in MicroPython. Good luck debugging that and please share your findings!

[Kenneth]

Yeah, if it's indeed a memory leak, it will most likely in the display driver. That one of the tricks by running "managed" code in such a strict environment .

I'll try to debug it and certainly share my findings as soon as I have some.

[Kenneth]

Immediately after resetting the board:

Code: Select all

MemoryError: 
FATAL: uncaught exception 805237c

FATAL ERROR:
            

That's the only thing I get when I add following code at the beginning of main.py, using yesterday's dfu.

Code: Select all

import gc
gc.disable()

[pfalcon]

Hmm, weird... I usually use "mem_info()" function to trace memory usage, but it's not defined for stmhal. Aha, there's pyb.info() instead. Too bad we don't have (yet) consistent functions across ports...

Btw, I hope that safe mode works well, so you can get out of that FATAL ERROR

[dhylands]

Perhaps move the gc.disable to just before the loop?

I suspect that a hc during initialization is causing your memory error with gc disabled earlier.

[Kenneth]

Moving gc.disable around doesn't prevent the fatal error. But there is no issue recovering from it, just press the reset button, mount the filesystem, revert the changes, unmount and reset again .

I placed pyb.info() in my loop, and I see the GC values change rapidly. I extracted them from my output:

Code: Select all

...
92 - 83120 : 18000 - 1=4837 2=40 m=64
97 - 89328 : 11792 - 1=5225 2=40 m=64
102 - 95536 : 5584 - 1=5613 2=40 m=64
101 - 7680 : 93440 - 1=122 2=40 m=64
28 - 13888 : 87232 - 1=510 2=40 m=64
35 - 20096 : 81024 - 1=898 2=40 m=64
41 - 26304 : 74816 - 1=1286 2=40 m=64
46 - 32512 : 68608 - 1=1674 2=40 m=64
52 - 38720 : 62400 - 1=2062 2=40 m=64
58 - 44928 : 56192 - 1=2450 2=40 m=64
63 - 51136 : 49984 - 1=2838 2=40 m=64
68 - 57344 : 43776 - 1=3226 2=40 m=64
74 - 63552 : 37568 - 1=3614 2=40 m=64
80 - 69760 : 31360 - 1=4002 2=40 m=64
85 - 75968 : 25152 - 1=4390 2=40 m=64
90 - 82176 : 18944 - 1=4778 2=40 m=64
96 - 88384 : 12736 - 1=5166 2=40 m=64
...

It seems indeed that the slow loops are caused by the garbage collector. I'll double check my code whether I can find a leak and update if I found something noticeable.

[Markus Gritsch]

Hi,

I am having a similar gc related issue with the following example code (can be run and tested without additional hardware):

Code: Select all

# MicroPython example for controlling one WS2812 LED.
# Method similar to http://www.espruino.com/WS2811

from pyb import SPI

spi = SPI(1, SPI.MASTER, baudrate=6400000, polarity=0, phase=1)
spi.send(chr(0x00))

def byte2bits(byte):
    b0 = chr(0x03)
    b1 = chr(0x0F)
    bits = ''
    mask = 0x80
    while mask != 0:
        bits += b0 if ( byte & mask ) == 0 else b1
        mask >>= 1
    return bits

import math
import gc

buf = bytearray(10 * 3)
n = 0
while True:
    pos = 0
    while pos < len( buf ):
        red = int((1 + math.sin((n + pos) * 0.1324)) * 127) >> 4
        green = int((1 + math.sin((n + pos) * 0.1654)) * 127) >> 4
        blue = int((1 + math.sin((n + pos) * 0.1)) * 127) >> 4
        buf[pos] = green; buf[pos + 1] = red; buf[pos + 2] = blue
        pos += 3
    data = ''.join(list(map(byte2bits, buf)))
    spi.send(data)
    gc.collect()
    print(n)
    n += 1

(Only the last 5 lines after the inner while loop are of interest.)

The code above runs smoothly at about 60 iterations per second.

But when I remove the gc.collect() call, the loop stutters at irregular intervals and yields only about 14 iterations per second.

It's clear, that the line data = ''.join(list(map(byte2bits, buf))) wastefully uses memory, but why do I have to call gc.collect() afterwards manually, instead of 'data' being automatically discarded after going out of scope?

[dhylands]

When you do the gc.collect() manually, it's doing a small (and consistent) amount of work, so it will take approximately the same amount of time each time.

When you remove the gc.collect call, then gc.collect will be deferred until the heap runs out of memory, at which point it will garbage collect in order to reclaim some.

I'm going to guess that this will also introduce some delay, but since much more memory is garbage collected, it takes longer. I'm not familiar with the actual gc algorithm, but its possible that its not linear, which means that it may be taking much more time than the sum of the smaller garbage collections being done.