alsa-jack issues

alsa-jack issues

[Radoslaw Szkodzinski]

Hello,

A recent change in alsa-plugins 1.0.28 alsa-jack has changed the poll semantics.
This breaks audacious and mpv, perhaps more applications.

The regression is caused by:
Commit: 9217377337cdceb62abeb5969112b738bb5cd551
jack: fix polling and recovering


This might or might not be related to lack of
snd_pcm_poll_descriptor_revents call or the use of a timer instead of
repolling.

Another major problem is the lack of handling of DRAINING state. This
breaks short sample playback with aplay and possibly other
applications. That also was present in older alsa-jack and is not a
regression.

-- 
Radosław Szkodziński
_______________________________________________
Alsa-devel mailing list
Alsa-devel@alsa-project.org
http://mailman.alsa-project.org/mailman/listinfo/alsa-devel

Re: alsa-jack issues

[Takashi Iwai]

At Sat, 6 Sep 2014 07:09:17 +0200,
Radoslaw Szkodzinski wrote:
> 
> Hello,
> 
> A recent change in alsa-plugins 1.0.28 alsa-jack has changed the poll semantics.
> This breaks audacious and mpv, perhaps more applications.

Could you elaborate more?  What's broken and how?

> The regression is caused by:
> Commit: 9217377337cdceb62abeb5969112b738bb5cd551
> jack: fix polling and recovering

Let's add the patch author to Cc.

> This might or might not be related to lack of
> snd_pcm_poll_descriptor_revents call or the use of a timer instead of
> repolling.
> 
> Another major problem is the lack of handling of DRAINING state. This
> breaks short sample playback with aplay and possibly other
> applications. That also was present in older alsa-jack and is not a
> regression.

A fix patch is welcome :)  I guess this won't be too difficult to
implement.


Takashi

Re: alsa-jack issues

[Radoslaw Szkodzinski]

On Thu, Sep 11, 2014 at 1:33 AM, Sergey <sergemp@mail.ru> wrote:
> Sat, 6 Sep 2014 Radoslaw Szkodzinski wrote:
>
>>A recent change in alsa-plugins 1.0.28 alsa-jack has changed the poll semantics.
>>This breaks audacious and mpv, perhaps more applications.
>>
>>The regression is caused by:
>>Commit: 9217377337cdceb62abeb5969112b738bb5cd551
>>jack: fix polling and recovering
>
> I'm initial author of this commit and I'd love to fix the issue,
> but it never happens to me. I need your help to fix it.
>
> Can you provide some steps to reproduce this bug? How much time it
> takes to reproduce it? Can you reproduce it with alsa 1.0.27 and
> alsa-jack plugin 1.0.28? You can download that plugin separately:

I'll test this during the weekend. 1.0.27.x was fine with alsa 1.0.27.

> By the way, what distribution are you using?
> Is there a livecd that I can download to reproduce this problem?

This is actually Gentoo, so not really. However, I think it should be
reproducible anywhere.

>>This might or might not be related to lack of
>>snd_pcm_poll_descriptor_revents call or the use of a timer instead of
>>repolling.
>
> It should not. But we can't be sure until we find what causes it.

I'm not entirely sure myself. The above mentioned applications cause
the problem.
The whole setup consists of:

Highly patched 3.12.x kernel, no RT patches but in full preempt mode.
Jack2 in DBus mode, realtime and mlock enabled. ALSA output to ICE1724
soundcard, sample rate matched everywhere to 44.1kHz.
ALSA set to use speexrate_best and 44.1kHz by default if this is important.

Applications:
Ladish
Carla with Caps equalizers and one other personal LADSPA plugin (RT safe).
Directly connecting to playback also reproduces the issue.

Any period size and nframes, though very long period sizes vastly
reduce the likelihood this is reproducible.
It is not related to xruns directly, but an xrun can precipitate the issue too.

Reproducible in audacious 3.4.1 or older and mpv (git revision, from
this month or older), but not with sox or aplay.
No problems with direct Jack outputs of the above applications whatsoever.

Both of the problematic applications use a sleep timer in addition or
instead of polling. (audacious due to a bug, mpv by design I think)

> I'm sorry for bothering you.

Not a bother at all, I'd like to see this fixed.

R.

Re: alsa-jack issues

[Radoslaw Szkodzinski]

[-- Attachment #1: Type: text/plain, Size: 1769 bytes --]

On Thu, Sep 11, 2014 at 11:02 AM, Radoslaw Szkodzinski
<astralstorm@gmail.com> wrote:
> On Thu, Sep 11, 2014 at 1:33 AM, Sergey <sergemp@mail.ru> wrote:
>> Sat, 6 Sep 2014 Radoslaw Szkodzinski wrote:
>>
>>>A recent change in alsa-plugins 1.0.28 alsa-jack has changed the poll semantics.
>>>This breaks audacious and mpv, perhaps more applications.
>>>
>>>The regression is caused by:
>>>Commit: 9217377337cdceb62abeb5969112b738bb5cd551
>>>jack: fix polling and recovering
>>
>> I'm initial author of this commit and I'd love to fix the issue,
>> but it never happens to me. I need your help to fix it.
>>
>> Can you provide some steps to reproduce this bug? How much time it
>> takes to reproduce it? Can you reproduce it with alsa 1.0.27 and
>> alsa-jack plugin 1.0.28? You can download that plugin separately:
>
> I'll test this during the weekend. 1.0.27.x was fine with alsa 1.0.27.

Sorry it took this long, the following version is fine:
media-plugins/alsa-plugins-1.0.27-r3 was built with the following:
USE="ffmpeg jack libsamplerate speex -debug -pulseaudio" ABI_X86="32 64 -x32"

It takes between 1 and 10 minutes to reproduce the bug with alsa-plugins-1.0.28.

Alsa-lib info is in both cases:
media-libs/alsa-lib-1.0.28 was built with the following:
USE="python -alisp -debug -doc" ABI_X86="32 64 -x32"
PYTHON_SINGLE_TARGET="python2_7" PYTHON_TARGETS="python2_7"

I'm somewhat suspicious is it caused by a wrong Jack buffer size, and
only masked by incorrect handling of buffer fill in the older version.
Verbose log from aplay is attached (w/ alsa-jack 1.0.27.x).
Note the discrepancy between JackClient period size (not divisible by
actual period size) and ALSA min_avail.

Best regards,
-- 
Radosław Szkodziński

[-- Attachment #2: aplay-jack.log --]
[-- Type: text/plain, Size: 6701 bytes --]

jack_client_new: deprecated
Jack: JackClient::SetupDriverSync driver sem in flush mode
Jack: JackPosixSemaphore::Connect name = jack_sem.1000_default_alsa-jack.jackP.21511.0
Jack: JackPosixSemaphore::Connect sem_getvalue 0
Jack: Clock source : unknown
Jack: JackLibClient::Open name = alsa-jack.jackP.21511.0 refnum = 6
Playing WAVE '/usr/share/sounds/login.wav' : Signed 16 bit Little Endian, Rate 44100 Hz, Stereo
Jack: JackClient::PortRegister ref = 6 name = alsa-jack.jackP.21511.0:out_000 type = 32 bit float mono audio port_index = 34
Jack: JackClient::PortRegister ref = 6 name = alsa-jack.jackP.21511.0:out_001 type = 32 bit float mono audio port_index = 35
Plug PCM: Linear Integer <-> Linear Float conversion PCM (FLOAT_LE)
Its setup is:
  stream       : PLAYBACK
  access       : RW_INTERLEAVED
  format       : S16_LE
  subformat    : STD
  channels     : 2
  rate         : 44100
  exact rate   : 44100 (44100/1)
  msbits       : 16
  buffer_size  : 22050
  period_size  : 5512
  period_time  : 125000
  tstamp_mode  : NONE
  period_step  : 1
  avail_min    : 5512
  period_event : 0
  start_threshold  : 22050
  stop_threshold   : 22050
  silence_threshold: 0
  silence_size : 0
  boundary     : 6206523236469964800
Slave: ALSA <-> JACK PCM I/O Plugin
Its setup is:
  stream       : PLAYBACK
  access       : MMAP_INTERLEAVED
  format       : FLOAT_LE
  subformat    : STD
  channels     : 2
  rate         : 44100
  exact rate   : 44100 (44100/1)
  msbits       : 32
  buffer_size  : 22050
  period_size  : 5512
  period_time  : 125000
  tstamp_mode  : NONE
  period_step  : 1
  avail_min    : 5512
  period_event : 0
  start_threshold  : 22050
  stop_threshold   : 22050
  silence_threshold: 0
  silence_size : 0
  boundary     : 6206523236469964800
Max peak (11024 samples): 0x00001fe1 #####                24%
Max peak (11024 samples): 0x00002fc5 ########             37%
Max peak (11024 samples): 0x000032e2 ########             39%
Max peak (11024 samples): 0x000042e2 ###########          52%
Jack: JackClient::Activate
Jack: JackPosixThread::StartImp : create non RT thread
Jack: JackPosixThread::ThreadHandler : start
Jack: JackClient::kBufferSizeCallback buffer_size = 256
Jack: JackClient::Init : period = 5804 computation = 100 constraint = 5804
Jack: JackPosixThread::AcquireRealTimeImp priority = 10
Jack: JackClient::ClientNotify ref = 6 name = alsa-jack.jackP.21511.0 notify = 2
Jack: JackClient::kActivateClient name = alsa-jack.jackP.21511.0 ref = 6 
Jack: JackClient::Connect src = alsa-jack.jackP.21511.0:out_000 dst = Carla:Advanced Crossfeed:in0
Jack: JackClient::ClientNotify ref = 6 name = alsa-jack.jackP.21511.0 notify = 18
Jack: JackClient::ClientNotify ref = 6 name = alsa-jack.jackP.21511.0 notify = 18
Jack: JackClient::Connect src = alsa-jack.jackP.21511.0:out_001 dst = Carla:Advanced Crossfeed:in1
Jack: JackClient::ClientNotify ref = 6 name = alsa-jack.jackP.21511.0 notify = 18
Jack: JackClient::ClientNotify ref = 6 name = alsa-jack.jackP.21511.0 notify = 18
Max peak (11024 samples): 0x0000505a #############        62%
Max peak (11024 samples): 0x0000416b ###########          51%
Max peak (11024 samples): 0x00005235 #############        64%
Max peak (11024 samples): 0x000057a4 ##############       68%
Max peak (11024 samples): 0x00007fa8 #################### 99%
Max peak (11024 samples): 0x00006644 ################     79%
Max peak (11024 samples): 0x000062a7 ################     77%
Max peak (11024 samples): 0x00004615 ###########          54%
Max peak (11024 samples): 0x00005f0f ###############      74%
Max peak (11024 samples): 0x00006aa0 #################    83%
Max peak (11024 samples): 0x00005f61 ###############      74%
Max peak (11024 samples): 0x000051eb #############        63%
Max peak (11024 samples): 0x000069a5 #################    82%
Max peak (11024 samples): 0x00005a9b ###############      70%
Max peak (11024 samples): 0x00004599 ###########          54%
Max peak (11024 samples): 0x00003526 #########            41%
Max peak (11024 samples): 0x000034bc #########            41%
Max peak (11024 samples): 0x00002a6e #######              33%
Max peak (11024 samples): 0x00002d82 ########             35%
Max peak (11024 samples): 0x000023a9 ######               27%
Max peak (11024 samples): 0x000019c9 #####                20%
Max peak (11024 samples): 0x00001271 ###                  14%
Max peak (11024 samples): 0x0000126a ###                  14%
Max peak (11024 samples): 0x0000101b ###                  12%
Max peak (11024 samples): 0x00000936 ##                   7%
Max peak (11024 samples): 0x0000096e ##                   7%
Max peak (11024 samples): 0x00000711 ##                   5%
Max peak (11024 samples): 0x000006be ##                   5%
Max peak (11024 samples): 0x000004f9 #                    3%
Max peak (11024 samples): 0x000003b1 #                    2%
Max peak (11024 samples): 0x0000031f #                    2%
Max peak (11024 samples): 0x00000378 #                    2%
Max peak (11024 samples): 0x0000022a #                    1%
Max peak (11024 samples): 0x00000261 #                    1%
Max peak (11024 samples): 0x0000022b #                    1%
Max peak (11024 samples): 0x00000172 #                    1%
Max peak (11024 samples): 0x00000117 #                    0%
Jack: JackClient::Deactivate
Jack: JackClient::Deactivate res = 0
Jack: JackPosixThread::Kill
Jack: jack_client_close
Jack: JackClient::Close ref = 6
Jack: JackClient::Deactivate
Jack: JackSocketClientChannel::Stop
Jack: JackPosixThread::Kill
Jack: JackClientSocket::Close
Jack: JackClientSocket::Close
Jack: JackPosixSemaphore::Disconnect name = jack_sem.1000_default_alsa-jack.jackP.21511.0
Jack: JackLibClient::~JackLibClient
Jack: JackShmReadWritePtr1::~JackShmReadWritePtr1 5
Jack: Succeeded in unlocking 422 byte memory area
Jack: JackLibGlobals Destroy ae6d9890
Jack: ~JackLibGlobals
Jack: JackPosixSemaphore::Disconnect name = jack_sem.1000_default_system
Jack: JackPosixSemaphore::Disconnect name = jack_sem.1000_default_freewheel
Jack: JackPosixSemaphore::Disconnect name = jack_sem.1000_default_dbusapi
Jack: JackPosixSemaphore::Disconnect name = jack_sem.1000_default_Carla
Jack: JackPosixSemaphore::Disconnect name = jack_sem.1000_default_alsa-jack.jackP.14807.41
Jack: JackPosixSemaphore::Disconnect name = jack_sem.1000_default_alsa-jack.jackP.21274.0
Jack: no message buffer overruns
Jack: JackPosixThread::Stop
Jack: JackPosixThread::ThreadHandler : exit
Jack: JackShmReadWritePtr::~JackShmReadWritePtr 1
Jack: Succeeded in unlocking 1186 byte memory area
Jack: JackShmReadWritePtr::~JackShmReadWritePtr 0
Jack: Succeeded in unlocking 21701018 byte memory area
Jack: jack_client_close res = 0


[-- Attachment #3: Type: text/plain, Size: 0 bytes --]