Sometimes I2S doesn't properly start

[LinusHeu]

I'm really pulling my hair out here. I2S seemed to work reliably when I used just this core and played audio from an array in flash. But I want to use Arduino-Audio-Tools to play wav files from an SD-card (and ideally add more features later) but that doesn't seem to work.

Symptom:

According to the Logs of Arduino-Audio-Tools it starts I2S successfully, then it writes audio data to the output buffer. But it gets stuck after [Size of I2S output buffer] bytes are written. No sound is audible. The MCU doesn't crash. (In another test, I had the onboard LED blink on core1, and it never stopped.)

With the Debugger, I can see that it gets stuck here forever (Arduino-Audio-Tools uses blocking write to I2S): https://github.com/earlephilhower/arduino-pico/blob/f11cc4db69b91410a7904adf9eefa4a5650ff115/libraries/AudioBufferManager/src/AudioBufferManager.cpp#L174

It looks to me like the I2S output buffer is not played. It just gets filled and never gets emptied.

I added digitalWrite(LED_BUILTIN, pio_sm_is_tx_fifo_empty(_pio,_sm)); to the end of I2S::begin() https://github.com/earlephilhower/arduino-pico/blob/9352d2d14bbbae1849234207ee98065a35199ac6/libraries/I2S/src/I2S.cpp#L238-L243 The LED turns on every time the bug occurs, and stays off every time it works. So I think there is some issue with this core/I2S. The PIO state machines don't get fed any data? Even directly after I2S::begin() they should play silence, right? I assume this is "proof" that the issue occurs somewhere in the setup, before any data is actually written to the I2S output buffer.

MCVE

The MCVE below reproduces it 100% of the time in my testing today. While changing logging changes the bug, I don't think it's actually directly related to logging. In another sketch (where I first encountered the bug) it was pretty random but felt like it occurred maybe more often when logging was off and less often when logging was enabled.

Very sorry, the MCVE is a bit large for my taste. I really hope you can still reproduce it and help me. The last few days I only had sketches where the bug occurred randomly, so I'm really happy to be able to reproduce it at all. It uses Arduino-Audio-Tools to play a wav file from the SD-card. The driver between Arduino-Audio-Tools and this core's I2S is in AudioI2S/I2SRP2040.h

main.cpp

#include <Arduino.h>
#include <AudioTools.h>
#include <SDFS.h>

I2SStream i2s;
EncodedAudioStream decoder(&i2s, new WAVDecoder());
StreamCopy copier;
File audioFile;

void setup() {
  pinMode(LED_BUILTIN, OUTPUT);
  Serial.begin();
  while (!Serial)
    ;
  delay(1000);
  Serial.println("Hallo");

  SDFSConfig sdconf;
  sdconf.setCSPin(17);
  sdconf.setSPISpeed(25000000);
  SPI.setRX(16);
  SPI.setTX(19);
  SPI.setSCK(18);
  SDFS.setConfig(sdconf);
  Serial.println(SDFS.begin());

  Serial.print("SDFS.exists(\"CExplorerK.wav\"): ");
  Serial.println(SDFS.exists("CExplorerK.wav"));
  Serial.println("Let's go");

  audioFile = SDFS.open("CExplorerK.wav", "r");

  //AudioLogger::instance().begin(Serial, AudioLogger::Debug);  //Bug doesn't occur. But there is some underflow because of the logging
  AudioLogger::instance().begin(Serial, AudioLogger::Info); //Bug occurs
  //AudioLogger::instance().begin(Serial, AudioLogger::Error); //Bug doesn't occur

  I2SConfig i2sconfig = i2s.defaultConfig(TX_MODE);
  i2sconfig.buffer_count = 5;
  i2sconfig.buffer_size = 512;
  i2sconfig.pin_bck = 27;
  i2sconfig.pin_data = 26;
  i2sconfig.pin_ws = 28;
  i2s.begin(i2sconfig);

  decoder.begin();

  copier.begin(decoder, audioFile);
}

void loop() {
  if (!copier.copy()) {
    Serial.println("ENDED SUCCESSFULLY");
    i2s.end();
      stop();
  }
}

platformio.ini:

[env:rpipico]
platform = https://github.com/maxgerhardt/platform-raspberrypi.git
board = rpipico
framework = arduino
board_build.core = earlephilhower
platform_packages = framework-arduinopico@symlink://C:\Users\linus\Projekte\arduino-pico

debug_build_flags = -ggdb3 -g3

debug_tool = cmsis-dap
;upload_protocol = cmsis-dap
debug_speed = 30000 #default debug speed is only 1000kHz

monitor_echo = true
monitor_filters = log2file
;monitor_speed = 115200

Version of Arduino-Pico: https://github.com/LinusHeu/arduino-pico/tree/i2sBug (only 2 commits old and the debug LED added that I mentioned above) Version of Arduino-Audio-Tools: https://github.com/LinusHeu/arduino-audio-tools/tree/i2sbug (git cloned to /lib/) (should be the same as the latest main version of philschatzman) Adafruit I2S Amp: https://www.adafruit.com/product/3006 Adafruit Micro-SD breakout: https://www.adafruit.com/product/4682 Micro-SD: Sandisk Extreme Pro 32GB Only file on the card: sdcardsong.zip Raspberry Pi Pico

[earlephilhower]

I've never used that library (ESP8266Audio is so much cooler 😆) but if they are doing any logging inside an I2S callback there's a good chance the issue here. They could end up missing the ping and/or pong IRQs while waiting on a Serial to get responded to by the USB host PC. Is that the case? W/O logging to Serial all is well, w/logging you sometimes get hangs.

It seems like the ERROR vs INFO means the ERROR one only dumps a little bit, so doesn't waste too much time and doesn't (often) miss the IRQs, while the INFO is probably much more verbose and will take forever to finish a dump and miss IRQs much more frequently.

[LinusHeu]

if they are doing any logging inside an I2S callback there's a good chance the issue here

It doesn't use the I2S::void onTransmit(void(*)(void)); and void onReceive(void(*)(void)); at all.

Also, it's really weird. With Error (no messages during playback in this case) logging, I don't get the bug. With "Info" (so a lot of logging) I get the bug. And with "Debug" (a gigantic amount of logging) I don't get the bug (in this example).

[LinusHeu]

And I can basically "predict" the issue before it gets stuck, using that digitalWrite(LED_BUILTIN, pio_sm_is_tx_fifo_empty(_pio,_sm)); in I2S::begin(). Like, the LED turns on, and then it fills the buffer and gets stuck. Every time it doesn't get stuck, the LED stays off. So I'm suspecting that something doesn't get properly set up. Maybe a (hardware-)resource conflict with the SD-card that's completely over my head.

[LinusHeu]

I found out a few more things:

1. Maybe the debug_build_flags affect the issue. I commented that line of the platformio.ini out to better debug it.
2. Arduino-Audio-Tools starts I2S twice. First it starts it with some default sample rate (44100Hz). Then, after it has read the header of the wav, it stops i2s and starts it again with the correct sample rate (22050). I changed digitalWrite(LED_BUILTIN, pio_sm_is_tx_fifo_empty(_pio,_sm)); to Serial.println(pio_sm_is_tx_fifo_empty(_pio,_sm));: When the bug occurs it outputs 0 and then 1. And when the bug doesn't occur 0 and 0. So I think the bug only occurs when I2S is started for the second time.
3. Adding delay(5000); between i2s.begin(i2sconfig); and decoder.begin() in my sketch above switches the bugs' relation to logging around. Without that delay, it's like I said (in the comments in the MCVE) above. With the added delay(5000) it's like this: Logging to Debug = no bug Logging to Info = no bug Logging to Error = bug I suspect there might be a timing issue, race condition, or such.