Bug 90489

Summary:	[regression] DYNAMIC_LATENCY introduced in module-combine causes a race contition between pa_sink_render_into_full and sink_update_requested_latency_cb in alsa-sink.c
Product:	PulseAudio	Reporter:	M132 <marcel132132>
Component:	modules	Assignee:	pulseaudio-bugs
Status:	RESOLVED FIXED	QA Contact:	pulseaudio-bugs
Severity:	normal
Priority:	medium	CC:	jiri.tyr, lennart, mtijink.bugs
Version:	unspecified
Hardware:	All
OS:	All
Whiteboard:
i915 platform:		i915 features:
Bug Depends on:
Bug Blocks:	88920

Description M132 2015-05-17 05:41:24 UTC

When sink_update_requested_latency() in src/modules/module-combine-sink.c:790 is called, it posts a SINK_INPUT_MESSAGE_SET_REQUESTED_LATENCY message to all of it's output sinks. If one of the sinks is created by module-alsa-sink, sink_update_requested_latency_cb() in src/alsa/alsa-sink.c:1507 is called to handle the latency change. This function, except updating the latency, sometimes also creates a rewind request. 

If the rewind request gets processed before the pa_sink_render_into_full() is called, everything will work as supposed. However if not, the "!s->thread_info.rewind_requested" assertion is being triggered on src/pulsecore/sink.c:1323, causing whole server to abort.

Commit that introduced this is here: http://cgit.freedesktop.org/pulseaudio/pulseaudio/commit/?id=23f120aabbf4d48d7012e196cf95d89ec6b6d8c8

Here's the part of PulseAudio's output:

[...]
I: [pulseaudio] protocol-native.c: Requested tlength=272,11 ms, minreq=20,00 ms
D: [pulseaudio] protocol-native.c: Adjust latency mode enabled, configuring sink latency to half of overall latency.
D: [pulseaudio] protocol-native.c: Requested latency=116,05 ms, Received latency=116,05 ms
D: [pulseaudio] memblockq.c: memblockq requested: maxlength=4194304, tlength=27528, base=4, prebuf=24004, minreq=3528 maxrewind=0
D: [pulseaudio] memblockq.c: memblockq sanitized: maxlength=4194304, tlength=27528, base=4, prebuf=24004, minreq=3528 maxrewind=0
I: [pulseaudio] protocol-native.c: Final latency 272,11 ms = 116,05 ms + 2*20,00 ms + 116,05 ms
D: [combine] module-combine-sink.c: Sink update requested latency 116,05
D: [combine] protocol-native.c: max_request changed, trying to update from 27528 to 42336.
D: [combine] protocol-native.c: Notifying client about increased tlength
D: [alsa-sink-CX20757 Analog] alsa-sink.c: Latency set to 116,05ms
D: [alsa-sink-CX20757 Analog] alsa-sink.c: hwbuf_unused=332300
D: [alsa-sink-CX20757 Analog] alsa-sink.c: setting avail_min=87311
D: [alsa-sink-CX20757 Analog] module-combine-sink.c: Sink input update max request 20468
D: [alsa-sink-CX20757 Analog] alsa-sink.c: Requesting rewind due to latency change.
D: [combine] module-combine-sink.c: Sink update max request 20468
E: [alsa-sink-CX20757 Analog] sink.c: Assertion '!s->thread_info.rewind_requested' failed at pulsecore/sink.c:1239, 

The assertion is almost always triggered when following conditions are met:

- /etc/pulse/default.pa contains:

# alsa_output.pci-0000_00_14.2.analog-stereo is the name of default output sink
load-module module-combine-sink sink_name=media slaves=alsa_output.pci-0000_00_14.2.analog-stereo resample_method=speex-float-1 format=s16le rate=44100 channels=2 
load-module module-sine sink=media frequency=440

set-default-source media.monitor

- module-sine's outputs to the sink created by module-combine-sink and is muted
- Audacity is starting while some program (Rhythmbox in my case) is playing sounds using the native protocol.

Comment 1 Raymond 2015-05-17 08:29:52 UTC

http://cgit.freedesktop.org/pulseaudio/pulseaudio/patch/src/modules/module-combine-sink.c?id=512baa1a1fdb58f2d39882ac9d1660da7b8b21be


+PA_MODULE_DEPRECATED("Please use module-combine-sink instead of module-combine!");

Comment 2 Raymond 2015-05-17 08:38:53 UTC

 module-combine-sink sink_name=media slaves=alsa_output.pci-0000_00_14.2.analog-stereo resample_method=speex-float-1 format=s16le rate=44100 channels=2

why only one slave instead of two slaves?

Comment 3 M132 2015-05-17 14:06:36 UTC

While writing the title of the bug, I actually meant module-combine-sink.

I'm using module-combine-sink with one slave, because of another bug, described here: https://bugs.freedesktop.org/show_bug.cgi?id=79807

However, the bug isn't probably triggered because of this. I've had the same setup with PulseAudio 5.0, and everything was working flawlessly.

Comment 4 Raymond 2015-05-17 16:01:46 UTC

take a look at datasheet, one of ADC can record DAC signal through node 0x15

Comment 5 M132 2015-05-17 16:38:54 UTC

???

Comment 6 Raymond 2015-05-18 05:21:03 UTC

Codec: Conexant CX20757
Address: 0
AFG Function Id: 0x1 (unsol 1)
Vendor Id: 0x14f15115
Subsystem Id: 0x17aac03d
Revision Id: 0x100100
No Modem Function Group found
Default PCM:
    rates [0x160]: 44100 48000 96000
    bits [0xe]: 16 20 24
    formats [0x1]: PCM
Default Amp-In caps: N/A
Default Amp-Out caps: N/A
State of AFG node 0x01:
  Power states:  D0 D1 D2 D3 D3cold S3D3cold CLKSTOP EPSS
  Power: setting=D0, actual=D0
GPIO: io=3, o=0, i=0, unsolicited=1, wake=0
  IO[0]: enable=0, dir=0, wake=0, sticky=0, data=0, unsol=0
  IO[1]: enable=0, dir=0, wake=0, sticky=0, data=0, unsol=0
  IO[2]: enable=0, dir=0, wake=0, sticky=0, data=0, unsol=0
Node 0x10 [Audio Output] wcaps 0xc1d: Stereo Amp-Out R/L
  Control: name="Headphone Playback Volume", index=0, device=0
    ControlAmp: chs=3, dir=Out, idx=0, ofs=0
  Control: name="Headphone Playback Switch", index=0, device=0
    ControlAmp: chs=3, dir=Out, idx=0, ofs=0
  Device: name="CX20757 Analog", type="Audio", device=0
  Amp-Out caps: ofs=0x4a, nsteps=0x4a, stepsize=0x03, mute=1
  Amp-Out vals:  [0x80 0x80]
  Converter: stream=8, channel=0
  PCM:
    rates [0x60]: 44100 48000
    bits [0xa]: 16 24
    formats [0x1]: PCM
  Power states:  D0 D1 D2 D3 EPSS
  Power: setting=D0, actual=D0
Node 0x11 [Audio Output] wcaps 0xc1d: Stereo Amp-Out R/L
  Control: name="Speaker Playback Volume", index=0, device=0
    ControlAmp: chs=3, dir=Out, idx=0, ofs=0
  Control: name="Speaker Playback Switch", index=0, device=0
    ControlAmp: chs=3, dir=Out, idx=0, ofs=0
  Amp-Out caps: ofs=0x4a, nsteps=0x4a, stepsize=0x03, mute=1
  Amp-Out vals:  [0x4a 0x4a]
  Converter: stream=8, channel=0
  PCM:
    rates [0x60]: 44100 48000
    bits [0xa]: 16 24
    formats [0x1]: PCM
  Power states:  D0 D1 D2 D3 EPSS
  Power: setting=D0, actual=D0


Node 0x14 [Audio Input] wcaps 0x100d1b: Stereo Amp-In R/L
  Amp-In caps: ofs=0x4a, nsteps=0x50, stepsize=0x03, mute=1
  Amp-In vals:  [0x4a 0x4a] [0x4a 0x4a] [0x4a 0x4a]
  Converter: stream=0, channel=0
  SDI-Select: 0
  PCM:
    rates [0x160]: 44100 48000 96000
    bits [0xa]: 16 24
    formats [0x1]: PCM
  Power states:  D0 D1 D2 D3 EPSS
  Power: setting=D0, actual=D0
  Connection: 3
     0x19* 0x1a 0x15

Node 0x15 [Audio Mixer] wcaps 0x20050b: Stereo Amp-In
  Amp-In caps: ofs=0x4a, nsteps=0x4a, stepsize=0x03, mute=1
  Amp-In vals:  [0x00 0x00] [0x00 0x00]
  Power states:  D0 D1 D2 D3 EPSS
  Power: setting=D0, actual=D0
  Connection: 2
     0x10 0x11

Comment 7 M132 2015-05-18 12:55:59 UTC

Thanks, but I'd still like to record directly from the PulseAudio server, without distortion caused by digital to analog and analog to digital conversions.

Comment 8 Raymond 2015-05-18 14:32:36 UTC

do you mean your combined-sink is not the default sink ?

Comment 9 M132 2015-05-18 17:42:18 UTC

Yes, I manually select which applications I want to record, in pavucontrol.

Comment 10 Raymond 2015-05-19 01:48:50 UTC

D: [alsa-sink-CX20757 Analog] alsa-sink.c: Latency set to 116,05ms
D: [alsa-sink-CX20757 Analog] alsa-sink.c: hwbuf_unused=332300
D: [alsa-sink-CX20757 Analog] alsa-sink.c: setting avail_min=87311


hwbuf_unused is strange

seem snd_hda_prealloc_max is neither 64 nor 4096 

between 0.371 second or 23.7 second buffer

Comment 11 Tanu Kaskinen 2015-05-27 09:51:30 UTC

Regression, marking as a release blocker.

Comment 12 Tanu Kaskinen 2015-05-30 11:51:49 UTC

I looked a bit into this. The problem is that module-combine-sink can generate rewind requests during the sink input pop() callback. That should never happen. Each output struct has member inq, which is a message queue containing messages from the combine sink thread to the output thread. There are basically only two messages that are transmitted in that queue: POST and SET_REQUESTED_LATENCY. Processing a SET_REQUESTED_LATENCY message results in a rewind request.

There are two places where the message queue may get processed during the pop() callback: render_memblock() and request_memblock() both call pa_asyncmsgq_process_one() in a loop to make sure the message queue has no buffered audio before requesting the combine sink to render more audio. If there is a SET_REQUESTED_LATENCY message in the queue when it's drained, this crash will happen.

I think the queue draining code could be removed from both places without totally breaking things, but it might cause a situation where audio is rendered earlier than necessary. That might cause some issues.

A safer fix would be to have two queues for the two messages. That way the SET_REQUESTED_LATENCY messages could be processed only when it's safe to do so. I'll hopefully get around writing a patch tomorrow.

Comment 13 Tanu Kaskinen 2015-06-27 15:45:21 UTC

(In reply to Tanu Kaskinen from comment #12)
> I'll hopefully get around writing a patch tomorrow.

I did get around to doing that, but I didn't have time for testing the patch. Now I have checked that I can reproduce the crash, and that the patch gets rid of it. I sent the patch to the mailing list: http://lists.freedesktop.org/archives/pulseaudio-discuss/2015-June/024136.html

Audacity seems to do some crazy stuff at startup - it creates over 70 connections before it settles down. Good for stress testing...

Comment 14 Tanu Kaskinen 2015-06-29 09:43:41 UTC

*** Bug 91139 has been marked as a duplicate of this bug. ***

Comment 15 Jiri Tyr 2015-07-10 21:57:37 UTC

I was experiencing the following two crashes very frequently:

Jul 08 23:55:04 desktop pulseaudio[5512]: E: [alsa-sink-VT1718S Analog] sink.c: Assertion '!s->thread_info.rewind_requested' failed at pulsecore/sink.c:1239, function pa_sink_render_into(). Aborting.
Jul 09 00:32:08 desktop pulseaudio[6984]: E: [alsa-sink-VT1718S Digital] sink.c: Assertion '!s->thread_info.rewind_requested' failed at pulsecore/sink.c:1323, function pa_sink_render_into_full(). Aborting.

After I have applied the patch, there are no more crashes. I have been testing it for two days.

Comment 16 Ashlynn Anderson 2015-07-11 04:14:53 UTC

I've been having this problem for some time as well. I'm just now going in and applying the patch and I'll report back whether it works properly for me.

Comment 17 Tanu Kaskinen 2015-07-21 17:11:02 UTC

I pushed the patch now. Thanks, Jiri, for testing.

Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.