pulsesink: no sound heard very shortly at starting of resuming playback.
Submitted by KimJeongYeon
Link to original bug (#755050)
Description
Dear all,
When I use pulsesink based playback, I found no sound heard very shortly(around 100ms) when resume paused playback.
The reproduce step is:
- play 1 second (44100Hz, mono, 16bit signed short) of wav file via pulsesink,
- pause playback around EOS (1sec),
- seek to 0, resume.
- pcm was dropped(no sound) around 100ms at starting of resume.
// pa_stream_write() at the end of playback
0:00:47.458404541 pulse pulsesink.c:783:gst_pulsering_stream_request_cb:<pulsesink3>
got request for length 6856
0:00:47.459289550 pulse pulsesink.c:1824:gst_pulseringbuffer_commit:<pulsesink3>
requesting 2276 bytes of shared memory
0:00:47.459381103 pulse pulsesink.c:1833:gst_pulseringbuffer_commit:<pulsesink3>
got 2276 bytes of shared memory
0:00:47.459411621 pulse pulsesink.c:1842:gst_pulseringbuffer_commit:<pulsesink3>
writing 1138 samples at offset 342180
0:00:47.459472656 pulse pulsesink.c:1895:gst_pulseringbuffer_commit:<pulsesink3>
flushing 1138 samples at offset 342180
0:00:47.459564209 pulse pulsesink.c:1939:gst_pulseringbuffer_commit:<pulsesink3>
wrote 1138 samples
// end of buffer, pulsesink got eos event.
0:00:47.459777832 basesink gstbasesink.c:3191:gst_base_sink_event:<pulsesink3>
received event 0xaf8be130 eos event: 0xaf8be130, time 99:99:99.999999999, seq-num 1241, (NULL)
0:00:47.459869384 pulse pulsesink.c:1998:gst_pulsering_flush:<pulsesink3>
entering flush
0:00:47.459991455 basesink gstbasesink.c:1854:gst_base_sink_get_sync_times:<pulsesink3>
sync times for EOS 99:99:99.999999999
0:00:47.460052490 basesink gstbasesink.c:2308:gst_base_sink_wait:<pulsesink3>
checking preroll 0
// try to wait until 3.905 sec
0:00:47.460083007 basesink gstbasesink.c:2319:gst_base_sink_wait:<pulsesink3>
possibly waiting for clock to reach 0:00:01.001043084
0:00:47.460113525 basesink gstbasesink.c:2073:gst_base_sink_wait_clock:<pulsesink3>
time 0:00:01.001043084, base_time 0:00:02.903992000
0:00:47.460205078 pulse pulsesink.c:2414:gst_pulsesink_get_time:<pulsesink3>
current time is 0:00:03.739977000
0:00:47.519287109 pulse pulsesink.c:2414:gst_pulsesink_get_time:<pulsesink3>
current time is 0:00:03.802569000
0:00:47.519683838 pulse pulsesink.c:2414:gst_pulsesink_get_time:<pulsesink3>
current time is 0:00:03.802989000
0:00:47.519927978 pulse pulsesink.c:2414:gst_pulsesink_get_time:<pulsesink3>
current time is 0:00:03.803247000
0:00:47.520233154 pulse pulsesink.c:2414:gst_pulsesink_get_time:<pulsesink3>
current time is 0:00:03.803602000
// waiting was broken due to application tried to pause.
0:00:47.520477295 pulse pulsesink.c:1490:gst_pulseringbuffer_pause:<pulsesink3>
pausing and corking
0:00:47.520507812 pulse pulsesink.c:1355:gst_pulsering_set_corked:<pulsesink3>
setting corked state to 1
0:00:47.525177002 pulse pulsesink.c:856:gst_pulsering_stream_latency_cb:<pulsesink3>
latency_update, 1441797905315028000, 0:344456, 0:345094, 90252, 90000
0:00:47.525390625 pulse pulsesink.c:783:gst_pulsering_stream_request_cb:<pulsesink3>
got request for length 10340
0:00:47.525543213 pulse pulsesink.c:801:gst_pulsering_stream_underflow_cb:<pulsesink3>
Got underflow
0:00:47.526428222 pulse pulsesink.c:550:gst_pulsering_context_subscribe_cb:<pulsesink6>
type 0012, idx 347
0:00:47.526489257 pulse pulsesink.c:550:gst_pulsering_context_subscribe_cb:<pulsesink5>
type 0012, idx 347
0:00:47.526550293 pulse pulsesink.c:550:gst_pulsering_context_subscribe_cb:<pulsesink4>
type 0012, idx 347
0:00:47.526580810 pulse pulsesink.c:550:gst_pulsering_context_subscribe_cb:<pulsesink3>
type 0012, idx 347
0:00:47.526611328 pulse pulsesink.c:550:gst_pulsering_context_subscribe_cb:<pulsesink2>
type 0012, idx 347
0:00:47.526672363 pulse pulsesink.c:550:gst_pulsering_context_subscribe_cb:<pulsesink1>
type 0012, idx 347
0:00:47.526702881 pulse pulsesink.c:550:gst_pulsering_context_subscribe_cb:<pulsesink0>
type 0012, idx 347
// read_index & write_index became 344456 (3.905 sec) after pause, it seems ok.
0:00:47.526824951 pulse pulsesink.c:856:gst_pulsering_stream_latency_cb:<pulsesink3>
latency_update, 1441797905317561000, 0:344456, 0:344456, 80791, 90000
0:00:47.526977539 pulse pulsesink.c:856:gst_pulsering_stream_latency_cb:<pulsesink3>
latency_update, 1441797905318721000, 0:344456, 0:344456, 79297, 90000
0:00:47.527343750 basesink gstbasesink.c:2328:gst_base_sink_wait:<pulsesink3>
clock returned 2
0:00:47.527404785 basesink gstbasesink.c:2308:gst_base_sink_wait:<pulsesink3>
checking preroll 1
0:00:47.528472900 pulse pulsesink.c:2414:gst_pulsesink_get_time:<pulsesink3>
current time is 0:00:03.805343000
0:00:47.537872314 pulse pulsesink.c:856:gst_pulsering_stream_latency_cb:<pulsesink3>
latency_update, 1441797905330501000, 0:344456, 0:344456, 67521, 90000
0:00:47.559356689 pulse pulsesink.c:856:gst_pulsering_stream_latency_cb:<pulsesink3>
latency_update, 1441797905351955000, 0:344456, 0:344456, 89655, 90000
// application try to seek & flush using pa_stream_flush()
0:00:47.592529297 basesink gstbasesink.c:4366:gst_base_sink_send_event:<pulsesink3>
handling event 0xaf8be010 seek event: 0xaf8be010, time 99:99:99.999999999, seq-num 1287, GstEventSeek, rate=(double)1, format=(GstFormat)GST_FORMAT_TIME, flags=(GstSeekFlags)GST_SEEK_FLAG_FLUSH+GST_SEEK_FLAG_ACCURATE, cur-type=(GstSeekType)GST_SEEK_TYPE_SET, cur=(gint64)0, stop-type=(GstSeekType)GST_SEEK_TYPE_NONE, stop=(gint64)-1;
0:00:47.593109131 basesink gstbasesink.c:3191:gst_base_sink_event:<pulsesink3>
received event 0xb85b3170 flush-start event: 0xb85b3170, time 99:99:99.999999999, seq-num 1288, (NULL)
0:00:47.593475341 basesink gstbasesink.c:3000:gst_base_sink_default_event:<pulsesink3>
flush-start 0xb85b3170
0:00:47.593719482 basesink gstbasesink.c:2349:gst_base_sink_wait:<pulsesink3>
we are flushing
0:00:47.594177246 pulse pulsesink.c:2414:gst_pulsesink_get_time:<pulsesink3>
current time is 0:00:03.805343000
0:00:47.594818115 basesink gstbasesink.c:3191:gst_base_sink_event:<pulsesink3>
received event 0xb85b30e0 flush-stop event: 0xb85b30e0, time 99:99:99.999999999, seq-num 1296, GstEventFlushStop, reset-time=(boolean)true;
0:00:47.595062256 pulse pulsesink.c:1404:gst_pulseringbuffer_clear:<pulsesink3>
clearing
0:00:47.597290039 pulse pulsesink.c:856:gst_pulsering_stream_latency_cb:<pulsesink3>
latency_update, 1441797905389064000, 1:344456, 0:344456, 88854, 90000
0:00:47.597503662 pulse pulsesink.c:856:gst_pulsering_stream_latency_cb:<pulsesink3>
latency_update, 1441797905389735000, 0:344456, 0:344456, 88153, 90000
0:00:47.597747802 basesink gstbasesink.c:3010:gst_base_sink_default_event:<pulsesink3>
flush-stop 0xb85b30e0, reset_time: 1
0:00:47.600616455 basesink gstbasesink.c:3191:gst_base_sink_event:<pulsesink3>
received event 0xaf8be178 segment event: 0xaf8be178, time 99:99:99.999999999, seq-num 1298, GstEventSegment, segment=(GstSegment)"GstSegment, flags=(GstSegmentFlags)GST_SEGMENT_FLAG_RESET, rate=(double)1, applied-rate=(double)1, format=(GstFormat)GST_FORMAT_TIME, base=(guint64)0, offset=(guint64)0, start=(guint64)0, stop=(guint64)18446744073709551615, time=(guint64)0, position=(guint64)0, duration=(guint64)1001043084;";
0:00:47.601135254 basesink gstbasesink.c:1902:gst_base_sink_get_sync_times:<pulsesink3>
got times start: 0:00:00.000000000, stop: 0:00:00.046439910, do_sync 0
0:00:47.601226806 basesink gstbasesink.c:1455:gst_base_sink_commit_state:<pulsesink3>
commiting state to PAUSED
0:00:47.601257324 basesink gstbasesink.c:1480:gst_base_sink_commit_state:<pulsesink3>
posting PAUSED state change message
0:00:47.601318359 basesink gstbasesink.c:1486:gst_base_sink_commit_state:<pulsesink3>
posting async-done message
0:00:47.602111816 basesink gstbasesink.c:4413:gst_base_sink_send_event:<pulsesink3>
handled event 0xaf8be010 seek event: 0xaf8be010, time 99:99:99.999999999, seq-num 1287, GstEventSeek, rate=(double)1, format=(GstFormat)GST_FORMAT_TIME, flags=(GstSeekFlags)GST_SEEK_FLAG_FLUSH+GST_SEEK_FLAG_ACCURATE, cur-type=(GstSeekType)GST_SEEK_TYPE_SET, cur=(gint64)0, stop-type=(GstSeekType)GST_SEEK_TYPE_NONE, stop=(gint64)-1;: 1
0:00:47.606475830 pulse pulsesink.c:856:gst_pulsering_stream_latency_cb:<pulsesink3>
latency_update, 1441797905399135000, 0:344456, 0:344456, 78731, 90000
0:00:47.609008789 pulse pulsesink.c:2414:gst_pulsesink_get_time:<pulsesink3>
current time is 0:00:03.805343000
0:00:47.609649658 basesink gstbasesink.c:4366:gst_base_sink_send_event:<pulsesink3>
handling event 0xb85b3050 latency event: 0xb85b3050, time 99:99:99.999999999, seq-num 1310, GstEventLatency, latency=(guint64)0;
0:00:47.609985351 basesink gstbasesink.c:4413:gst_base_sink_send_event:<pulsesink3>
handled event 0xb85b3050 latency event: 0xb85b3050, time 99:99:99.999999999, seq-num 1310, GstEventLatency, latency=(guint64)0;: 1
// application try to resume,
// pa_stream_write()
0:00:47.610321045 basesink gstbasesink.c:4975:gst_base_sink_change_state:<pulsesink3>
PAUSED to PLAYING, don't need preroll
0:00:47.610534668 pulse pulsesink.c:1707:gst_pulseringbuffer_commit:<pulseringbuffer3>
start!
0:00:47.610565185 pulse pulsesink.c:1450:gst_pulseringbuffer_start:<pulsesink3>
starting
0:00:47.610595703 pulse pulsesink.c:1714:gst_pulseringbuffer_commit:<pulsesink3>
entering commit
0:00:47.610626220 pulse pulsesink.c:1732:gst_pulseringbuffer_commit:<pulsesink3>
in 2047, out 2047
// I expect that offset should be around "344456", but pa_stream_get_time() returns "335630".
// around 100ms of pcm couldn't heard due to discontinuity.
0:00:47.610748291 pulse pulsesink.c:1755:gst_pulseringbuffer_commit:<pulsesink3>
need to write 2048 samples at offset 335630
0:00:47.610778808 pulse pulsesink.c:1759:gst_pulseringbuffer_commit:<pulsesink3>
discontinuity, offset is 335630, last offset was 344456
0:00:47.610809326 pulse pulsesink.c:1824:gst_pulseringbuffer_commit:<pulsesink3>
requesting 4096 bytes of shared memory
0:00:47.610870361 pulse pulsesink.c:1833:gst_pulseringbuffer_commit:<pulsesink3>
got 4096 bytes of shared memory
0:00:47.610900879 pulse pulsesink.c:1842:gst_pulseringbuffer_commit:<pulsesink3>
writing 2048 samples at offset 335630
0:00:47.610931396 pulse pulsesink.c:1895:gst_pulseringbuffer_commit:<pulsesink3>
flushing 2048 samples at offset 335630
0:00:47.611022949 pulse pulsesink.c:1916:gst_pulseringbuffer_commit:<pulsesink3>
read_index at 344456, offset 339726
0:00:47.611053466 pulse pulsesink.c:1939:gst_pulseringbuffer_commit:<pulsesink3>
wrote 2048 samples
0:00:47.611206054 basesink gstbasesink.c:1902:gst_base_sink_get_sync_times:<pulsesink3>
got times start: 0:00:00.046439910, stop: 0:00:00.092879819, do_sync 0
When I tried to disable interpolation timing(PA_STREAM_INTERPOLATE_TIMING) flag in pulsesink.c, the
offset move expectedly and sound heard well without this kind of drop. Please refer below test patch.
diff --git a/ext/pulse/pulsesink.c b/ext/pulse/pulsesink.c
index e580afc..a10da7e 100755
--- a/ext/pulse/pulsesink.c
+++ b/ext/pulse/pulsesink.c
@@ -961,8 +961,8 @@ gst_pulseringbuffer_acquire (GstAudioRingBuffer * buf,
}
/* construct the flags */
- flags = PA_STREAM_INTERPOLATE_TIMING | PA_STREAM_AUTO_TIMING_UPDATE |
-
PA_STREAM_ADJUST_LATENCY | PA_STREAM_START_CORKED;
-
flags = PA_STREAM_AUTO_TIMING_UPDATE | PA_STREAM_ADJUST_LATENCY |
-
PA_STREAM_START_CORKED;
if (psink->mute_set) {
if (psink->mute)
I guess interpolation timing isn't correct in some special cases than index based timing, but I have no idea why.
Can you give us any feedback about this issue? Is it proper disabling "PA_STREAM_INTERPOLATE_TIMING" flag than use it?
Regards,
KimJeongYeon
Version: 1.4.1