After an evaluation, GNOME has moved from Bugzilla to GitLab. Learn more about GitLab.
No new issues can be reported in GNOME Bugzilla anymore.
To report an issue in a GNOME project, go to GNOME GitLab.
Do not go to GNOME Gitlab for: Bluefish, Doxygen, GnuCash, GStreamer, java-gnome, LDTP, NetworkManager, Tomboy.
Bug 581460 - [baseaudiosrc] Reusing audio source leads to null timestamps on first buffers
[baseaudiosrc] Reusing audio source leads to null timestamps on first buffers
Status: RESOLVED FIXED
Product: GStreamer
Classification: Platform
Component: gst-plugins-base
git master
Other Linux
: Normal normal
: 0.10.24
Assigned To: GStreamer Maintainers
GStreamer Maintainers
Depends on:
Blocks:
 
 
Reported: 2009-05-05 12:50 UTC by René Stadler
Modified: 2009-06-17 12:03 UTC
See Also:
GNOME target: ---
GNOME version: ---


Attachments
Test program (1.65 KB, text/x-csrc)
2009-05-05 12:53 UTC, René Stadler
  Details
Small patch to add some extra logging (1.29 KB, patch)
2009-05-05 12:55 UTC, René Stadler
committed Details | Review
Debug log (445.88 KB, text/x-log)
2009-05-05 12:56 UTC, René Stadler
  Details

Description René Stadler 2009-05-05 12:50:23 UTC
When reusing a pulsesrc (or alsasrc) element (PLAYING->READY->PLAYING cycle), starting from the second time, the timestamps of the first couple buffers are 0. It makes no difference to set the state to NULL instead of READY.

I added some extra logging to gstbaseaudiosrc.c which shows that the timestamps are clamped to 0 because they are smaller than the basetime. Attaching test program, small patch for extra logging and logs.

Not sure how to fix this, maybe the basetime is a bit incorrect and the internal timestamps from the ringbuffer/clock as well, or maybe this is expected and the buffers should be dropped. Or should the state change cycle reset everything back to 0 after all?
Comment 1 René Stadler 2009-05-05 12:53:14 UTC
Created attachment 134018 [details]
Test program

Compile: gcc $(pkg-config --cflags --libs gstreamer-0.10) -o test-reuse test-reuse.c

Run: GST_DEBUG=2 ./test-reuse "pulsesrc num-buffers=100 ! identity check-perfect=true ! fakesink"

This shows the warnings from identity about the repeating 0 timestamps.
Comment 2 René Stadler 2009-05-05 12:55:02 UTC
Created attachment 134019 [details] [review]
Small patch to add some extra logging

Just for testing...
Comment 3 René Stadler 2009-05-05 12:56:21 UTC
Created attachment 134020 [details]
Debug log

Output for: GST_DEBUG=2,*ringbuffer*:5,,*audiosrc:5 ./test-reuse "pulsesrc num-buffers=100 ! identity check-perfect=true ! fakesink"
Comment 4 René Stadler 2009-05-05 13:09:22 UTC
Some log excerpts and analysis (egrep 'identity|EOS|buffer timestamp|processed samples' debug.log):

processed samples: raw 0, delay 0, real 0, time 0:00:00.000000000
buffer timestamp 0, ts 0:00:00.000000000 <= base_time 0:00:00.000000000
processed samples: raw 441, delay 49, real 490, time 0:00:00.011111111
buffer timestamp 0:00:00.010000000 (base_time 0:00:00.000000000)
buffer timestamp 0:00:00.020000000 (base_time 0:00:00.000000000)
buffer timestamp 0:00:00.030000000 (base_time 0:00:00.000000000)
buffer timestamp 0:00:00.040000000 (base_time 0:00:00.000000000)
buffer timestamp 0:00:00.050000000 (base_time 0:00:00.000000000)
[...]

and so on until

[...]
buffer timestamp 0:00:00.960000000 (base_time 0:00:00.000000000)
buffer timestamp 0:00:00.970000000 (base_time 0:00:00.000000000)
buffer timestamp 0:00:00.980000000 (base_time 0:00:00.000000000)
buffer timestamp 0:00:00.990000000 (base_time 0:00:00.000000000)
Got EOS

Makes sense, 10ms per buffer (latency-time), num-buffers=100 makes this the last buffer, spanning to 1s with its 10ms duration. Now state change cycle and the second round (with the faulty timestamps):

processed samples: raw 44100, delay 0, real 44100, time 0:00:01.000000000
processed samples: raw 44541, delay 0, real 44541, time 0:00:01.010000000
buffer timestamp 0, ts 0:00:00.820000000 <= base_time 0:00:01.010000000
processed samples: raw 44541, delay 103, real 44644, time 0:00:01.012335600
buffer timestamp 0, ts 0:00:00.830000000 <= base_time 0:00:01.010000000
Buffer not time-contiguous with previous one: prev ts 0:00:00.000000000, prev dur 0:00:00.010000000, new ts 0:00:00.000000000 (expected ts 0:00:00.010000000, delta=-0:00:00.010000000)
buffer timestamp 0, ts 0:00:00.840000000 <= base_time 0:00:01.010000000
Buffer not time-contiguous with previous one: prev ts 0:00:00.000000000, prev dur 0:00:00.010000000, new ts 0:00:00.000000000 (expected ts 0:00:00.010000000, delta=-0:00:00.010000000)
buffer timestamp 0, ts 0:00:00.850000000 <= base_time 0:00:01.010000000
Buffer not time-contiguous with previous one: prev ts 0:00:00.000000000, prev dur 0:00:00.010000000, new ts 0:00:00.000000000 (expected ts 0:00:00.010000000, delta=-0:00:00.010000000)
[...]

and so on until the internal timestamps reach up to the base_time:

[...]
Buffer not time-contiguous with previous one: prev ts 0:00:00.000000000, prev dur 0:00:00.010000000, new ts 0:00:00.000000000 (expected ts 0:00:00.010000000, delta=-0:00:00.010000000)
buffer timestamp 0, ts 0:00:01.010000000 <= base_time 0:00:01.010000000
Buffer not time-contiguous with previous one: prev ts 0:00:00.000000000, prev dur 0:00:00.010000000, new ts 0:00:00.000000000 (expected ts 0:00:00.010000000, delta=-0:00:00.010000000)
buffer timestamp 0:00:00.010000000 (base_time 0:00:01.010000000)
buffer timestamp 0:00:00.020000000 (base_time 0:00:01.010000000)
buffer timestamp 0:00:00.030000000 (base_time 0:00:01.010000000)
buffer timestamp 0:00:00.040000000 (base_time 0:00:01.010000000)
buffer timestamp 0:00:00.050000000 (base_time 0:00:01.010000000)
[...]
buffer timestamp 0:00:00.790000000 (base_time 0:00:01.010000000)
buffer timestamp 0:00:00.800000000 (base_time 0:00:01.010000000)
Got EOS
processed samples: raw 80262, delay 0, real 80262, time 0:00:01.820000000


Other observations:

pulsesrc sees these warning after each EOS:
0:00:01.875599121 13816 0xb2000478 WARN              audiosrc gstaudiosrc.c:228:audioringbuffer_thread_func:<pulsesrc0> error reading data (reason: Success), skipping segment

alsasrc does not produce this warning, but the outcome is the same except that the numbers are different.

Also, increasing the latency-time property lowers the number of null timestamped buffers.
Comment 5 Wim Taymans 2009-05-05 15:15:01 UTC
I have some patches to fix this, it's a combination of a couple of things, like clocks going backwards etc..
Comment 6 Stefan Sauer (gstreamer, gtkdoc dev) 2009-05-24 11:21:29 UTC
Could those patches be committed or incase they needs work, could you attatch them here?
Comment 7 Wim Taymans 2009-06-17 12:02:19 UTC
commit ffd90dda89f92b0138d26f1f203360f60846d09c
Author: Wim Taymans <wim.taymans@collabora.co.uk>
Date:   Wed Jun 17 14:00:23 2009 +0200

    audiosrc: fix get_offset
    
    When we need to jump to the most recently captured sample, jump to where the
    next sample will be written instead of to some old data.
    
    Fixes #581460
Comment 8 Wim Taymans 2009-06-17 12:03:05 UTC
The last patch is not entirely the ultimate solution but it does the right thing to fix this bug.