I2S with asyncio doesn't work on ESP32-S3 with OCT SPIRAM

[shlomozippel]

Port, board and/or hardware

esp32-s3 SPIRAM_OCT variant

MicroPython version

MicroPython v1.23.0 on 2024-10-16; Chroma.tech S3 SPIRAM with ESP32S3

Reproduction

1. Run any of the I2S uasyncio examples from https://github.com/miketeachman/micropython-i2s-examples/tree/master/examples
2. The program freezes when await swriter.drain() doesn't return (after the first few iterations to fill up ibuf)

Expected behaviour

I expect the asyncio version to work. The blocking and non-blocking versions both work

Observed behaviour

await swriter.drain() doesn't return

Additional Information

No, I've provided everything above.

Code of Conduct

Yes, I agree

[miketeachman]

Hi, I'm the author of the I2S examples repo and the original author of the MicroPython I2S implementation on the ESP32. I might be able to help. I have a couple of questions to aid with debugging:

• what I2S device is being used?
• can you give more information on the Chroma.tech device? e.g. a link to the dev board or product description. A schematic would really help, if available.
• can you provide the code that you used for debugging. I'm looking to see how you determined that the call to swriter.drain() did not return. Any debugging output would also help.

[shlomozippel]

Thanks Mike!

The chromatech board uses:

• ESP32-S3-WROOM-1-N8R8
• ES8316 I2S audio codec. It requires MCK so I added support for that pin (https://github.com/chroma-tech/micropython/commit/6139bcb04aab7d71187d801dfe087c5835981d90)

Some tests I've done:

• Added print() statements before & after the await swriter.drain(). I could see it returned 2 times and then didn't return on the 3rd. I heard the audio for those first few calls
• calling swriter.write() instead of the buffer copy workaround swriter.out_buf = mv[:] caused it to work, but it wasn't async anymore. I am rendering LEDs in another task and my framerate dropped from ~100 to ~5. Audio output worked fine
• blocking and nonblocking versions of I2S worked fine
• asyncio version with the buffer copy workaround worked fine on the default esp32-s3 build (ESP_GENERIC_S3 without SPIRAM_OCT variant

I'll add the schematic and example code a bit later when I'm at my dev computer

Thanks for looking into this, I was planning on digging a bit deeper later this afternoon

EDIT: audio was playing for the first few asyncio drain calls

[shlomozippel]

The relevant audio loop:

async def continuous_play(audio_out, m):
    swriter = asyncio.StreamWriter(audio_out)
    wav_samples = mixer.buffer(4096)
    wav_samples_mv = memoryview(wav_samples)
    while True:
        m.mixinto(wav_samples_mv)
        # apply temporary workaround to eliminate heap allocation in uasyncio Stream class.
        # workaround can be removed after acceptance of PR:
        #    https://github.com/micropython/micropython/pull/7868
        # swriter.write(wav_samples_mv[:])
        swriter.out_buf = wav_samples_mv[:]
        print(">")
        await swriter.drain()
        print("<")

async def main():
    print("Starting codec")
    i2c = I2C(0, scl=fern.I2C_SCL, sda=fern.I2C_SDA, freq=100000)
    codec.init(i2c)

    m = mixer.Mixer()

    audio_out = I2S(
        0,
        sck=Pin(fern.I2S_BCK),
        ws=Pin(fern.I2S_WS),
        sd=Pin(fern.I2S_SDOUT),
        mck=Pin(fern.I2S_MCK),
        mode=I2S.TX,
        bits=16,
        format=I2S.STEREO,
        rate=16000,
        ibuf=8000,
    )

    v = mixer.Voice("sounds/well.wav")
    v.loop = True
    m.play(v)

    print("Starting audio loop")
    asyncio.create_task(continuous_play(audio_out, m))
    asyncio.get_event_loop().run_forever()

asyncio.run(main())

The output is:

>>> import audiotest
Starting codec
Starting audio loop
>
<
>
<
>

[output from continuous_play stops, but the other running tasks are still running. thats how I know the "await drain" is never returning. I hear a small fragment of audio from those first 2-3 calls]

If I swap swriter.out_buf = wav_samples_mv[:] with swriter.write(wav_samples_mv[:]) then the audio plays fine, but the write is blocking and doesn't let other async coroutines run until the audio is done playing

I also tried adding swriter.out_buf = b"" before the loop in continuous_play but it made no difference

[shlomozippel]

[miketeachman]

This is really good background information to help debug and reproduce this problem. I have the same ESP32-S3 module on a dev board so I can try to reproduce this problem.

One easy thing to try is increasing the size of ibuf to say 40000 bytes. An ibuf size of 8000 bytes used in your project is rather small in relation to the sample buffer size of 4096. I think the example code in I2S examples may have led you in this direction. There is a bug in the example. I noticed in the asyncio write example, that the ESP32 section has BUFFER_LENGTH_IN_BYTES = 2200. I must have been doing some debug testing and committed that value to the repo in error. The 2200 value is definitely a bug in the example. It should be BUFFER_LENGTH_IN_BYTES = 40000. This proposed change may make no difference but it is worth trying.

I'll have time tomorrow (Friday) to do some testing on my dev board.

[shlomozippel]

I tried increasing ibuf to 40000 and I'm experiencing the same result

Thanks for looking into this!

[miketeachman]

I tried v1.23.0 on my ESP32-S3-WROOM-1-N8R8 dev board with the same configuration (same buffer sizes, same I2S setup). I didn't see any issues. The audio was continuous.

Is it possible to share all of the MicroPython code? It would be interesting to examine the code for situations where the other task(s) do not yield back the asyncio scheduler. If another task does not return control to the asyncio scheduler the audio task can potentially get stuck in the drain method.

[shlomozippel]

Yep, happy to share it. Also, just to confirm, you're using the SPIRAM_OCT board variant? It works fine for me without the SPIRAM_OCT

[shlomozippel]

I am using this build: https://github.com/chroma-tech/micropython/commits/chromatech23/

It's basically 1.23.0 with some minor changes:

• MCK pin added to I2S
• added some dependencies to idf_component.yml which I need for some user modules
• removed the RMT and bitstream modules which conflict with one of my user modules

I will test it out now with the official 1.23.0 SPIRAM_OCT release, not the chromatech one

[shlomozippel]

The entire code I was testing with is pasted below. mixer only works on memory buffers and doesn't do anything async. codec is just i2c commands to init the I2S codec, also nothing async. fern is just for the controller pinout

import mixer
import codec
from machine import I2S, Pin, I2C
import fern
import asyncio

async def continuous_play(audio_out, m):
    swriter = asyncio.StreamWriter(audio_out)
    wav_samples = mixer.buffer(4096)
    wav_samples_mv = memoryview(wav_samples)
    while True:
        m.mixinto(wav_samples_mv)
        # apply temporary workaround to eliminate heap allocation in uasyncio Stream class.
        # workaround can be removed after acceptance of PR:
        #    https://github.com/micropython/micropython/pull/7868
        # swriter.write(wav_samples_mv[:])
        swriter.out_buf = wav_samples_mv[:]
        print(">")
        await swriter.drain()
        print("<")

# allocate sample array buffer
wav_samples = bytearray(4096)
wav_samples_mv = memoryview(wav_samples)
m = mixer.Mixer()

audio_out = I2S(
    0,
    sck=Pin(fern.I2S_BCK),
    ws=Pin(fern.I2S_WS),
    sd=Pin(fern.I2S_SDOUT),
    mck=Pin(fern.I2S_MCK),
    mode=I2S.TX,
    bits=16,
    format=I2S.STEREO,
    rate=16000,
    ibuf=40000,
)

async def main():
    print("Starting codec")
    i2c = I2C(0, scl=fern.I2C_SCL, sda=fern.I2C_SDA, freq=100000)
    codec.init(i2c)

    v = mixer.Voice("sounds/well.wav")
    v.loop = True
    m.play(v)

    print("Starting audio loop")
    asyncio.create_task(continuous_play(audio_out, m))
    asyncio.get_event_loop().run_forever()

asyncio.run(main())

[miketeachman]

Also, just to confirm, you're using the SPIRAM_OCT board variant?

Definitely.

In an earlier post you mentioned rendering LEDs in another task. I didn't see this task in the code sample. That is the task I'm curious about.

[shlomozippel]

The problem happens even without the task, but for completeness:

class FPS:
    def __init__(self):
        self._count = 0
        self._last_calc = 0
        self._fps = 0

    def tick(self):
        now = time.ticks_ms()
        delta = time.ticks_diff(now, self._last_calc)
        self._count += 1

        if delta >= 1000:
            self._fps = self._count / (delta / 1000)
            self._count = 0
            self._last_calc = now

    @property
    def fps(self):
        return self._fps

async def render_task():
    import time

    f = FPS()
    last_print = time.ticks_ms()
    while True:
        f.tick()
        if time.ticks_diff(time.ticks_ms(), last_print) > 1000:
            print(f"FPS: {f.fps}")
            last_print = time.ticks_ms()
        await asyncio.sleep_ms(10)

it's not actually rendering anything, just wanted to measure the framerate of a loop that takes 10ms

[miketeachman]

Got it. I had thought that another asyncio task was needed to create the condition.

Unfortunately, I'm a bit light on ideas on what is the issue. I don't see any obvious problem in the code. At this point, I usually try to go back to code that works and then incrementally add functionality until it fails. Do you have time to run the asyncio write example from the I2S examples repo? Try to make minimal changes to the example, e.g. I2S pin assignments, MCK. It's likely not important to read the samples from a SD card as you just want to see if the program gets stuck in the drain method. I'm curious to see if you can get the example to work. It's a solid example that should always work, on every ESP32 platform.

[shlomozippel]

Ok, the problem only happens with:

• CONFIG_I2S_ISR_IRAM_SAFE=y
• BOARD_VARIANT = SPIRAM_OCT

I'm not sure why it happens and can't remember why I added the offending config option, but I'm glad I found it after the incremental divide & conquer.

Thanks again for looking into this!

[miketeachman]

Woohoo ! I'm glad you were able to divide and conquer to some success.

[ma261065]

So is the answer to not use the option? Or is there an underlying bug?

[shlomozippel]

Everything works as expected without the option (which is disabled by default). I'm not sure what the bug is when the option is enabled, and it wasn't important enough for me to chase it down

[ma261065]

So which of the two options you listed was the actual culprit?

[shlomozippel]

Both options enabled cause the bug. If just one of them is enabled then everything works as expected. There is no real need to enable CONFIG_I2S_ISR_IRAM_SAFE. I enabled it when I was testing something unrelated, and then discovered the bug when trying it out with octal SPIRAM