Display updates extremly slow after PR#9344

[bablokb]

The IO clock or whatever it's called is just slowing down instead of the system clock.
This means, the neopixel goes white (wrong frequency), but the system keeps on running.
The display curiously keeps on going fine (data updating).

Originally posted by @bill88t in #9344 (comment)

Using the (currently newest) PR#9344 build (from S3-bucket, board: sunton_esp32_2432S032C with integrated ST7789 display), all display updates are very slow.

[bill88t]

Does your code include any AnalogIn objects?

[bill88t]

Also, as a temporary workaround, you can pair your board to any bluetooth device.
This will eat a lot of ram but will make the adc bug go away and the clocks will function as intended.

[bablokb]

No AnalogIn, no wifi. Just plain displayio with labels and images:

def show_colors():
  clear_display()
  N_SHADES = 4
  N_COLORS = N_SHADES*N_SHADES*N_SHADES
  COLOR_STEP = 256/N_SHADES
  stripe_width = display.width // N_COLORS
  i = -1
  for red in range(N_SHADES):
    for green in range(N_SHADES):
      for blue in range(N_SHADES):
        i += 1
        color = ((min(int(COLOR_STEP*red),255) << 16) +
                 (min(int(COLOR_STEP*green),255) << 8) +
                 min(int(COLOR_STEP*blue),255))
        rect = Rect(x=i*stripe_width,y=0,
                width=stripe_width,height=display.height,
                fill=color,outline=None,stroke=0)
        test_group.append(rect)

  lbl = Label(terminalio.FONT, text=board.board_id, color=0xFFFFFF, scale=2)
  lbl.anchor_point = (0.5, 0.5)
  lbl.anchored_position = (display.width//2,display.height//2)
  test_group.append(lbl)
  display.refresh()

and loading an image from SD:

  img_file = open(img_filename, "rb")
  bmp  = displayio.OnDiskBitmap(img_file)
  tile = displayio.TileGrid(bmp,pixel_shader=displayio.ColorConverter())
  test_group.append(tile)
  display.refresh()

I have tested this with all builds from https://adafruit-circuit-python.s3.amazonaws.com/index.html?prefix=bin/sunton_esp32_2432S032C/de_DE/, and the problem pops up with the latest one (PR9344 from 2024-06-18). So I was looking at the PR and what had changed, and I saw your comment in the PR.

Maybe this is unrelated to your "IO clock slowing down", but it definitely feels like it. The program just feels like it is running at maybe half or one-third speed. But I guess it is busy with some other stuff in the background maybe.

[dhalbert]

I redid some task-blocking-related stuff in #9374, which has not yet been merged. Would you mind testing with an artifact from that PR, to see if this problem still exists? Look for the latest artifacts on that PR (it's rebuilding now).

[bablokb]

I added some instrumentation to my tests and here are the results (code as posted above, full code here: https://github.com/bablokb/circuitpython-examples/blob/master/sunton-3.2/main.py).

Starting tests for sunton_esp32_2432S032C (version PR9316, 06/10/24)

show_colors (sleep): 3.00201
show_colors (title): 0.052002
show_colors (ui): 0.0820007
show_colors (refresh): 0.365997
show_colors (run): 0.462006

load_image (sleep): 3.004
load_image (title): 0.0529785
load_image (load): 0.436005
load_image (refresh): 1.36502
load_image (run): 1.81403

Starting tests for sunton_esp32_2432S032C (version PR9374-9c8896f)

show_colors (sleep): 3.07101
show_colors (title): 3.36501
show_colors (ui): 13.217
show_colors (refresh): 3.901
show_colors (run): 17.401

load_image (sleep): 3.12399
load_image (title): 3.073
load_image (load): 1.854
load_image (refresh): 6.032
load_image (run): 8.174

So it is not only a displayio problem: everything runs too slow, even a simple time.sleep() is far off.
BTW: the lines labelled "(title)" just set the text property of a pre-created Label and call refresh(), so not much going on. And we now have 3s versus 0.05s.

[dhalbert]

@bablokb Thanks for the instrumentation. This is a plain ESP32 board, is that right? Could you make a cut-down example that shows slower time.sleep() or other simple operations, without using the display at all? That would be a starting place for us to debug this, and see which chips it is happening on. EDIT: I've got one, see below.

[dhalbert]

EDIT: slightly revised example and more observations.

I ended up with an extremely simple test case:

import time

while True:
    start = time.monotonic()
    for i in range(100):
        time.sleep(0.010)
    print(time.monotonic() - start)
    time.sleep(1)

On a QT Py ESP32 on 9.1.0-beta.3, each range loop runs in about a second, as expected. on an ESP32 running adafruit-circuitpython-adafruit_qtpy_esp32_pico-en_US-20240626-main-PR9353-f1d29ee.bin (the most recent build), it runs in about 3 seconds!

Another observation is that the slow loop only happens after restarting the VM (ctrl-C, then ctrl-D). After a hard reset, the timing is normal (about 1 second).

Another way to see delays is simply to paste the line

a = "AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA"

into the REPL. In older versions, the paste in instantaneous. On the most recent build, you can see delays between the characters.

I see this only on ESP32. ESP32-C3, ESP32-S2, and ESP32-S3 are fine.

[dhalbert]

Confirmed via a bisect that it's commit 63aeb11, which is PR #9325.

Turning off BLE (CIRCUITPY_BLEIO =0) causes the problem to go away.

[bablokb]

I see this only on ESP32. ESP32-C3, ESP32-S2, and ESP32-S3 are fine.

I opened another issue #9362 which is also related to PR #9325. And that problem is also not reproducible on an ESP32-C3.