Repeatedly starting/ending I2S crashes?

[jfrey-xx]

Hello,

A bit of context: I am trying to implement audio output using both I2S and PWM Audio (an I2S chip is connected to a speaker and I'm using the PWM output as a cheap way to connect headphones when needed). Alas, when PWM is enabled, the sound via the I2S becomes corrputed (e.g. pops occurring). That even when I don't write anymore to I2S (hence the output should defaul to 0s on the I2S I believe). I don't have an oscilloscope to check what is going on with the output. That could be a separate bug report, since this is not what I am after here.

To mitigate the issue I am now trying to start/step completely each output when I want to swich back and forth between speaker and headphones. That works, if I call end() on the PWM side the I2S works properly, and when I2S is ended the speaker becomes silent. But after switching a couple times, the pico crashes (does not respond to anything, reset required). And this is the topic of this bug report.

After narrowing-down the problem it seems that just calling repeapitidely begin() / end() on the I2S causes the crash. I supected at first a memory issue, but checking the heap size with the SDK functions does not seem to indicate a leak (nor did I found one after a quick inspection of the code). The problems occurs more quickly if I output something on the Serial port. Or when I initialisie some variable (I had at first some audio buffer, global scope fixed size arrays, the reason why ), and immediately if I try to reset I2S (end/begin) too fast (twice within a second). Maybe there is something going on with the PIO and the FIFO? Before spending more time digging the code I thought it could be worth to ask if this use-case is even supported.

Here is a minimal code to reproduce the issue (tested with 2.7.1, no optimization for the compilation, with and without TinyUSB stack); sine at fixed frequency, timer to reset periosically I2S.

#define TIME_uS                     time_us_32()
#define fTime                       (TIME_uS/1000000.0)

#include <I2S.h>
I2S i2s(OUTPUT);

#define pBCLK 20
#define pWS (pBCLK+1)
#define pDOUT 22

const int sampleRate = 16000;
unsigned long timer0 = 0;
bool PWMon = true;

void setup()
{
  Serial.begin(115200);

  i2s.setBCLK(pBCLK);
  i2s.setDATA(pDOUT);
  i2s.setBitsPerSample(16);

  delay(100);
  timer0 = millis();
}

void loop()
{
  if (millis() > 3000) 
  {
    float fAmp = 50.0 * sin(2.0 * PI * fTime * 440.0);
    short amp = (short)fAmp;

    if (!PWMon) i2s.write16(amp, amp);


    if (millis() - timer0 >= 10000)
    {
      timer0 = millis();

      if (PWMon)    Serial.println("Before I2S begin : ");
      else          Serial.println("Before I2S end : ");

      if (!PWMon)    i2s.end();
      else          i2s.begin(sampleRate);

      if (PWMon)    Serial.println("After I2S begin : ");
      else          Serial.println("After I2S end : ");

      PWMon = !PWMon;
    }
  }
}

Is there something wrong with the code above, that I missed?

[earlephilhower]

Interesting problem and use case, thanks for the MCVE. Do you have a Picoprobe? Dumping the call stack (where in gdb) would be very helpful here. There may be a race condition between start/stop, even if no memory leak...

[maxgerhardt]

I broke out my picoprobe and ran the sketch with the latest Arduino-Pico core in PlatformIO and it seems to get stuck in the I2S write function for the value 917518...

[earlephilhower]

Well, looks like the AudioBufferManager DMA is not running and producing empty frames. Will look into it.

There are some cases where you have essentially a double-fault (miss 2 DMA interrupts and the DMA ping-pong breaks) which I can't think of a way to reliably detect in the code (w/o adding yet another race condition). Could also be a case where the DMA was not properly started (or released on the shutdown)...

[maxgerhardt]

This behavior is not very consistent though, on my second debug try with -O0 optimization instead of -Og it seems to get stuck in IRQ calls..

[earlephilhower]

That could be a mismatch between the DMA channel interrupt (and its list) and reality (which would also of course make it impossible to get frames from filled->empty state since that's what the DMA handler basically does). If a DMA channel that's not in our active list comes in, the core will loop back into the IRQ immediately on exit of the handler since the "clear IRQ" bit is in the DMA handler code, not here.

[earlephilhower]

@jfrey-xx can you try #1163 and report back?

I've modded hour test app to switch every 1s instead of 10s so I can get more runs in. It's at 211 I2S begin()s loops now with no signs of hanging. Looks like it was a corner case where tearing down the old I2S could have happened while a DMA was sending an IRQ, leaving things inconsistent.

@maxgerhardt I've done runs w/ -Os and -Og (at loop 65 now) on this one, too. Both seem OK. The optimization would of course change the timing of things subtly so having slightly different crash signatures is probably to be expected since it looks like a race condition.

[maxgerhardt]

I applied the patch from the PR to my framework files.

Now at -Os and -Og optimization I do not get a hangup anymore, but at -O0 it quickly hangs up after 3 iterations (iteration time set to 100ms)

Before I2S begin : 
After I2S begin :   
Before I2S end : 
After I2S end :  
Before I2S begin : 
After I2S begin : 
<HANG>

Which is again in

It might just be that when some routines do not run fast enough, it misses something :/

[earlephilhower]

Re -O0, we don't have that in the IDE so I just hacked it in. I can repro the hang, and can make it go away by increasing the time between interrupts by setting the frequency to ~4KHz. At 16KHz it fails in 1-2 loops, at 8KHZ it fails in 6-8 loops, but at 4KHz it's gone 600 loops so far.

So, I do believe that at O0 you hit the double fault (the 2nd DMA finishes before the 1st one can be set up) and essentially no DMA happens at that point.

Not really related to the problem here which was a logic one, this is a timing one where there's just not enough oomph in the core to do the DMA work and other stuff. :( Solution there is to reduce frequency or increase the buffer sizes (which are set low by default to minimize the output delay).

[maxgerhardt]

As a "deseperate method of last resort" in these situations, can't the while(!*p) {} loop be rewritten to be a time-out loop? If this code busy waits for over a second waiting on the sample to be sent, for sure something went wrong.

[earlephilhower]

I see your point, but it's kind of complicated.

There is already a non-blocking write people can use if they can deal with failure.

Here, we'd be failing at, say, 1000ms but doing it silently. The app in most cases is probably doing these writes in a loop (i.e. fill the whole buffer with the sine wave) so every single write will end up waiting 1s and you're essentially frozen, too. This doesn't lock IRQs so the serial/etc. still function during this long timeout.

Even force-restarting the DMA isn't a good solution in this case. The problem isn't the userland generating samples too slow. The DMA handler simply checks "is there a full buffer yet?" and if not immediately assigns the silence buffer to the DMA channel. So even restarting DMA would end up failing again because that simple comparison couldn't be done fast enough. Too much water for the bucket and it's just gonna spill no matter what you do. 😭

[maxgerhardt]

Here, we'd be failing at, say, 1000ms but doing it silently

Technically the return type of the bool AudioBufferManager::write(uint32_t v, bool sync) function is bool, which up the chain is upcasted to size_t, so returning a false would indeed inform the caller that 0 samples were written.

But I do get your point of there being no way out of this situation. I'm just thinking about that being a caveat when wanting to debug a I2S application in PIO (or really with any tool) and -O0 was chosen. (Sometimes -Og does optimize some variables that one is interested in). Maybe a note can be left in the docs saying that, "when debugging I2S applications or any application that requires fast code to function properly, care must be taken that the optimization level during debugging still produces fast enough code".