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>[00m entering commit 0:02:40.583862020 pulsesink.c:1426:gst_pulseringbuffer_commit:<sink>[00m in 2821, out 2821 0:02:40.583912686 pulsesink.c:1451:gst_pulseringbuffer_commit:<sink>[00m need to write 2822 samples at offset 5470 0:02:40.583968020 pulsesink.c:1522:gst_pulseringbuffer_commit:<sink>[00m requesting 4232 bytes of shared memory 0:02:40.584070686 pulsesink.c:1531:gst_pulseringbuffer_commit:<sink>[00m got 4232 bytes of shared memory 0:02:40.584130353 pulsesink.c:1540:gst_pulseringbuffer_commit:<sink>[00m writing 2116 samples at offset 5470 0:02:40.584229020 pulsesink.c:1595:gst_pulseringbuffer_commit:<sink>[00m flushing 2116 samples at offset 5470 0:02:40.584475686 pulsesink.c:1616:gst_pulseringbuffer_commit:<sink>[00m read_index at 0, offset 9702 0:02:40.584548020 pulsesink.c:1073:gst_pulsering_set_corked:<sink>[00m setting corked state to 0 0:02:40.584776686 pulsesink.c:1451:gst_pulseringbuffer_commit:<sink>[00m need to write 706 samples at offset 9702 0:02:40.584853686 pulsesink.c:1509:gst_pulseringbuffer_commit:<sink>[00m waiting for free space 0:02:40.587476353 pulsesink.c:690:gst_pulsering_stream_latency_cb:<sink>[00m latency_update, 1420125880920876000, 0:9702, 0:0, 1011045, 90000 0:02:40.587820353 pulsesink.c:690:gst_pulsering_stream_latency_cb:<sink>[00m latency_update, 1420125880922091000, 0:9702, 0:0, 1004026, 90000 0:02:40.587917020 pulsesink.c:420:gst_pulsering_context_subscribe_cb:<sink>[00m type 18, idx 5 0:02:40.588031353 pulsesink.c:1509:gst_pulseringbuffer_commit:<sink>[00m waiting for free space 0:02:40.595662353 pulsesink.c:690:gst_pulsering_stream_latency_cb:<sink>[00m latency_update, 1420125880930264000, 0:9702, 0:0, 995871, 90000 0:02:40.616356020 pulsesink.c:690:gst_pulsering_stream_latency_cb:<sink>[00m latency_update, 1420125880951034000, 0:9702, 0:0, 975094, 90000 0:02:40.657076020 pulsesink.c:690:gst_pulsering_stream_latency_cb:<sink>[00m latency_update, 1420125880991743000, 0:9702, 0:0, 934383, 90000 0:02:40.737874020 pulsesink.c:690:gst_pulsering_stream_latency_cb:<sink>[00m latency_update, 1420125881072554000, 0:9702, 0:0, 853609, 90000 0:02:40.898739686 pulsesink.c:690:gst_pulsering_stream_latency_cb:<sink>[00m latency_update, 1420125881233411000, 0:9702, 0:0, 692740, 90000 0:02:41.219641353 pulsesink.c:690:gst_pulsering_stream_latency_cb:<sink>[00m latency_update, 1420125881554246000, 0:9702, 0:0, 371885, 90000 0:02:41.592752020 pulsesink.c:717:gst_pulsering_stream_started_cb:<sink>[00m stream started 0:02:41.598814020 pulsesink.c:690:gst_pulsering_stream_latency_cb:<sink>[00m latency_update, 1420125881932608000, 0:9702, 0:510, 323, 90000 0:02:41.599335020 pulsesink.c:633:gst_pulsering_stream_request_cb:<sink>[00m got request for length 1020 0:02:41.599528020 pulsesink.c:1522:gst_pulseringbuffer_commit:<sink>[00m requesting 1020 bytes of shared memory 0:02:41.599734020 pulsesink.c:1531:gst_pulseringbuffer_commit:<sink>[00m got 1020 bytes of shared memory 0:02:41.599800686 pulsesink.c:1540:gst_pulseringbuffer_commit:<sink>[00m writing 510 samples at offset 9702 0:02:41.599861686 pulsesink.c:1595:gst_pulseringbuffer_commit:<sink>[00m flushing 510 samples at offset 9702 0:02:41.599955020 pulsesink.c:1451:gst_pulseringbuffer_commit:<sink>[00m need to write 196 samples at offset 10722 0:02:41.600016353 pulsesink.c:1509:gst_pulseringbuffer_commit:<sink>[00m waiting for free space 0:02:41.603722353 pulsesink.c:633:gst_pulsering_stream_request_cb:<sink>[00m got request for length 4450 0:02:41.603960020 pulsesink.c:633:gst_pulsering_stream_request_cb:<sink>[00m got request for length 8682 0:02:41.604067353 pulsesink.c:690:gst_pulsering_stream_latency_cb:<sink>[00m latency_update, 1420125881938370000, 0:10722, 0:9702, 97791, 90000 0:02:41.604190353 pulsesink.c:1522:gst_pulseringbuffer_commit:<sink>[00m requesting 392 bytes of shared memory Regards, Mahendran D VTSC Chennai -----Original Message----- From: Ahmed S. Darwish [mailto:darwish.07@xxxxxxxxx] Sent: Friday, November 25, 2016 11:16 AM To: Mahendran, Dandapani (D.) Cc: pulseaudio-discuss at lists.freedesktop.org Subject: Re: 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>
