delay(1) after non-blocking I2S::write() returned 0 causes audio distortion (No underflow)

[LinusHeu]

Main issue (for now): If there is a tiny delay() after a non-blocking I2S::write() returns 0, audio is heavily distorted. But NO underflow occurs.
Non-Blocking I2S::write() returns 0. Immediately try again until write() succeeds: no cracking.
Non-Blocking I2S::write() returns 0. delay(1) before each attempt to try again: heavy audio distortion and noise. No underflow detected.

I expect a delay(1) if write returned 0 to cause no problems. Because I assume that write() returned 0 due to full buffers.
When the buffers are full, the MCU should be able to do anything else (including waiting).
As expected, the delay(1) causes no underflow. However, it causes audio playback to be extremely distorted.

StarWars30.h from here: https://github.com/pschatzmann/arduino-audio-tools/tree/main/examples/examples-stream/streams-memory_raw-i2s

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

const unsigned char *ptr = StarWars30_raw;
size_t toPlay = StarWars30_raw_len;
long sampleRate = 22050;

void setup() {
  pinMode(LED_BUILTIN,OUTPUT);
  digitalWrite(LED_BUILTIN,LOW);
  i2s.setBCLK(26); //WS = 27
  i2s.setDATA(28);
  i2s.setBitsPerSample(16);
  i2s.setBuffers(32,16);
  if(i2s.begin(sampleRate)){
    digitalWrite(LED_BUILTIN,HIGH);
  }
}

void loop() {
  while(toPlay){
    //===Make the track stereo and quieter
    int16_t frame[2];
    frame[0] = (*(int16_t*)ptr) /8;
    frame[1] = (*(int16_t*)ptr) /8;

    //===Write one L+R sample to I2S
    while(!i2s.write(*(int32_t*)frame,false)){
    //while(!i2s.write((uint8_t*)frame,4)){
      delay(1);//No underflows get detected but audio is weirdly distorted.
      //delay(100);//Causes underflow (that gets detected) and "silence stutter silence stutter..." (as expected)
     //remove both delays: audio is played nicely. There are tiny pops though
    }
    //i2s.write(*(int32_t*)frame,true);//use blocking write instead of non-blocking: audio is played nicely. There are tiny pops though
    toPlay -= 2;
    ptr += 2;
    //===Detect underflows. Turn LED off if underflow was detected
    if(toPlay < StarWars30_raw_len - 512){//give it some time to fill the buffers. There is always an underflow at the beginning
      if(i2s.getOverUnderflow()){
        digitalWrite(LED_BUILTIN,LOW);
      }
    } else {
      i2s.getOverUnderflow();
    }
  }
  //===END
  i2s.end();
}

Added to libraries/I2S/src/I2S.h:

    bool getOverUnderflow(){
        return _arb->getOverUnderflow();
    }

How it sounds with the delay(1): https://www.youtube.com/watch?v=p6itk2GX288

My guesses:

1. delay(1) blocks interrupts, so no new buffer can be fed to the PIO after the first one is played. But I faintly remember, from using Arduino Unos in school, that delay() did not block interrupts. Is that different in this core/RP2040?
2. delay(1) is actually enough delay to cause an underflow. But the underflow detection doesn't work.
3. If it's the delay() in framework-arduinopico/cores/rp2040/delay.cpp which uses sleep_ms(): Maybe it takes too long to wake up from sleeping to feed a new buffer to the PIO.
4. The PIO state machines sleep as well during the delay()/sleep_ms() or their clock is affected in some way.

Context what I'm even trying to do +2 bonus problems I'm having:
I am trying to find an explanation to this weird behaviour: pschatzmann/arduino-audio-tools#857 (comment)

TL;DR of the issue I'm trying to fix:
It would often need multiple attempts to write 1024 bytes to I2S. It writes 0 bytes each time and then writes all 1024 at once in the (mostly) 7 to 8th attempt. Audio is cracking no matter how gigantic I make the buffers.

Additional info in case you don't know the arduino-audio-tools library and how it works:
I used non-blocking I2S write. Arduino-audio-tools tries to write again until all bytes have been written. After each (failed/incomplete) attempt, there is a delay(5). When I made the I2S.write blocking, the cracking disappeared.

There might be two additional issues/weird behaviours.

1. I don't know why writes even fail. I2S.availableForWrite() is called. Multiplied by 4 to get bytes. It should only attempt to write that amount of bytes. (And wait a bit if I2S.availableForWrite() returned 0.)
   Haven't made a minimal sketch to reproduce for this issue yet. So I'm not even sure if that issue is in arduino-audio-tools/my code or if I2S::availableForWrite() returns wrong values.

2. I only noticed this when writing the following sketch to reproduce the third issue: There are very tiny but audible pops in the audio playback even though no underflow occurs. But to be honest, I am not 100% sure that they aren't caused by my hardware. (Pico is powered by USB from my PC.)

[earlephilhower]

delay(1) blocks interrupts, so no new buffer can be fed to the PIO after the first one is played. But I faintly remember, from using Arduino Unos in school, that delay() did not block interrupts. Is that different in this core/RP2040?
If it's the delay() in framework-arduinopico/cores/rp2040/delay.cpp which uses sleep_ms(): Maybe it takes too long to wake up from sleeping to feed a new buffer to the PIO.

delay uses the Pico SDK sleep_ms call which doesn't disable IRQs AFAIK, or at least does not disable them during the actual sleep(the setup for the alarm might disable in the SDK, though). I'm not sure of the guaranteed accuracy, so "1ms" may actually delay until an alarm goes off in, say, up to 1.9999ms. Also, IIRC sleep_ms uses wfe or wfi which might cause a large drop in processor current meaning your analog VDD (unless it's completely separate from the processor's VDD) might bounce up and down significantly, really hurting audio quality on many DACs.

delay(1) is actually enough delay to cause an underflow. But the underflow detection doesn't work.

Anyway, looking at the math: At 22050hz, you need ~22 samples in 1 millisecond. Let's bump that up to 2x assuming some wiggle in the delay() call and some overhead elsewhere. So ~44 samples per ms. Your setBuffers(32, 16) should give 32 buffers of 16 samples, so plenty of space in total there.

However, with each buffer having 16 LR samples, that means @ 22khz you need to service an IRQ every 1/22050 * 16 == 0.726 milliseconds (i.e. ~1400 IRQs per second). That may be very tight given IRQ overhead on the chip. Why not try setBuffers(16,64) instead? That will give you 1 IRQ every ~3ms.

If at the higher buffer size playback is still spotty, we'll need to get a logic analyzer on the I2S bus to see what's going on. (In that case, send in a SilenceValue of 0xa5a5a5a5a5 or something very visible to make it obvious when the I2S buffer management underflows, if it ever does.

The PIO state machines sleep as well during the delay()/sleep_ms() or their clock is affected in some way.

The PIO has its own clocking and is unaffected by the core sleeping. If the PIO FIFO underflows (filled by DMA) then the I2S clock/data will stop until more data is pushed into the FIFO.

[LinusHeu]

Thank you for your ideas and information.

As for power: I'm using an MAX98357 I2S amp which is powered by Vbus of the pico. And both are powered by my PC's USB.

Some more testing:
Keeping the amount of buffers at 16 and increasing the size of each one (64,256,1024, 2048):
=> as buffer size is increased, cracking is reduced but never goes away. At 2048, removing the delay(1) still decreases cracking noticeably.

Increasing the amount of buffers (16, 32, 64, 128, 512) but keeping the size at a constant 64:
=> has zero noticeable effect.

(Size of 4096 caused the track to be interrupted by complete noise. Amount of 1024 caused loud beeps about every 2 seconds. I expected weird behaviour like this with extreme sizes.)

setBuffers(16,64) and:

1. Replacing the delay(1) with busy_wait_ms(1)
   => No effect, same cracking as with delay(1).
2. Replacing the delay(1) with this:

unsigned long endOfWait = millis();
endOfWait += 1;
while(millis() < endOfWait);

=> no noticeable change vs delay(1) either.

To check if the other core has any effect on this, I tried using setBuffers(16,64) and:

1. Having the delay(1) like in the sketch above. But adding void setup1(){while(true){}} void loop1(){while(true){}} to make the other core busy:
   =>No change
2. Removing the delay(1) like in the sketch above. But keeping the other core in a while(true){delay(1);} loop:
   => Clean playback as before.

So, the second core has, as far as I can tell, zero effect on this issue.

Using blocking write but adding this above the blocking write:

while(!i2s.availableForWrite()){
    delay(1);
}
i2s.write(*(int32_t*)frame,true);

=> Same effect as the delay() after non-blocking write returned 0.

I think it really has something to do with how often interrupts are serviced.
If an underflow was occurring, then I would expect the same total amount of buffer size to have similar behaviour. But setBuffers(512,64) has a huge amount of cracking and noise while setBuffers(16,2048) has a little cracking. Both have the same amount of space in total.

Workaround for now: Have absolutely no delay on the core that handles I2S. Don't busy wait with millis() either. Not even when the buffers are full. I think I can work with that.

I'm just still curious why, though it's probably a bit over my head. :D
Sadly, I don't have a logic analyser.

[LinusHeu]

Update to bonus issue 2:

I only noticed this when writing the following sketch to reproduce the third issue: There are very tiny but audible pops in the audio playback even though no underflow occurs. But to be honest, I am not 100% sure that they aren't caused by my hardware. (Pico is powered by USB from my PC.)

This "type of pop" occurs even when there is zero delay. And even when using blocking write.

But:

1. increasing the size of each buffer makes them less frequent. At setBuffers(32,16) I could hear them every time I played the track. With setBuffers(16,64) they were already almost so infrequent that you might think you were imagining them.
2. moving everything to core1 fixes them completely!

[earlephilhower]

Good debug, thanks a lot! It does narrows things down.

moving everything to core1 fixes them completely!

This may indicate that the USB interrupt is the root of the trouble. It runs on core0 1000 times a second, at least, and it may block the DMA done IRQ from processing while it's ongoing. For one more test, would you be able to build using Tools->USB Stack->No USB and try again? (Note, you'll need to use the BOOTSEL method to upload after this is run since the USB serial won't be there).

It may also point to a mutex issue on the list of full/empty buffers, but there's nothing to test to pinpoint that. I'll just need to eyeball things in the code.

As for the setBuffers() stuff, if the overflow flag is not set, then increasing buffer count should have no effect. Only then 2nd param, the size of each buffer, would impact this since it's not really an underflow (in this code, "underflow" means I don't have a full buffer ready to send to I2S when the DMA engine needs another one, not that I don't have a single sample).

I'll also need to double check I maximize the PIO FIFOs (combine TX/RX) which also helps to take pressure off the system.

[LinusHeu]

I'm using Platformio. Adding build_flags = -DPIO_FRAMEWORK_ARDUINO_NO_USB to platformio.ini is correct, right? (I can confirm, that disables USB because it makes upload without pressing the bootloader-button not work.)

With USB disabled, the pops are still there.
They might be less frequent, but it's really hard to tell.

[earlephilhower]

Thanks, I believe you got the right define (since the USB upload failed it's pretty obvious). That complicates things, though, as on the system there's really only the USB IRQ (and one SYSRQ exception once every 24 seconds or something to update the cycle count epoch).

One other thing, since it kind of got lost in the noise here, are you saying that you're seeing availableForWrite stick at 0 for a long time then immediately jump to some large number of samples? I expect the availableForWrite to go up by bufferSize. If you do setBuffers(16, 64) I'd expect it to go from 0->64->128->192->256->etc.., not 0->(256, 512, etc.). If that's really happening then maybe there's something fishy w/the full/empty buffer list I can dig into.

Let me hook up a logic analyzer this weekend and see exactly what's going on w/the pops. If the I2S clock stops, that means the PIO is out of data. If it's sending silenceSample (3rd param in setBuffers()) then it's the core not feeding in full buffers fast enough (which, if the 0->256/1024 available is really happening could very well happen).

[LinusHeu]

are you saying that you're seeing availableForWrite stick at 0 for a long time then immediately jump to some large number of samples?

No. Sorry, I write a lot. :D I thought that availableForWrite() returned >0 when it was supposed to return 0. But I didn't test it in a minimal sketch. I only saw weird behaviour when using Arduino-Audio-Tools.

However, I just read through the code of Arduino-Audio-Tools again. And found the "issue". I'm pretty sure it's actually intended behaviour by Arduino-Audio-Tools. Arduino-Audio-Tools does check I2S::availableForWrite(). I thought it would only attempt to write, if it returned >0. But even when availableForWrite returns 0, Arduino-Audio-Tools just tries to write. :D
Of course, trying to write when the buffers are full causes the non-blocking write to return 0.
And then, as soon as one buffer is empty, the next write succeeds.

So this "issue" had nothing to do with I2S.
As far as I can tell, write() and availableForWrite() seem to work correctly (from the users point of view).

Only the cracking/noise when using delay() and the pops when running on core0 definitely have something to do with I2S.

Very sorry for the confusion.

[earlephilhower]

I soldered up an Adafruit MAXxxx DAC+amp and did some tests locally. I can

1. Reproduce the high frequency click/.tap when using your code (meaning probably not analog./wiring issue)
2. Replacing delay(1) with busy_wait_ms(1) has same effect (meaning not related to power/sleep on the core since this is a just a tight loop, not a wfi/wfe)
3. Changing the buffer count has no effect
4. Changing the buffer size does. If I move to setBuffers(5, 3200) the click goes down to almost individually countable.

That 4th one seems to indicate the DMA buffer swapover is funky. Could be I'm not allowing you to fill up all buffers, or somehow the ABM has lost track and thinks only a single one is ever available.

I'll do some digging now that I've got the HW and a MCVE...

[earlephilhower]

Just as suspected from (4) above, the DMA swapover had an issue. Please try the very simple change in #1500 (with `setBuffers(4, 64) just for sanity since OTW your IRQs are pretty hot and heavy). Your MCVE seems to play fine now with that change, with either delay or busy_wait_ms.

--edit-- setBuffers(32, 16) w/delay(1) also seems to work too. Higher IRQ load, but enough buffers to handle 1ms sleeps every now and then.

[LinusHeu]

Wow! Thank you so much! It's perfect! I can hear absolutely zero cracking, pops, or anything like that.

[lyusupov]

I use https://github.com/earlephilhower/ESP8266Audio library to play WAV voice files by PWM method.
I can confirm as well that after this PR #1500 was applied - I can no longer hear numerous 'cracks' that I've heard before.