Possible ALSA loopback bug?

Possible ALSA loopback bug?

[Timothy Pearson]

I've been running a dedicated machine with ALSA loopback, feeding
darkice on the capture side and (currently) using mplayer to provide
audio on the playback side.  I've seen sporadic hangs for a couple of
years on this setup, but recently with the switch to mplayer I have
additional information that points more to ALSA than the other applications.

When the audio hangs, mplayer prints a continuous stream of:
"Audio device got stuck!"

The only way to "unstick" the audio stream is to terminate and restart
mplayer.  Restarting darkice does not fix the stuck stream.  There is no
pulseaudio on this sytem.

What would be the next steps to debug this setup?  It's shown up on two
entirely different installs at this point (Ubuntu 14.04 and Debian 9).

Thanks!

-- 
Timothy Pearson
Raptor Engineering
+1 (415) 727-8645 (direct line)
+1 (512) 690-0200 (switchboard)
https://www.raptorengineering.com

Re: Possible ALSA loopback bug?

[Timothy Pearson]

On 01/20/2019 07:00 PM, Timothy Pearson wrote:
> I've been running a dedicated machine with ALSA loopback, feeding
> darkice on the capture side and (currently) using mplayer to provide
> audio on the playback side.  I've seen sporadic hangs for a couple of
> years on this setup, but recently with the switch to mplayer I have
> additional information that points more to ALSA than the other applications.
> 
> When the audio hangs, mplayer prints a continuous stream of:
> "Audio device got stuck!"
> 
> The only way to "unstick" the audio stream is to terminate and restart
> mplayer.  Restarting darkice does not fix the stuck stream.  There is no
> pulseaudio on this sytem.
> 
> What would be the next steps to debug this setup?  It's shown up on two
> entirely different installs at this point (Ubuntu 14.04 and Debian 9).
> 
> Thanks!

A bit of additional information:  before audio output ceases entirely,
the messages start printing and the audio becomes very choppy.  The
system has no processes stuck at 100% CPU or any other visible signs of
duress during this time.

Suggestions on debug are welcome!

-- 
Timothy Pearson
Raptor Engineering
+1 (415) 727-8645 (direct line)
+1 (512) 690-0200 (switchboard)
https://www.raptorengineering.com

Re: Possible ALSA loopback bug?

[Takashi Iwai]

On Mon, 21 Jan 2019 22:38:19 +0100,
Timothy Pearson wrote:
> 
> On 01/20/2019 07:00 PM, Timothy Pearson wrote:
> > I've been running a dedicated machine with ALSA loopback, feeding
> > darkice on the capture side and (currently) using mplayer to provide
> > audio on the playback side.  I've seen sporadic hangs for a couple of
> > years on this setup, but recently with the switch to mplayer I have
> > additional information that points more to ALSA than the other applications.
> > 
> > When the audio hangs, mplayer prints a continuous stream of:
> > "Audio device got stuck!"
> > 
> > The only way to "unstick" the audio stream is to terminate and restart
> > mplayer.  Restarting darkice does not fix the stuck stream.  There is no
> > pulseaudio on this sytem.
> > 
> > What would be the next steps to debug this setup?  It's shown up on two
> > entirely different installs at this point (Ubuntu 14.04 and Debian 9).
> > 
> > Thanks!
> 
> A bit of additional information:  before audio output ceases entirely,
> the messages start printing and the audio becomes very choppy.  The
> system has no processes stuck at 100% CPU or any other visible signs of
> duress during this time.
> 
> Suggestions on debug are welcome!

The whole story above indicates merely a message like infamous TeX
error, "something is wrong" :)  We need more detailed information.

For example, how is the PCM status of each running PCM stream when
this happens?  Also, track where the application gets stuck, what was
expected but what didn't happen.  You can see it via gdb or whatever.


thanks,

Takashi

Re: Possible ALSA loopback bug?

[Timothy Pearson]

On 01/22/2019 11:13 AM, Takashi Iwai wrote:
> On Mon, 21 Jan 2019 22:38:19 +0100,
> Timothy Pearson wrote:
>>
>> On 01/20/2019 07:00 PM, Timothy Pearson wrote:
>>> I've been running a dedicated machine with ALSA loopback, feeding
>>> darkice on the capture side and (currently) using mplayer to provide
>>> audio on the playback side.  I've seen sporadic hangs for a couple of
>>> years on this setup, but recently with the switch to mplayer I have
>>> additional information that points more to ALSA than the other applications.
>>>
>>> When the audio hangs, mplayer prints a continuous stream of:
>>> "Audio device got stuck!"
>>>
>>> The only way to "unstick" the audio stream is to terminate and restart
>>> mplayer.  Restarting darkice does not fix the stuck stream.  There is no
>>> pulseaudio on this sytem.
>>>
>>> What would be the next steps to debug this setup?  It's shown up on two
>>> entirely different installs at this point (Ubuntu 14.04 and Debian 9).
>>>
>>> Thanks!
>>
>> A bit of additional information:  before audio output ceases entirely,
>> the messages start printing and the audio becomes very choppy.  The
>> system has no processes stuck at 100% CPU or any other visible signs of
>> duress during this time.
>>
>> Suggestions on debug are welcome!
> 
> The whole story above indicates merely a message like infamous TeX
> error, "something is wrong" :)  We need more detailed information.

That's what I had guessed, but I am not familiar enough with the ALSA
stack to know what would be useful for debugging or how to get it.  The
loopback module is in kernel, which makes debug even more fun.

I recently determined that the capture end of the loopback device
(darkice) reports "Buffer overrun".  Given that, my next question
becomes what happens if capture stops / stalls on an ALSA loopback
device?  Is this expected to be recoverable without restarting both ends
of the loopback (playback and capture) or am I asking ALSA to do
something it isn't designed to do?

> For example, how is the PCM status of each running PCM stream when
> this happens?  Also, track where the application gets stuck, what was
> expected but what didn't happen.  You can see it via gdb or whatever.

How would I get the PCM status?

> 
> thanks,
> 
> Takashi


-- 
Timothy Pearson
Raptor Engineering
+1 (415) 727-8645 (direct line)
+1 (512) 690-0200 (switchboard)
https://www.raptorengineering.com

Re: Possible ALSA loopback bug?

[Takashi Iwai]

On Tue, 22 Jan 2019 18:16:52 +0100,
Timothy Pearson wrote:
> 
> On 01/22/2019 11:13 AM, Takashi Iwai wrote:
> > On Mon, 21 Jan 2019 22:38:19 +0100,
> > Timothy Pearson wrote:
> >>
> >> On 01/20/2019 07:00 PM, Timothy Pearson wrote:
> >>> I've been running a dedicated machine with ALSA loopback, feeding
> >>> darkice on the capture side and (currently) using mplayer to provide
> >>> audio on the playback side.  I've seen sporadic hangs for a couple of
> >>> years on this setup, but recently with the switch to mplayer I have
> >>> additional information that points more to ALSA than the other applications.
> >>>
> >>> When the audio hangs, mplayer prints a continuous stream of:
> >>> "Audio device got stuck!"
> >>>
> >>> The only way to "unstick" the audio stream is to terminate and restart
> >>> mplayer.  Restarting darkice does not fix the stuck stream.  There is no
> >>> pulseaudio on this sytem.
> >>>
> >>> What would be the next steps to debug this setup?  It's shown up on two
> >>> entirely different installs at this point (Ubuntu 14.04 and Debian 9).
> >>>
> >>> Thanks!
> >>
> >> A bit of additional information:  before audio output ceases entirely,
> >> the messages start printing and the audio becomes very choppy.  The
> >> system has no processes stuck at 100% CPU or any other visible signs of
> >> duress during this time.
> >>
> >> Suggestions on debug are welcome!
> > 
> > The whole story above indicates merely a message like infamous TeX
> > error, "something is wrong" :)  We need more detailed information.
> 
> That's what I had guessed, but I am not familiar enough with the ALSA
> stack to know what would be useful for debugging or how to get it.  The
> loopback module is in kernel, which makes debug even more fun.
> 
> I recently determined that the capture end of the loopback device
> (darkice) reports "Buffer overrun".  Given that, my next question
> becomes what happens if capture stops / stalls on an ALSA loopback
> device?  Is this expected to be recoverable without restarting both ends
> of the loopback (playback and capture) or am I asking ALSA to do
> something it isn't designed to do?

If it's about buffer overrun (or underrun for playback), more often
it's an application-side problem that doesn't recover the stream
properly.

> > For example, how is the PCM status of each running PCM stream when
> > this happens?  Also, track where the application gets stuck, what was
> > expected but what didn't happen.  You can see it via gdb or whatever.
> 
> How would I get the PCM status?

You can check it in /proc/asound/card*/pcm*/....
If the stream gets stuck as XRUN state, it implies that the
application didn't treat it right.


HTH,

Takashi

Re: Possible ALSA loopback bug?

[Timothy Pearson]

On 01/22/2019 11:21 AM, Takashi Iwai wrote:
> On Tue, 22 Jan 2019 18:16:52 +0100,
> Timothy Pearson wrote:
>>
>> On 01/22/2019 11:13 AM, Takashi Iwai wrote:
>>> On Mon, 21 Jan 2019 22:38:19 +0100,
>>> Timothy Pearson wrote:
>>>>
>>>> On 01/20/2019 07:00 PM, Timothy Pearson wrote:
>>>>> I've been running a dedicated machine with ALSA loopback, feeding
>>>>> darkice on the capture side and (currently) using mplayer to provide
>>>>> audio on the playback side.  I've seen sporadic hangs for a couple of
>>>>> years on this setup, but recently with the switch to mplayer I have
>>>>> additional information that points more to ALSA than the other applications.
>>>>>
>>>>> When the audio hangs, mplayer prints a continuous stream of:
>>>>> "Audio device got stuck!"
>>>>>
>>>>> The only way to "unstick" the audio stream is to terminate and restart
>>>>> mplayer.  Restarting darkice does not fix the stuck stream.  There is no
>>>>> pulseaudio on this sytem.
>>>>>
>>>>> What would be the next steps to debug this setup?  It's shown up on two
>>>>> entirely different installs at this point (Ubuntu 14.04 and Debian 9).
>>>>>
>>>>> Thanks!
>>>>
>>>> A bit of additional information:  before audio output ceases entirely,
>>>> the messages start printing and the audio becomes very choppy.  The
>>>> system has no processes stuck at 100% CPU or any other visible signs of
>>>> duress during this time.
>>>>
>>>> Suggestions on debug are welcome!
>>>
>>> The whole story above indicates merely a message like infamous TeX
>>> error, "something is wrong" :)  We need more detailed information.
>>
>> That's what I had guessed, but I am not familiar enough with the ALSA
>> stack to know what would be useful for debugging or how to get it.  The
>> loopback module is in kernel, which makes debug even more fun.
>>
>> I recently determined that the capture end of the loopback device
>> (darkice) reports "Buffer overrun".  Given that, my next question
>> becomes what happens if capture stops / stalls on an ALSA loopback
>> device?  Is this expected to be recoverable without restarting both ends
>> of the loopback (playback and capture) or am I asking ALSA to do
>> something it isn't designed to do?
> 
> If it's about buffer overrun (or underrun for playback), more often
> it's an application-side problem that doesn't recover the stream
> properly.
> 
>>> For example, how is the PCM status of each running PCM stream when
>>> this happens?  Also, track where the application gets stuck, what was
>>> expected but what didn't happen.  You can see it via gdb or whatever.
>>
>> How would I get the PCM status?
> 
> You can check it in /proc/asound/card*/pcm*/....
> If the stream gets stuck as XRUN state, it implies that the
> application didn't treat it right.

After the latest lockup, using "cat card*/pcm*/*/status", both streams
are showing RUNNING.  One curiosity is that the playback side owner PID
doesn't match the mplayer PID, while the capture side owner PID matches
the running darkice process.

mplayer is jammed waiting in fill_audio_out_buffers():

Thread 1 (Thread 0x7fffb3d466f0 (LWP 28629)):
#0  0x00007fffbd096dd8 in __nanosleep_nocancel () at
../sysdeps/unix/syscall-template.S:84
#1  0x0000000120e1a81c in usec_sleep (usec_delay=<optimized out>) at
osdep/timer-linux.c:42
#2  0x0000000120cb94c8 in fill_audio_out_buffers () at mplayer.c:2171
#3  main (argc=<optimized out>, argv=<optimized out>) at mplayer.c:3794
(gdb)

Unfortunately the sleep time was optimized out, but I suspect it grows
very large as mplayer eventually just waits forever in usleep().  The
formula used to determine sleep time is roughly:

bytes_to_write = mpctx->audio_out->get_space();
sleep_time = (ao_data.outburst - bytes_to_write) * 1000 / ao_data.bps;

This further supports the idea that ALSA simply stops accepting new data
for an unknown reason.

I'd be happy to dig further if there's anything that would help!

-- 
Timothy Pearson
Raptor Engineering
+1 (415) 727-8645 (direct line)
+1 (512) 690-0200 (switchboard)
https://www.raptorengineering.com