[Bug 755050] New: pulsesink: no sound heard very shortly at starting of resuming playback.

GStreamer (GNOME Bugzilla) bugzilla at gnome.org
Tue Sep 15 03:15:43 PDT 2015 

https://bugzilla.gnome.org/show_bug.cgi?id=755050

            Bug ID: 755050
           Summary: pulsesink: no sound heard very shortly at starting of
                    resuming playback.
    Classification: Platform
           Product: GStreamer
           Version: 1.4.1
                OS: Linux
            Status: NEW
          Severity: major
          Priority: Normal
         Component: gst-plugins-good
          Assignee: gstreamer-bugs at lists.freedesktop.org
          Reporter: see2002 at gmail.com
        QA Contact: gstreamer-bugs at lists.freedesktop.org
     GNOME version: ---

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

-- 
You are receiving this mail because:
You are the QA Contact for the bug.
You are the assignee for the bug.

More information about the gstreamer-bugs mailing list