ALSA: invalid handling of capture overruns

[codepainters]

I'm working on an application using cpal over ALSA to continuously capture audio stream on Raspberry Pi. I use both RPI and PC for testing. Note: I'm using a version from master branch, as I need both i16 and i32 sample formats, with i32 not being supported in stable version.

Unfortunately I'm experiencing odd behavior upon capture overruns (which I trigger setting buffer size too low).

1. The most severe case is when poll() return EPOLERR which is not handled properly.

476794 1669022562.665530 poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN|POLLERR|POLLNVAL}], 2, 200) = 1 ([{fd=5, revents=POLLIN}])
476794 1669022562.666440 ioctl(5, SNDRV_PCM_IOCTL_STATUS_EXT,      0x7f6b10495f88) = 0
476794 1669022562.666532 ioctl(5, SNDRV_PCM_IOCTL_HWSYNC, 0x98) =      0
476794 1669022562.666577 ioctl(5, SNDRV_PCM_IOCTL_READI_FRAMES,      0x7f6b10496760) = 0
476794 1669022562.666707 poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN|POLLERR|POLLNVAL}], 2, 200) = 1 ([{fd=5, revents=POLLIN|POLLERR}])
476794 1669022562.669590 poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN|POLLERR|POLLNVAL}], 2, 200) = 1 ([{fd=5, revents=POLLIN|POLLERR}])
476794 1669022562.669765 poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN|POLLERR|POLLNVAL}], 2, 200) = 1 ([{fd=5, revents=POLLIN|POLLERR}])

And then I no longer get any more callbacks from cpal, but my application is eating up 100% of CPU core, as poll() is executed in a tight loop.

The problem is here:

cpal/src/host/alsa/mod.rs

Lines 746 to 753 in 7776c66

	let stream_type = match stream.channel.revents(&descriptors[1..])? {
	alsa::poll::Flags::OUT => StreamType::Output,
	alsa::poll::Flags::IN => StreamType::Input,
	_ => {
	// Nothing to process, poll again
	return Ok(PollDescriptorsFlow::Continue);
	}
	};

This match doesn't recognize POLLIN|POLLERR and returns PollDescriptorsFlow::Continue, causing the worker thread to poll() again immediately, leading to a tight loop.

The problem seems obvious, I'll try to come with a pull request.

2. Another scenario is when the second ioctl call fails.

476936 1669022662.246764 poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN|POLLERR|POLLNVAL}], 2, 200) = 1 ([{fd=5, revents=POLLIN}])
476936 1669022662.247721 ioctl(5, SNDRV_PCM_IOCTL_STATUS_EXT, 0x7f70e2810f88) = 0
476936 1669022662.247884 ioctl(5, SNDRV_PCM_IOCTL_HWSYNC, 0x98) = -1 EPIPE (Broken pipe)
476936 1669022662.248019 ioctl(5, SNDRV_PCM_IOCTL_PREPARE, 0) = 0
476936 1669022662.248112 poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN|POLLERR|POLLNVAL}], 2, 200) = 0 (Timeout)
476936 1669022662.448722 write(1, "Die! A backend-specific error has occurred: `alsa::poll()` spuriously returned\n", 79) = 79
476936 1669022662.449074 poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN|POLLERR|POLLNVAL}], 2, 200) = 0 (Timeout)
476936 1669022662.649849 write(1, "Die! A backend-specific error has occurred: `alsa::poll()` spuriously returned\n", 79) = 79
476936 1669022662.650342 poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN|POLLERR|POLLNVAL}], 2, 200) = 0 (Timeout)
476936 1669022662.851166 write(1, "Die! A backend-specific error has occurred: `alsa::poll()` spuriously returned\n", 79) = 79

In this scenario I no longer get any data callbacks, instead I get error callback periodically (poll timeout).

I believe the problem is here:

cpal/src/host/alsa/mod.rs

Lines 604 to 609 in 7776c66

	PollDescriptorsFlow::XRun => {
	if let Err(err) = stream.channel.prepare() {
	error_callback(err.into());
	}
	continue;
	}

The call to prepare() passes OK, but the stream is stopped - according to ALSA, this call changes the state to SND_PCM_STATE_PREPARED, there also need to be a call to start() to transition to SND_PCM_STATE_RUNNING and re-enable data flow.

I'm a bit confused here about what is the intended cpal behavior here:

• should I assume that stream is broken when my error callback is called for the first time, drop the Stream and create a new one? In such case I believe cpal should do some cleanup (e.g. stop the polling loop).
• should I assume that the error is temporary and the data flow will continue? In such case start() call is missing.

3. The third scenario is when ioctl(SNDRV_PCM_IOCTL_READI_FRAMES) fails with EPIPE:

476728 1669022521.635527 poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN|POLLERR|POLLNVAL}], 2, 200) = 1 ([{fd=5,        revents=POLLIN}])
476728 1669022521.636362 ioctl(5, SNDRV_PCM_IOCTL_STATUS_EXT, 0x7f8b2368af88) = 0
476728 1669022521.636521 ioctl(5, SNDRV_PCM_IOCTL_HWSYNC, 0x98) = 0
476728 1669022521.636681 ioctl(5, SNDRV_PCM_IOCTL_READI_FRAMES, 0x7f8b2368b760) = -1 EPIPE (Broken pipe)
476728 1669022521.636777 write(1, "Die! A backend-specific error has occurred: ALSA function 'snd_pcm_readi' failed with error 'EPIPE: Broken pipe'\n", 113) = 113
476728 1669022521.636823 poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN|POLLERR|POLLNVAL}], 2, 200) = 1 ([{fd=5,        revents=POLLIN|POLLERR}])
476728 1669022521.636860 poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN|POLLERR|POLLNVAL}], 2, 200) = 1 ([{fd=5,        revents=POLLIN|POLLERR}])
476728 1669022521.636892 poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN|POLLERR|POLLNVAL}], 2, 200) = 1 ([{fd=5,        revents=POLLIN|POLLERR}])

Here, the error from process_input() is properly delivered to my error callback, but then we enter the tight loop scenario, due to POLLERR not being recognized.

[ashleysmithgpu]

Just a quick note that I ran in to this issue as-well. I was getting constant ALSA lib pcm.c:8545:(snd_pcm_recover) "overrun" occurred errors. I changed the code to add the suggested:

            PollDescriptorsFlow::XRun => {
                if let Err(err) = stream.channel.prepare() {
                    error_callback(err.into());
                }
                if let Err(err) = stream.channel.start() {
                    error_callback(err.into());
                }
                continue;
            }

And it seems to work fine now. I still get the overruns, but it gracefully continues.
I am running on a raspberry PI zero w with the respeaker 2mic board attached.

[codepainters]

I have moved away from CPAL altogether. My application only needs to work on Linux (Windows was a nice-to-have feature), and I only need a simple record capability (and I also use Respeaker!).

I decided to switch to raw alsa, which solved all my problems. I was initially afraid of the low-level interface, but it turned out surprisingly easy.

[sandreas]

@roderickvd

Just would like to ask, if anybody ever had looked into this. I'm running into the same issue where audio completely breaks and I get

audio stream error: A backend-specific error has occurred: `alsa::poll()` returned POLLERR
audio stream error: A backend-specific error has occurred: `alsa::poll()` returned POLLERR
audio stream error: A backend-specific error has occurred: `alsa::poll()` returned POLLERR
# ....

in a repeated loop. Unfortunately I'm bound to a device specific ALSA (kernel 5.10), so I cannot upgrade to pipewire or something more modern.

I'm capable of writing Rust code, so if somebody can point me into the right direction, I may be able to submit a pull request.

If it is just this:

            PollDescriptorsFlow::XRun => {
                if let Err(err) = stream.channel.prepare() {
                    error_callback(err.into());
                }
                if let Err(err) = stream.channel.start() {
                    error_callback(err.into());
                }
                continue;
            }

could integrate that - if there is no tests that have to be updated.

I also experimented with raising the buffer sizes to prevent underruns (XRUN):

pcm.!default {
    type plug
    slave {
        pcm "hw:2,0"
        rate 44100
        format S16_LE
        channels 2
        buffer_size 4096
        period_size 1024
    }
}

but I think that my hardware is not supporting fixed buffer sizes, since the playback is not working this way.

I would really appreciate any help.

[roderickvd]

@sandreas thanks for the nudge. You'd be of great help if you could help me test #1112 properly on several devices. Your old kernel is an interesting use case; let me know how it goes there as well as on newer targets, for both playback and capture streams.

[sandreas]

You'd be of great help if you could help me test #1112 properly on several devices.

Sure.

Using rodio in my project I bumped from 0.21.1to 0.22.1with cpal bumped 0.16.0 to 0.17.3 I noticed that straight audio playback is no longer possible on my Kernel 5.1.0 device - it's just fast forwarding, while on my Notebook (6.12.74-1-lts) it is working fine with a non ALSA backend. I hadn't the time to investigate further, so I'm not sure why this happened (not necessarily cpal, but possible).

Here is repository and the commit to update rodio / cpal:

• https://github.com/nanowave-player/nanowave-ui/
• nanowave-player/nanowave-ui@0b48850

I'm building a DIY portable audio player using a more exotic piece of hardware (LicheeRV Nano, riscv64-linux-musl). It uses a buildroot image based on kernel 5.10 as well as an Apple USB-C to 3.5mm adapter for audio output. Development happens on linux, which is "reproducing" the hardware environment as good as it gets and except GPIO it goes pretty well. However, this is one of the things that turned out to be different :-)

I report back ASAP.

[roderickvd]

What do you mean with "fast-forwarding"? If you mean to say that your samples are being consumed at a much faster pace than they are played back, then that's 99% sure due to BufferSize::Default now following the system defaults. To solve that, configure the system or use BufferSize::Fixed. See:

• https://github.com/RustAudio/cpal/releases/tag/v0.17.0
• https://www.reddit.com/r/rust/comments/1prot31/cpal_0170_is_out_crossplatform_audio_io_gets/
• get_pos does not seem to account for the current speed rodio#837

Let me know about #1112 though! That's v0.18 in the making.

[sandreas]

What do you mean with "fast-forwarding"? If you mean to say that your samples are being consumed at a much faster pace than they are played back, then that's 99% sure due to BufferSize::Default now following the system defaults.

Yeah I meant that samples are consumed too fast - thanks for clarifying this.

Unfortunately I'm currently fighting instability issues on the device. This could have a lot of reasons (e.g. power supply, kernel, faulty hardware or a new buildroot) so I have to narrow this down first. I have some spare hardware and old images so this should not take too long, but until this is "fixed" I cannot really test something reliably.

As soon as I can I'm going to test #1112 and report back. Should not take longer than next week. Thanks for taking the time to reach out.

[sandreas]

@roderickvd

Ok, I'm one step further. I only bumped rodio and cpal along with applying instructions from UPGRADE.md and the audio playback is non-functional. Reverting the change (see nanowave-player/nanowave-ui@0f6cecd) makes audio playback work again, but then I still run into the polling error after a little while:

audio stream error: A backend-specific error has occurred: `alsa::poll()` returned POLLERR
audio stream error: A backend-specific error has occurred: `alsa::poll()` returned POLLERR
audio stream error: A backend-specific error has occurred: `alsa::poll()` returned POLLERR
audio stream error: A backend-specific error has occurred: `alsa::poll()` returned POLLERR
audio stream error: A backend-specific error has occurred: `alsa::poll()` returned POLLERR
...

Typically after the polling error nothing can heal the system (not even re-plugging the usb-c audio device) and sometimes the problem even survives a reboot (that's why it felt so unstable I think).

Maybe you could point me into the right direction / documentation on how to make the buffersize act like 1.6.0 in my specific use case? I checked the commits but there were so many I did not find the right one. In the rare case I'd find a generic solution to the polling problem I'd submit a PR ASAP.

Regarding #1112: I'm on it. Currently trying to understand the code and working into the project. I plan to fork and put some debug output next week, but first I need to find the playback issue with the 0.16.0 -> 0.17.3 upgrade, otherwise testing will become a nightmare trying to fix 2 things at a time.