[pulseaudio-discuss] Issue migrating to pulseaudio8.0: Audio streamed through gsteamer pulsesink pulgin starts to play delayed

[Mahendran, Dandapani (D.)]

Thank you.

Following are the observations, when we tried to backtrack the changes.

If we revert below changes under the function sink_process_msg(...) in module-null-sink.c, there is no initial delay in the playback.  The issue that we are facing is getting resolved.

>From (Pulseaudio-8.0):
            if (pa_sink_get_state(u->sink) == PA_SINK_SUSPENDED || pa_sink_get_state(u->sink) == PA_SINK_INIT) {
                if (PA_PTR_TO_UINT(data) == PA_SINK_RUNNING || PA_PTR_TO_UINT(data) == PA_SINK_IDLE)
                    u->timestamp = pa_rtclock_now();
            }

To (Pulseaudio-4.0 until 7.0):
  	if (PA_PTR_TO_UINT(data) == PA_SINK_RUNNING)
       	         u->timestamp = pa_rtclock_now();

This change seems to have been introduced in pulseaudio-7.1.  Is this change for fixing some other issue? What is the impact of this change?

Regards,
Mahendran D
VTSC Chennai

-----Original Message-----
From: Ahmed S. Darwish [mailto:darwish.07 at gmail.com] 
Sent: Saturday, November 26, 2016 3:27 PM
To: Mahendran, Dandapani (D.)
Cc: Arun Raghavan; pulseaudio-discuss at lists.freedesktop.org
Subject: Re: [pulseaudio-discuss] Issue migrating to pulseaudio8.0: Audio streamed through gsteamer pulsesink pulgin starts to play delayed

On Fri, Nov 25, 2016 at 10:56:55AM +0000, Mahendran, Dandapani (D.) wrote:
> Hello Darwish,
> 
> Thank you for your response.
> 
> I have attached the gst & pulseaudio logs with time stamps.
> Audio is played with delay and breaks/cut.
> 
> Also, attaching the pulseaudio log taken by running "extended-test.c", 
> that streams the audio through same sink (route_andautonav).  During 
> this testing with extended-test.c, audio is streamed properly without 
> any delay/break/cut.  So the problem seems more oriented towards gstreamer and pulsesink plugin.
>

Yeah, from the gstreamer log there's a lot of instances of:

  0:02:42.130359686 gst_pulsering_stream_request_cb: got request for length 17640
  0:02:42.130592686 gst_pulsering_stream_underflow_cb: Got underflow
  ...
  0:02:51.930305021 gst_pulsering_stream_request_cb: got request for length 9526
  0:02:51.930489354 gst_pulsering_stream_underflow_cb: Got underflow
  ...
  0:02:54.775065355 gst_pulsering_stream_request_cb: got request for length 9702
  0:02:54.775288355 gst_pulsering_stream_underflow_cb: Got underflow
  ...

So pulse _is doing its job_ and asks for the stream to be filled through the stream's write callback. Meanwhile gstreamer does not provide it anything in return -- triggering an underrun.

So the question is, why gstreamer is not fulfilling the requests?

Looking at gstreamer's pulsesink code [1], it seems the stream write callback only fulfills the request and signals the PA mainloop if there's an in-commit buffer with appropriate length.

So either there's a bug in the sink's handling of the mainloop, or the gstreamer source is not providing audio at appropriate speed.

PS. The attached "extended-test.c" coding is misusing pulse's stream underflow and stream ready callbacks. Check pacat source code for the more appropriate handling.

PSS. From the attached pulse logs, you're creating a BIG number of streams at once. This triggers __a lot of__ rewinds for existing streams playing audio and increases the the possibility of cracks and server misbehavior [2]

Regards,

[1] https://github.com/GStreamer/gst-plugins-good/blob/master/ext/pulse/pulsesink.c ,
    gst_pulsering_stream_request_cb()

[2] https://github.com/a-darwish/malicious-pulseaudio-clients/blob/master/kill_server_quickly_open_write_streams.c

--
Darwish
http://darwish.chasingpointers.com