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

[Mahendran, Dandapani (D.)]

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.

We have tried removing PA_STREAM_AUTO_TIMING_UPDATE  flag from pulsesink.c.  Though it improves the behavior, there are some occasional delay during the start of audio, and audio breaks are prevalent.

Also we have tried hardcoding the "pa_buffer_attr" values passed to " pa_stream_connect_playback " function.  There is no impact for these changes and disabling srbchannels.

In the following gst log, we can see a delay in getting "gst_pulsering_stream_started_cb" after the first commit.  Periodic underflows are seen in the log.

0:02:40.583763020 pulsesink.c:1408:gst_pulseringbuffer_commit:<sink> entering commit
0:02:40.583862020 pulsesink.c:1426:gst_pulseringbuffer_commit:<sink> in 2821, out 2821
0:02:40.583912686 pulsesink.c:1451:gst_pulseringbuffer_commit:<sink> need to write 2822 samples at offset 5470
0:02:40.583968020 pulsesink.c:1522:gst_pulseringbuffer_commit:<sink> requesting 4232 bytes of shared memory
0:02:40.584070686 pulsesink.c:1531:gst_pulseringbuffer_commit:<sink> got 4232 bytes of shared memory
0:02:40.584130353 pulsesink.c:1540:gst_pulseringbuffer_commit:<sink> writing 2116 samples at offset 5470
0:02:40.584229020 pulsesink.c:1595:gst_pulseringbuffer_commit:<sink> flushing 2116 samples at offset 5470
0:02:40.584475686 pulsesink.c:1616:gst_pulseringbuffer_commit:<sink> read_index at 0, offset 9702
0:02:40.584548020 pulsesink.c:1073:gst_pulsering_set_corked:<sink> setting corked state to 0
0:02:40.584776686 pulsesink.c:1451:gst_pulseringbuffer_commit:<sink> need to write 706 samples at offset 9702
0:02:40.584853686 pulsesink.c:1509:gst_pulseringbuffer_commit:<sink> waiting for free space
0:02:40.587476353 pulsesink.c:690:gst_pulsering_stream_latency_cb:<sink> latency_update, 1420125880920876000, 0:9702, 0:0, 1011045, 90000
0:02:40.587820353 pulsesink.c:690:gst_pulsering_stream_latency_cb:<sink> latency_update, 1420125880922091000, 0:9702, 0:0, 1004026, 90000
0:02:40.587917020 pulsesink.c:420:gst_pulsering_context_subscribe_cb:<sink> type 18, idx 5
0:02:40.588031353 pulsesink.c:1509:gst_pulseringbuffer_commit:<sink> waiting for free space
0:02:40.595662353 pulsesink.c:690:gst_pulsering_stream_latency_cb:<sink> latency_update, 1420125880930264000, 0:9702, 0:0, 995871, 90000
0:02:40.616356020 pulsesink.c:690:gst_pulsering_stream_latency_cb:<sink> latency_update, 1420125880951034000, 0:9702, 0:0, 975094, 90000
0:02:40.657076020 pulsesink.c:690:gst_pulsering_stream_latency_cb:<sink> latency_update, 1420125880991743000, 0:9702, 0:0, 934383, 90000
0:02:40.737874020 pulsesink.c:690:gst_pulsering_stream_latency_cb:<sink> latency_update, 1420125881072554000, 0:9702, 0:0, 853609, 90000
0:02:40.898739686 pulsesink.c:690:gst_pulsering_stream_latency_cb:<sink> latency_update, 1420125881233411000, 0:9702, 0:0, 692740, 90000
0:02:41.219641353 pulsesink.c:690:gst_pulsering_stream_latency_cb:<sink> latency_update, 1420125881554246000, 0:9702, 0:0, 371885, 90000
0:02:41.592752020 pulsesink.c:717:gst_pulsering_stream_started_cb:<sink> stream started
0:02:41.598814020 pulsesink.c:690:gst_pulsering_stream_latency_cb:<sink> latency_update, 1420125881932608000, 0:9702, 0:510, 323, 90000
0:02:41.599335020 pulsesink.c:633:gst_pulsering_stream_request_cb:<sink> got request for length 1020
0:02:41.599528020 pulsesink.c:1522:gst_pulseringbuffer_commit:<sink> requesting 1020 bytes of shared memory
0:02:41.599734020 pulsesink.c:1531:gst_pulseringbuffer_commit:<sink> got 1020 bytes of shared memory
0:02:41.599800686 pulsesink.c:1540:gst_pulseringbuffer_commit:<sink> writing 510 samples at offset 9702
0:02:41.599861686 pulsesink.c:1595:gst_pulseringbuffer_commit:<sink> flushing 510 samples at offset 9702
0:02:41.599955020 pulsesink.c:1451:gst_pulseringbuffer_commit:<sink> need to write 196 samples at offset 10722
0:02:41.600016353 pulsesink.c:1509:gst_pulseringbuffer_commit:<sink> waiting for free space
0:02:41.603722353 pulsesink.c:633:gst_pulsering_stream_request_cb:<sink> got request for length 4450
0:02:41.603960020 pulsesink.c:633:gst_pulsering_stream_request_cb:<sink> got request for length 8682
0:02:41.604067353 pulsesink.c:690:gst_pulsering_stream_latency_cb:<sink> latency_update, 1420125881938370000, 0:10722, 0:9702, 97791, 90000
0:02:41.604190353 pulsesink.c:1522:gst_pulseringbuffer_commit:<sink> requesting 392 bytes of shared memory

Regards,
Mahendran D
VTSC Chennai


-----Original Message-----
From: Ahmed S. Darwish [mailto:darwish.07 at gmail.com] 
Sent: Friday, November 25, 2016 11:16 AM
To: Mahendran, Dandapani (D.)
Cc: 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 Thu, Nov 24, 2016, Mahendran, Dandapani (D.) wrote:
> Hi All,
> 
> Following is the issue we are facing while using Pulseaudio8.0 along 
> with gstreamer pulsesink plugin.  This issue was not seen while using 
> Pulseaudio4.0.
> 
> Audio streaming started with an initial delay of 1.5 to 2 Secs.
# Attached are the pulse & gst logs during the issue case.
> 
> "route_andautonav" is the sink in which the problem is seen.
# Configuration for this sink in default.pa is load-module module-null-sink
# sink_name="route_andautonav"   format=s16le rate=44100 channels=2.
>

Hmm...

- Can you re-send the pulse logs with time-stamps attached? So far it's
  not clear where the delay exists

- How was the delay measured? Since this is just an initial delay, and
  this seems to be an automotive embedded board, it would be easiest to
  just reserve a GPIO pin and sprinkle some alternating high/lows: one
  in gstreamer pulse sink, one in libpulse, and one in the PA daemon
  itself at protocol-native.c different commands (AUTH,
  CREATE_PLAYBACK_STREAM, etc.)

- Was pulse socket-activated, or automatically started by SYSV/systemd?
  If it's the latter, are you sure there's no race conditions in the
  init system sequence?

- Is Pulse running with real-time scheduling priority? If not, can you
  reproduce with RT scheduling ON?

  Since this is an embedded board, are they any *other* processes in
  the system that are running with RT priority? If so, can you
  reproduce while they're disabled?

- One big change from PA 4.0 to PA 8.0 was srbchannels. Does disabling
  them make any difference?

- As Tanu stated, reproducing with a smaller program like pacat would
  be much much easier indeed.

Best of luck,

--
Darwish
http://darwish.chasingpointers.com
-------------- next part --------------
An embedded and charset-unspecified text was scrubbed...
Name: gst_logs.txt
URL: <https://lists.freedesktop.org/archives/pulseaudio-discuss/attachments/20161125/08507e2e/attachment-0001.txt>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: pulseverbose.log
Type: application/octet-stream
Size: 269513 bytes
Desc: pulseverbose.log
URL: <https://lists.freedesktop.org/archives/pulseaudio-discuss/attachments/20161125/08507e2e/attachment-0002.obj>
-------------- next part --------------
An embedded and charset-unspecified text was scrubbed...
Name: extended-test.c
URL: <https://lists.freedesktop.org/archives/pulseaudio-discuss/attachments/20161125/08507e2e/attachment-0001.c>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: extended_test_pulseverbose.log
Type: application/octet-stream
Size: 330175 bytes
Desc: extended_test_pulseverbose.log
URL: <https://lists.freedesktop.org/archives/pulseaudio-discuss/attachments/20161125/08507e2e/attachment-0003.obj>