GNOME Bugzilla – Bug 581460
[baseaudiosrc] Reusing audio source leads to null timestamps on first buffers
Last modified: 2009-06-17 12:03:05 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?
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.
Created attachment 134019 [details] [review] Small patch to add some extra logging Just for testing...
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"
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.
I have some patches to fix this, it's a combination of a couple of things, like clocks going backwards etc..
Could those patches be committed or incase they needs work, could you attatch them here?
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
The last patch is not entirely the ultimate solution but it does the right thing to fix this bug.