cpal icon indicating copy to clipboard operation
cpal copied to clipboard

Published 20 hours ago • verified publisher icon RustAudio

Sink.empty() is true before the playback ended

Open zenria opened this issue 4 years ago • 16 comments

Migrating from rodio 0.11, I used to monitor the end of sound playback using empty() function.

This worked fine on both MacOS and Linux (raspberry pi zero with USB output device)

Switched to 0.13: this still works on MacOS, but returns true on the raspberry way before the sound had finished to play.

zenria avatar Nov 04 '20 17:11 zenria

Maybe related to RustAudio/rodio#323?

est31 avatar Nov 04 '20 17:11 est31

Yes, it seems to be related.

The initial purpose I was using Sing::empty() was to loop playback. I tried another approach using a LoopedDecoder to and it's looping way too fast ; also the rodio thread eats a lot of CPU (approx 95%)

zenria avatar Nov 04 '20 19:11 zenria

BT of the thread that eats cpu:

Thread 8 (Thread 0xb5bfb3a0 (LWP 23791)):
#0  0xb6e6ad30 in ?? () from /usr/lib/arm-linux-gnueabihf/libasound.so.2
RustAudio/rodio#1  0xb6e6ad24 in ?? () from /usr/lib/arm-linux-gnueabihf/libasound.so.2
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

zenria avatar Nov 04 '20 19:11 zenria

@zenria it would be very helpful to know which commit caused the regression. Would it be possible to perform a bisection?

est31 avatar Nov 04 '20 19:11 est31

Yes, I will try to find that!

zenria avatar Nov 04 '20 23:11 zenria

First, trying to rollback last master commit does does not compiles (cpal 0.12.1):

error[E0308]: mismatched types
   --> /cargo/registry/src/github.com-1ecc6299db9ec823/cpal-0.12.1/src/host/alsa/mod.rs:906:59
    |
906 |         BufferSize::Fixed(v) => hw_params.set_buffer_size(v as i64)?,
    |                                                           ^^^^^^^^ expected `i32`, found `i64`
    |
help: you can convert an `i64` to `i32` and panic if the converted value wouldn't fit
    |
906 |         BufferSize::Fixed(v) => hw_params.set_buffer_size((v as i64).try_into().unwrap())?,
    |                                                           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^

Forcing cpal to 0.12.0 compiles, but no sound is played and awful errors are output:

an error occurred on output stream: A backend-specific error has occurred: ALSA function 'snd_pcm_writei' failed with error 'EAGAIN: Try again'
an error occurred on output stream: A backend-specific error has occurred: ALSA function 'snd_pcm_writei' failed with error 'EAGAIN: Try again'
an error occurred on output stream: A backend-specific error has occurred: ALSA function 'snd_pcm_writei' failed with error 'EAGAIN: Try again'
an error occurred on output stream: A backend-specific error has occurred: ALSA function 'snd_pcm_writei' failed with error 'EAGAIN: Try again'
an error occurred on output stream: A backend-specific error has occurred: unexpected number of frames written: expected 60663, result 926 (this should never happen)

Digging continues!

zenria avatar Nov 05 '20 07:11 zenria

I started investigating on latest rasbian (debian buster)

Distributor ID:	Raspbian
Description:	Raspbian GNU/Linux 10 (buster)
Release:	10
Codename:	buster

This still does not work, but now, it's stopping the whole program with exit code 134:

philou@elise-rbp-mini:~ $ ./rbp-rodio-bug
ALSA lib pcm_dmix.c:1043:(snd_pcm_dmix_open) The dmix plugin supports only playback stream
ALSA lib pcm_dsnoop.c:575:(snd_pcm_dsnoop_open) The dsnoop plugin supports only capture stream
ALSA lib pcm_dsnoop.c:638:(snd_pcm_dsnoop_open) unable to open slave
ALSA lib pcm_dsnoop.c:638:(snd_pcm_dsnoop_open) unable to open slave
memory allocation of 1258328832 bytes failedAborted
philou@elise-rbp-mini:~ $ echo $?
134

It seems something is trying to allocate 1GB on memory, which on a system containing only 512MB of RAM fails!

zenria avatar Nov 05 '20 13:11 zenria

Full GDB backtrace:

(gdb) bt full
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
        set = {__val = {0, 0, 0, 6429464, 6426208, 0, 3069453288, 0, 0, 0, 6426208, 6429464, 0, 0, 6433512,
            6429464, 3069454144, 0, 0, 0, 0, 0, 0, 0, 0, 3070224744, 0, 0, 0, 0, 3691916800, 0}}
        pid = <optimized out>
        tid = <optimized out>
        ret = <optimized out>
RustAudio/rodio#1  0xb6d22230 in __GI_abort () at abort.c:79
        save_stage = 1
        act = {__sigaction_handler = {sa_handler = 0xb6e55803 <main_arena+47>,
            sa_sigaction = 0xb6e55803 <main_arena+47>}, sa_mask = {__val = {6345332, 2, 0, 0, 3, 0, 5, 3066231584,
              5143244, 0, 3066230660, 3, 0, 6345332, 2, 0, 0, 3066230724, 1, 307319, 126, 3066231420, 1258328832,
              1, 1231032928, 0, 1258328832, 3066231584, 5144144, 6429464, 6345332, 2}}, sa_flags = 0,
          sa_restorer = 0x0}
        sigs = {__val = {32, 0 <repeats 31 times>}}
RustAudio/rodio#2  0x004ead88 in std::sys::unix::abort_internal () at src/libstd/sys/unix/mod.rs:167
No locals.
RustAudio/rodio#3  0x004e512c in std::process::abort () at src/libstd/process.rs:1623
No locals.
RustAudio/rodio#4  0x004e7e90 in rust_oom () at src/libstd/alloc.rs:282
No locals.
RustAudio/rodio#5  0x005003e0 in alloc::alloc::handle_alloc_error () at src/liballoc/alloc.rs:307
No locals.
RustAudio/rodio#6  0x004d75b4 in alloc::raw_vec::RawVec<T,A>::reserve (self=<optimized out>, used_capacity=<optimized out>,
    needed_extra_capacity=<optimized out>) at /rust/lib/rustlib/src/rust/src/liballoc/raw_vec.rs:269
        layout = <optimized out>
RustAudio/rodio#7  0x004d6f40 in alloc::vec::Vec<T>::reserve (self=0x0, additional=1258328832)
    at /rust/lib/rustlib/src/rust/src/liballoc/vec.rs:500
No locals.
RustAudio/rodio#8  alloc::vec::Vec<T>::extend_with (self=0x0, n=1258328832, value=...)
    at /rust/lib/rustlib/src/rust/src/liballoc/vec.rs:1676
        ptr = <optimized out>
        local_len = <optimized out>
        iter = <optimized out>
        __next = <optimized out>
        val = <optimized out>
RustAudio/rodio#9  alloc::vec::Vec<T>::resize (self=0x0, new_len=1258328832, value=0)
    at /rust/lib/rustlib/src/rust/src/liballoc/vec.rs:1559
        len = 3066230164
        len = <optimized out>
RustAudio/rodio#10 cpal::host::alsa::poll_descriptors_and_prepare_buffer (rx=<optimized out>, stream=<optimized out>,
    ctxt=<optimized out>) at /cargo/registry/src/github.com-1ecc6299db9ec823/cpal-0.13.0/src/host/alsa/mod.rs:693
        buffer_size = 1258328832
        available_samples = <optimized out>
        delay_frames = 0
        avail_frames = <optimized out>
        status = alsa::pcm::Status ([3, 0, 0, 0, 70, 10, 0, 0, 246, 90, 238, 58, 71, 10, 0, 0, 223, 172, 110, 0,
            0, 0, 0, 0, 0, 0, 112, 73, 28, 213, 68, 252, 92, 62, 171, 3, 92, 18, 0 <repeats 14 times>, 140, 5, 0,
            0, 192, 156, 193, 39, 71, 10, 0, 0, 74, 148, 118, 0 <repeats 85 times>])
        stream_type = <optimized out>
        res = <optimized out>
        filled = <optimized out>
        len = <optimized out>
        descriptors = <optimized out>
        buffer = 0x0
RustAudio/rodio#11 0x004d6298 in cpal::host::alsa::output_stream_worker (rx=..., stream=0x622ae8, data_callback=...,
    error_callback=...) at /cargo/registry/src/github.com-1ecc6299db9ec823/cpal-0.13.0/src/host/alsa/mod.rs:548
        ctxt = cpal::host::alsa::StreamWorkerContext {descriptors: alloc::vec::Vec<libc::unix::pollfd> {buf: alloc::raw_vec::RawVec<libc::unix::pollfd, alloc::alloc::Global> {ptr: core::ptr::unique::Unique<libc::unix::pollfd> {point--Type <RET> for more, q to quit, c to continue without paging--c
er: 0xb68005b8, _marker: core::marker::PhantomData<libc::unix::pollfd>}, cap: 4, alloc: alloc::alloc::Global}, len: 2}, buffer: alloc::vec::Vec<u8> {buf: alloc::raw_vec::RawVec<u8, alloc::alloc::Global> {ptr: core::ptr::unique::Unique<u8> {pointer: 0x1 <error: Cannot access memory at address 0x1>, _marker: core::marker::PhantomData<u8>}, cap: 0, alloc: alloc::alloc::Global}, len: 0}}
RustAudio/rodio#12 0x004aea1c in cpal::host::alsa::Stream::new_output::{{closure}} () at /cargo/registry/src/github.com-1ecc6299db9ec823/cpal-0.13.0/src/host/alsa/mod.rs:870
        rx = cpal::host::alsa::TriggerReceiver (5)
        stream = alloc::sync::Arc<cpal::host::alsa::StreamInner> {ptr: core::ptr::non_null::NonNull<alloc::sync::ArcInner<cpal::host::alsa::StreamInner>> {pointer: 0x622ae0}, phantom: core::marker::PhantomData<alloc::sync::ArcInner<cpal::host::alsa::StreamInner>>}
        data_callback = cpal::traits::DeviceTrait::build_output_stream::closure-0 (rodio::stream::{{impl}}::new_output_stream_with_format::closure-1 (rodio::dynamic_mixer::DynamicMixer<f32> {current_sources: alloc::vec::Vec<alloc::boxed::Box<Source>> {buf: alloc::raw_vec::RawVec<alloc::boxed::Box<Source>, alloc::alloc::Global> {ptr: core::ptr::unique::Unique<alloc::boxed::Box<Source>> {pointer: 0x6210d8, _marker: core::marker::PhantomData<alloc::boxed::Box<Source>>}, cap: 16, alloc: alloc::alloc::Global}, len: 0}, input: alloc::sync::Arc<rodio::dynamic_mixer::DynamicMixerController<f32>> {ptr: core::ptr::non_null::NonNull<alloc::sync::ArcInner<rodio::dynamic_mixer::DynamicMixerController<f32>>> {pointer: 0x6223f8}, phantom: core::marker::PhantomData<alloc::sync::ArcInner<rodio::dynamic_mixer::DynamicMixerController<f32>>>}}))
        error_callback = rodio::stream::{{impl}}::new_output_stream_with_format::closure-0
RustAudio/rodio#13 std::sys_common::backtrace::__rust_begin_short_backtrace (f=...) at /rust/lib/rustlib/src/rust/src/libstd/sys_common/backtrace.rs:130
No locals.
RustAudio/rodio#14 0x004b0870 in std::thread::Builder::spawn_unchecked::{{closure}}::{{closure}} () at /rust/lib/rustlib/src/rust/src/libstd/thread/mod.rs:475
        f = <optimized out>
RustAudio/rodio#15 <std::panic::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once (self=..., _args=<optimized out>) at /rust/lib/rustlib/src/rust/src/libstd/panic.rs:318
No locals.
RustAudio/rodio#16 std::panicking::try::do_call (data=<optimized out>) at /rust/lib/rustlib/src/rust/src/libstd/panicking.rs:297
        f = <optimized out>
        data = <optimized out>
        data = <optimized out>
        data = <optimized out>
        data = <optimized out>
        f = <optimized out>
RustAudio/rodio#17 std::panicking::try (f=...) at /rust/lib/rustlib/src/rust/src/libstd/panicking.rs:274
        data_ptr = <optimized out>
        data = <optimized out>
        data = <optimized out>
        data_ptr = <optimized out>
RustAudio/rodio#18 std::panic::catch_unwind (f=...) at /rust/lib/rustlib/src/rust/src/libstd/panic.rs:394
No locals.
RustAudio/rodio#19 std::thread::Builder::spawn_unchecked::{{closure}} () at /rust/lib/rustlib/src/rust/src/libstd/thread/mod.rs:474
        their_thread = std::thread::Thread {inner: alloc::sync::Arc<std::thread::Inner> {ptr: core::ptr::non_null::NonNull<alloc::sync::ArcInner<std::thread::Inner>> {pointer: 0x650930}, phantom: core::marker::PhantomData<alloc::sync::ArcInner<std::thread::Inner>>}}
        f = cpal::host::alsa::{{impl}}::new_output::closure-0 (cpal::host::alsa::TriggerReceiver (5), alloc::sync::Arc<cpal::host::alsa::StreamInner> {ptr: core::ptr::non_null::NonNull<alloc::sync::ArcInner<cpal::host::alsa::StreamInner>> {pointer: 0x622ae0}, phantom: core::marker::PhantomData<alloc::sync::ArcInner<cpal::host::alsa::StreamInner>>}, cpal::traits::DeviceTrait::build_output_stream::closure-0 (rodio::stream::{{impl}}::new_output_stream_with_format::closure-1 (rodio::dynamic_mixer::DynamicMixer<f32> {current_sources: alloc::vec::Vec<alloc::boxed::Box<Source>> {buf: alloc::raw_vec::RawVec<alloc::boxed::Box<Source>, alloc::alloc::Global> {ptr: core::ptr::unique::Unique<alloc::boxed::Box<Source>> {pointer: 0x6210d8, _marker: core::marker::PhantomData<alloc::boxed::Box<Source>>}, cap: 16, alloc: alloc::alloc::Global}, len: 0}, input: alloc::sync::Arc<rodio::dynamic_mixer::DynamicMixerController<f32>> {ptr: core::ptr::non_null::NonNull<alloc::sync::ArcInner<rodio::dynamic_mixer::DynamicMixerController<f32>>> {pointer: 0x6223f8}, phantom: core::marker::PhantomData<alloc::sync::ArcInner<rodio::dynamic_mixer::DynamicMixerController<f32>>>}})), rodio::stream::{{impl}}::new_output_stream_with_format::closure-0)
        their_packet = alloc::sync::Arc<core::cell::UnsafeCell<core::option::Option<core::result::Result<(), alloc::boxed::Box<Any>>>>> {ptr: core::ptr::non_null::NonNull<alloc::sync::ArcInner<core::cell::UnsafeCell<core::option::Option<core::result::Result<(), alloc::boxed::Box<Any>>>>>> {pointer: 0x621188}, phantom: core::marker::PhantomData<alloc::sync::ArcInner<core::cell::UnsafeCell<core::option::Option<core::result::Result<(), alloc::boxed::Box<Any>>>>>>}
        name = <optimized out>
        try_result = <optimized out>
RustAudio/rodio#20 core::ops::function::FnOnce::call_once{{vtable-shim}} () at /rust/lib/rustlib/src/rust/src/libcore/ops/function.rs:232
No locals.
RustAudio/rodio#21 0x004ea65c in <alloc::boxed::Box<F> as core::ops::function::FnOnce<A>>::call_once () at /rustc/5c1f21c3b82297671ad3ae1e8c942d2ca92e84f2/src/liballoc/boxed.rs:1076
No locals.
RustAudio/rodio#22 <alloc::boxed::Box<F> as core::ops::function::FnOnce<A>>::call_once () at /rustc/5c1f21c3b82297671ad3ae1e8c942d2ca92e84f2/src/liballoc/boxed.rs:1076
No locals.
RustAudio/rodio#23 std::sys::unix::thread::Thread::new::thread_start () at src/libstd/sys/unix/thread.rs:87
No locals.
RustAudio/rodio#24 0xb6e8c494 in start_thread (arg=0xb6c303c0) at pthread_create.c:486
        ret = <optimized out>
        start = <optimized out>
        pd = 0xb6c303c0
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {537028267, 539516731, -1224742552, -1228733504, -1224796240, 338, -1090525414, -1228733504, 0, -1228734724, 0 <repeats 54 times>}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
RustAudio/rodio#25 0xb6de2578 in ?? () at ../sysdeps/unix/sysv/linux/arm/clone.S:73 from /lib/arm-linux-gnueabihf/libc.so.6
No locals.
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

zenria avatar Nov 05 '20 13:11 zenria

Running in debug mode, with backtrace:

philou@elise-rbp-mini:~ $ RUST_BACKTRACE=1 ./rbp-rodio-bug-dbg
ALSA lib pcm_dmix.c:1043:(snd_pcm_dmix_open) The dmix plugin supports only playback stream
ALSA lib pcm_dsnoop.c:575:(snd_pcm_dsnoop_open) The dsnoop plugin supports only capture stream
ALSA lib pcm_dsnoop.c:638:(snd_pcm_dsnoop_open) unable to open slave
ALSA lib pcm_dsnoop.c:638:(snd_pcm_dsnoop_open) unable to open slave
thread '<unnamed>' panicked at 'attempt to multiply with overflow', /cargo/registry/src/github.com-1ecc6299db9ec823/cpal-0.13.0/src/host/alsa/mod.rs:692:23
stack backtrace:
   0: backtrace::backtrace::libunwind::trace
             at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.46/src/backtrace/libunwind.rs:86
   1: backtrace::backtrace::trace_unsynchronized
             at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.46/src/backtrace/mod.rs:66
   2: std::sys_common::backtrace::_print_fmt
             at src/libstd/sys_common/backtrace.rs:78
   3: <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt
             at src/libstd/sys_common/backtrace.rs:59
   4: core::fmt::write
             at src/libcore/fmt/mod.rs:1076
   5: std::io::Write::write_fmt
             at src/libstd/io/mod.rs:1537
   6: std::sys_common::backtrace::_print
             at src/libstd/sys_common/backtrace.rs:62
   7: std::sys_common::backtrace::print
             at src/libstd/sys_common/backtrace.rs:49
   8: std::panicking::default_hook::{{closure}}
             at src/libstd/panicking.rs:198
   9: std::panicking::default_hook
             at src/libstd/panicking.rs:218
  10: std::panicking::rust_panic_with_hook
             at src/libstd/panicking.rs:486
  11: rust_begin_unwind
             at src/libstd/panicking.rs:388
  12: core::panicking::panic_fmt
             at src/libcore/panicking.rs:101
  13: core::panicking::panic
             at src/libcore/panicking.rs:56
  14: cpal::host::alsa::poll_descriptors_and_prepare_buffer
             at /cargo/registry/src/github.com-1ecc6299db9ec823/cpal-0.13.0/src/host/alsa/mod.rs:692
  15: cpal::host::alsa::output_stream_worker
             at /cargo/registry/src/github.com-1ecc6299db9ec823/cpal-0.13.0/src/host/alsa/mod.rs:548
  16: cpal::host::alsa::Stream::new_output::{{closure}}
             at /cargo/registry/src/github.com-1ecc6299db9ec823/cpal-0.13.0/src/host/alsa/mod.rs:870
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
thread 'main' panicked at 'called `Result::unwrap()` on an `Err` value: Any', /cargo/registry/src/github.com-1ecc6299db9ec823/cpal-0.13.0/src/host/alsa/mod.rs:883:9
stack backtrace:
   0: backtrace::backtrace::libunwind::trace
             at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.46/src/backtrace/libunwind.rs:86
   1: backtrace::backtrace::trace_unsynchronized
             at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.46/src/backtrace/mod.rs:66
   2: std::sys_common::backtrace::_print_fmt
             at src/libstd/sys_common/backtrace.rs:78
   3: <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt
             at src/libstd/sys_common/backtrace.rs:59
   4: core::fmt::write
             at src/libcore/fmt/mod.rs:1076
   5: std::io::Write::write_fmt
             at src/libstd/io/mod.rs:1537
   6: std::sys_common::backtrace::_print
             at src/libstd/sys_common/backtrace.rs:62
   7: std::sys_common::backtrace::print
             at src/libstd/sys_common/backtrace.rs:49
   8: std::panicking::default_hook::{{closure}}
             at src/libstd/panicking.rs:198
   9: std::panicking::default_hook
             at src/libstd/panicking.rs:218
  10: std::panicking::rust_panic_with_hook
             at src/libstd/panicking.rs:486
  11: rust_begin_unwind
             at src/libstd/panicking.rs:388
  12: core::panicking::panic_fmt
             at src/libcore/panicking.rs:101
  13: core::option::expect_none_failed
             at src/libcore/option.rs:1272
  14: core::result::Result<T,E>::unwrap
             at /rust/lib/rustlib/src/rust/src/libcore/result.rs:1005
  15: <cpal::host::alsa::Stream as core::ops::drop::Drop>::drop
             at /cargo/registry/src/github.com-1ecc6299db9ec823/cpal-0.13.0/src/host/alsa/mod.rs:883
  16: core::ptr::drop_in_place
             at /rust/lib/rustlib/src/rust/src/libcore/ptr/mod.rs:184
  17: core::ptr::drop_in_place
             at /rust/lib/rustlib/src/rust/src/libcore/ptr/mod.rs:184
  18: core::ptr::drop_in_place
             at /rust/lib/rustlib/src/rust/src/libcore/ptr/mod.rs:184
  19: core::ptr::drop_in_place
             at /rust/lib/rustlib/src/rust/src/libcore/ptr/mod.rs:184
  20: rbp_rodio_bug::main
             at src/main.rs:32
  21: std::rt::lang_start::{{closure}}
             at /rust/lib/rustlib/src/rust/src/libstd/rt.rs:67
  22: std::rt::lang_start_internal::{{closure}}
             at src/libstd/rt.rs:52
  23: std::panicking::try::do_call
             at src/libstd/panicking.rs:297
  24: std::panicking::try
             at src/libstd/panicking.rs:274
  25: std::panic::catch_unwind
             at src/libstd/panic.rs:394
  26: std::rt::lang_start_internal
             at src/libstd/rt.rs:51
  27: std::rt::lang_start
             at /rust/lib/rustlib/src/rust/src/libstd/rt.rs:67
  28: main
  29: __libc_start_main
             at /build/glibc-FUvrFr/glibc-2.28/csu/libc-start.c:308
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.

zenria avatar Nov 05 '20 13:11 zenria

Hmm that's interesting

The location it panics is here: https://github.com/RustAudio/cpal/blob/2220f584911d73369dce345d0540952562e23883/src/host/alsa/mod.rs#L692

est31 avatar Nov 05 '20 14:11 est31

I've put a breakpoint right there, here is the output:

(gdb) info locals
available_samples = 2462065856
delay_frames = 0
avail_frames = 1231032928
status = alsa::pcm::Status ([3, 0, 0, 0, 149, 21, 0, 0, 35, 172, 4, 57, 149, 21, 0, 0, 43, 21, 186, 57, 0, 0, 0, 0, 0, 0, 112, 73, 236, 107, 170, 244, 36, 167, 69, 11, 92, 18,
    0 <repeats 14 times>, 219, 16, 0, 0, 192, 102, 83, 38, 149, 21, 0, 0, 219, 75, 186, 57, 0 <repeats 84 times>])
stream_type = cpal::host::alsa::StreamType::Output
res = 1
filled = 1
len = 1
descriptors = 0xb6c2f634
buffer = 0xb6c2f640

zenria avatar Nov 05 '20 14:11 zenria

@zenria yeah I guess the number of available frames should be clamped by some number by above. Say 100_000?. Should be easy to fix. PRs (to cpal) welcome.

est31 avatar Nov 05 '20 15:11 est31

@est31 not sure it is the right fix, it seems more like a cross compilation mess between i32 & i64 that leads to believe there is some available frames instead of buffer underrun: https://github.com/RustAudio/cpal/blob/2220f584911d73369dce345d0540952562e23883/src/host/alsa/mod.rs#L673-L677

stream.channel.avail() is relying under the hood on a signed integer. I'm trying to build directly on the rbp to check that but it takes a lot of time. I'll update the issue when I know a bit more

zenria avatar Nov 05 '20 15:11 zenria

@zenria that might be the issue. I think a similar check should be done here to what's done to delay_frames immediately below.

est31 avatar Nov 05 '20 16:11 est31

Hi, after digging a lot into cpal alsa code and reconstructed a poll loop outside of cpal ; I found what's causing the issue on raspberry PI:

First, stream.channel.revents(&descriptors[1..]) is returning an empty value (0) 1 out of 2 call here: https://github.com/RustAudio/cpal/blob/2220f584911d73369dce345d0540952562e23883/src/host/alsa/mod.rs#L663

This triggers a pcm prepare, which harms playback: https://github.com/RustAudio/cpal/blob/2220f584911d73369dce345d0540952562e23883/src/host/alsa/mod.rs#L555

Then, calling stream.channel.status() during playback seems to destroy somehow Alsa internal state. Even on another channel not currently being in the RUNNING state: https://github.com/RustAudio/cpal/blob/2220f584911d73369dce345d0540952562e23883/src/host/alsa/mod.rs#L672

By rewriting calls to pcm::status at the only point where it's needed, I'm able to play one stream at a time on the raspberry, but not two: https://github.com/zenria/cpal/tree/fix/raspberry_avail_frames-1

And finally, I've removed any call to alsa::pcm::PCM::status here: https://github.com/zenria/cpal/tree/fix/raspberry_avail_frames-no-status I'm able to start playback on 2 streams. (but I'm only hearing one, still trying to figure out why)

zenria avatar Nov 08 '20 17:11 zenria

@zenria I tried your version on my Raspberry Pi 3B+. I have had very bad audio quality using rodio compared to mplayer for example and this patch did not change that.

With the patch I'm no longer getting an error occurred on output stream: A backend-specific error has occurred: ALSA function 'snd_pcm_prepare' failed with an error EBUSY: Device or resource busy all the time. But that might be because it is not checking for errors?

joonazan avatar Mar 15 '21 14:03 joonazan