GNOME Bugzilla – Bug 769413
alsasrc, v4l2src: getting repeated timestamps when capturing from multiple sources (multiple pipelines in single command)
Last modified: 2016-09-09 12:18:27 UTC
Hello, I am an alsa and v4l2 drivers developer. I encountered the issue of getting repeated timestamps: 2 adjacent timestamps have the same value. The issue occurs when it is attempted to capture audio from 2 (or more) alsasrces in a single gst-launch command. The problem is generic and I think it is in the GStreamer "layer" because: - it happens for both audio sources (alsasrc) and for video captures (v4l2src) -> this excludes alsa middle layer. - I tested that it happens when capturing from various-branded hardware (see the example capturing from Intel sound device but it will occurs for other hardware as well). The problem breaks the audio & video sync for my customer and it is important for us to have it fixed. Please see the example below: 1) GET A LIST OF AUDIO CAPTURE DEVICES: **** List of CAPTURE Hardware Devices **** card 2: PCH [HDA Intel PCH], device 0: ALC662 rev1 Analog [ALC662 rev1 Analog] Subdevices: 1/1 Subdevice #0: subdevice #0 card 2: PCH [HDA Intel PCH], device 2: ALC662 rev1 Analog [ALC662 rev1 Analog] Subdevices: 1/1 Subdevice #0: subdevice #0 2) ATTEMPT TO CAPTURE FROM 2 DEVICES IN A SINGLE COMMAND: gst-launch-0.10 -v alsasrc device=hw:2,0 ! fakesink name=analog1 alsasrc device=hw:2,2 ! fakesink name=ANALOG2 | grep last-message | grep timestamp /GstPipeline:pipeline0/GstFakeSink:ANALOG2: last-message = "chain ******* (ANALOG2:sink) (4096 bytes, timestamp: 0:00:00.011609977, duration: 0:00:00.011609977, offset: 0, offset_end: 512, flags: 32 discont ) 0x154fe60" /GstPipeline:pipeline0/GstFakeSink:ANALOG2: last-message = "chain ******* (ANALOG2:sink) (4096 bytes, timestamp: 0:00:00.011609977, duration: 0:00:00.011609977, offset: 0, offset_end: 512, flags: 32 discont ) 0x154fe60" /GstPipeline:pipeline0/GstFakeSink:analog1: last-message = "chain ******* (analog1:sink) (4096 bytes, timestamp: 0:00:00.011609977, duration: 0:00:00.011609977, offset: 512, offset_end: 1024, flags: 0 ) 0x7fad18002dd0" /GstPipeline:pipeline0/GstFakeSink:analog1: last-message = "chain ******* (analog1:sink) (4096 bytes, timestamp: 0:00:00.023219954, duration: 0:00:00.011609977, offset: 1024, offset_end: 1536, flags: 0 ) 0x7fad18002e70" /GstPipeline:pipeline0/GstFakeSink:analog1: last-message = "chain ******* (analog1:sink) (4096 bytes, timestamp: 0:00:00.023219954, duration: 0:00:00.011609977, offset: 1024, offset_end: 1536, flags: 0 ) 0x7fad18002e70" /GstPipeline:pipeline0/GstFakeSink:analog1: last-message = "chain ******* (analog1:sink) (4096 bytes, timestamp: 0:00:00.034829931, duration: 0:00:00.011609978, offset: 1536, offset_end: 2048, flags: 0 ) ... We can clearly see that the first 2 timestamps are the same for ANALOG2 alsasrc. Why could that be? Would each pipeline in the above gst-launch command have a separate capture thread for audio capture? Can there be a problem to start them simultaneously? Note that the problem does not exist when the command is split into 2 commands: one for each alsasrc and attempted to run them at the same time from script: script1.sh: gst-launch-0.10 -v alsasrc device=hw:2,0 ! fakesink name=analog1 | grep last-message | grep timestamp script2.sh: gst-launch-0.10 -v alsasrc device=hw:2,2 ! fakesink name=ANALOG2 | grep last-message | grep timestamp script_main.sh: sh -x script1.sh & sh -x script2.sh & Thanks for your help with this, Przemek
*** Bug 769416 has been marked as a duplicate of this bug. ***
GStreamer 0.10 is no longer maintained since a few years. Can you check if the problem still exists with a newer 1.x version?
Hello, I checked that the problem exists in GStreamer 1.8.2. (tested on my Ubuntu 16.04 LTS 64bit). Problem exists for both audio (capturing from alsasrc) and video (capturing from v4l2src) and I believe it is driver-independent because I checked for our capture cards and capturing from the Intel sound card. The issue will happen every few (less than 10) runs of capture commands. For audio (alsasrc), you can reproduce with following commands: 1) list alsa capture devices with; $arecord -l 2) capture from 2 sound devices with: gst-launch-1.0 -v alsasrc device=hw:1,0 ! identity silent=false name=digital1 ! fakesink alsasrc device=hw:2,0 ! identity silent=false name=DIGITAL2 ! fakesink | grep last-message | grep pts Output of my tests: **** List of CAPTURE Hardware Devices **** card 0: VisionSCHD4 [VisionSC-HD4+ Dig Node0], device 0: Audio Capture [VisionSC-HD4+ Digital Node:0] Subdevices: 1/1 Subdevice #0: subdevice #0 card 1: VisionSCHD4_1 [VisionSC-HD4+ Dig Node1], device 0: Audio Capture [VisionSC-HD4+ Digital Node:1] Subdevices: 1/1 Subdevice #0: subdevice #0 card 2: VisionSCHD4_2 [VisionSC-HD4+ Dig Node2], device 0: Audio Capture [VisionSC-HD4+ Digital Node:2] Subdevices: 1/1 Subdevice #0: subdevice #0 card 3: VisionSCHD4_3 [VisionSC-HD4+ Dig Node3], device 0: Audio Capture [VisionSC-HD4+ Digital Node:3] Subdevices: 1/1 Subdevice #0: subdevice #0 card 4: PCH [HDA Intel PCH], device 0: ALC662 rev1 Analog [ALC662 rev1 Analog] Subdevices: 1/1 Subdevice #0: subdevice #0 card 4: PCH [HDA Intel PCH], device 2: ALC662 rev1 Alt Analog [ALC662 rev1 Alt Analog] Subdevices: 1/1 Subdevice #0: subdevice #0 DATAPATH AUDIO: $ gst-launch-1.0 -v alsasrc device=hw:1,0 ! identity silent=false name=digital1 ! fakesink alsasrc device=hw:2,0 ! identity silent=false name=DIGITAL2 ! fakesink | grep last-message | grep pts /GstPipeline:pipeline0/GstIdentity:DIGITAL2: last-message = chain ******* (DIGITAL2:sink) (16384 bytes, dts: none, pts: 0:00:00.092879818, duration: 0:00:00.092879818, offset: 0, offset_end: 4096, flags: 00000040 discont ) 0x7fbe3c0150e0 /GstPipeline:pipeline0/GstIdentity:DIGITAL2: last-message = chain ******* (DIGITAL2:sink) (16384 bytes, dts: none, pts: 0:00:00.092879818, duration: 0:00:00.092879818, offset: 0, offset_end: 4096, flags: 00000040 discont ) 0x7fbe3c0150e0 /GstPipeline:pipeline0/GstIdentity:digital1: last-message = chain ******* (digital1:sink) (16384 bytes, dts: none, pts: 0:00:00.092879818, duration: 0:00:00.092879819, offset: 4096, offset_end: 8192, flags: 00000000 ) 0x7fbe3c015850 /GstPipeline:pipeline0/GstIdentity:DIGITAL2: last-message = chain ******* (DIGITAL2:sink) (16384 bytes, dts: none, pts: 0:00:00.185759637, duration: 0:00:00.092879818, offset: 8192, offset_end: 12288, flags: 00000000 ) 0x7fbe3c0151f0 /GstPipeline:pipeline0/GstIdentity:digital1: last-message = chain ******* (digital1:sink) (16384 bytes, dts: none, pts: 0:00:00.185759637, duration: 0:00:00.092879818, offset: 8192, offset_end: 12288, flags: 00000000 ) 0x7fbe3c015960 /GstPipeline:pipeline0/GstIdentity:DIGITAL2: last-message = chain ******* (DIGITAL2:sink) (16384 bytes, dts: none, pts: 0:00:00.278639455, duration: 0:00:00.092879819, offset: 12288, offset_end: 16384, flags: 00000000 ) 0x7fbe3c015300 /GstPipeline:pipeline0/GstIdentity:digital1: last-message = chain ******* (digital1:sink) (16384 bytes, dts: none, pts: 0:00:00.278639455, duration: 0:00:00.092879819, offset: 12288, offset_end: 16384, flags: 00000000 ) 0x7fbe3c015a70 /GstPipeline:pipeline0/GstIdentity:DIGITAL2: last-message = chain ******* (DIGITAL2:sink) (16384 bytes, dts: none, pts: 0:00:00.371519274, duration: 0:00:00.092879818, offset: 16384, offset_end: 20480, flags: 00000000 ) 0x7fbe3c015410 In the above, 2 first timestamps are the same (0:00:00.092879818) for DIGITAL2 path. INTEL AUDIO: $ gst-launch-1.0 -v alsasrc device=hw:4,0 ! identity silent=false name=intel_audio1 ! fakesink alsasrc device=hw:4,2 ! identity silent=false name=INTEL_AUDIO2 ! fakesink | grep last-message | grep pts /GstPipeline:pipeline0/GstIdentity:INTEL_AUDIO2: last-message = chain ******* (INTEL_AUDIO2:sink) (1764 bytes, dts: none, pts: 0:00:00.020000000, duration: 0:00:00.010000000, offset: 0, offset_end: 441, flags: 00000040 discont ) 0x7fedfc019060 /GstPipeline:pipeline0/GstIdentity:intel_audio1: last-message = chain ******* (intel_audio1:sink) (1764 bytes, dts: none, pts: 0:00:00.010000000, duration: 0:00:00.010000000, offset: 441, offset_end: 882, flags: 00000000 ) 0x7fedfc0197d0 /GstPipeline:pipeline0/GstIdentity:INTEL_AUDIO2: last-message = chain ******* (INTEL_AUDIO2:sink) (1764 bytes, dts: none, pts: 0:00:00.030000000, duration: 0:00:00.010000000, offset: 1323, offset_end: 1764, flags: 00000000 ) 0x7fedfc019170 /GstPipeline:pipeline0/GstIdentity:INTEL_AUDIO2: last-message = chain ******* (INTEL_AUDIO2:sink) (1764 bytes, dts: none, pts: 0:00:00.030000000, duration: 0:00:00.010000000, offset: 1323, offset_end: 1764, flags: 00000000 ) 0x7fedfc019170 /GstPipeline:pipeline0/GstIdentity:INTEL_AUDIO2: last-message = chain ******* (INTEL_AUDIO2:sink) (1764 bytes, dts: none, pts: 0:00:00.040000000, duration: 0:00:00.010000000, offset: 1764, offset_end: 2205, flags: 00000000 ) 0x7fedfc019280 /GstPipeline:pipeline0/GstIdentity:intel_audio1: last-message = chain ******* (intel_audio1:sink) (1764 bytes, dts: none, pts: 0:00:00.030000000, duration: 0:00:00.010000000, offset: 1323, offset_end: 1764, flags: 00000000 ) 0x7fedfc0199f0 /GstPipeline:pipeline0/GstIdentity:INTEL_AUDIO2: last-message = chain ******* (INTEL_AUDIO2:sink) (1764 bytes, dts: none, pts: 0:00:00.050000000, duration: 0:00:00.010000000, offset: 2205, offset_end: 2646, flags: 00000000 ) 0x7fedfc019390 In the above, second and third timestamp are the same (0:00:00.030000000) for INTEL_AUDIO2 path. INTEL AUDIO another try: $ gst-launch-1.0 -v alsasrc device=hw:4,0 ! identity silent=false name=intel_audio1 ! fakesink alsasrc device=hw:4,2 ! identity silent=false name=INTEL_AUDIO2 ! fakesink | grep last-message | grep pts /GstPipeline:pipeline0/GstIdentity:intel_audio1: last-message = chain ******* (intel_audio1:sink) (1764 bytes, dts: none, pts: 0:00:00.000000000, duration: 0:00:00.010000000, offset: 0, offset_end: 441, flags: 00000040 discont ) 0x7f4d6800f010 /GstPipeline:pipeline0/GstIdentity:intel_audio1: last-message = chain ******* (intel_audio1:sink) (1764 bytes, dts: none, pts: 0:00:00.000000000, duration: 0:00:00.010000000, offset: 0, offset_end: 441, flags: 00000040 discont ) 0x7f4d6800f010 /GstPipeline:pipeline0/GstIdentity:intel_audio1: last-message = chain ******* (intel_audio1:sink) (1764 bytes, dts: none, pts: 0:00:00.010000000, duration: 0:00:00.010000000, offset: 441, offset_end: 882, flags: 00000000 ) 0x7f4d6800f120 /GstPipeline:pipeline0/GstIdentity:INTEL_AUDIO2: last-message = chain ******* (INTEL_AUDIO2:sink) (1764 bytes, dts: none, pts: 0:00:00.020000000, duration: 0:00:00.010000000, offset: 882, offset_end: 1323, flags: 00000000 ) 0x7f4d6800f780 /GstPipeline:pipeline0/GstIdentity:intel_audio1: last-message = chain ******* (intel_audio1:sink) (1764 bytes, dts: none, pts: 0:00:00.020000000, duration: 0:00:00.010000000, offset: 882, offset_end: 1323, flags: 00000000 ) 0x7f4d6800f230 /GstPipeline:pipeline0/GstIdentity:INTEL_AUDIO2: last-message = chain ******* (INTEL_AUDIO2:sink) (1764 bytes, dts: none, pts: 0:00:00.030000000, duration: 0:00:00.010000000, offset: 1323, offset_end: 1764, flags: 00000000 ) In the above, first 2 timestamps are duplicated (0:00:00.000000000) for intel_audio1 path. Thanks for your help on this, Przemek
There is a race condition with this method to trace timestamp when using multiple sinks. When I trace with debug section instead, I don't see this issue. GST_DEBUG="*SCHED:6" gst-launch-1.0 ... 2>&1 | grep calling | head -n 30 Please confirm this is your issue.
Hello, I can still see duplicated time stamps with this command: $GST_DEBUG="*SCHED:6" gst-launch-1.0 -v alsasrc device=hw:0,0 ! identity silent=false name=digital ! fakesink alsasrc device=hw:1,0 ! identity silent=false name=ANALOG ! fakesink 2>&1 | grep last-message | grep pts Look at ANALOG sink device: /GstPipeline:pipeline0/GstIdentity:ANALOG: last-message = chain ******* (ANALOG:sink) (16384 bytes, dts: none, pts: 0:00:00.092879818, duration: 0:00:00.092879818, offset: 0, offset_end: 4096, flags: 00000040 discont ) 0x7ff0ec015020 /GstPipeline:pipeline0/GstIdentity:ANALOG: last-message = chain ******* (ANALOG:sink) (16384 bytes, dts: none, pts: 0:00:00.092879818, duration: 0:00:00.092879818, offset: 0, offset_end: 4096, flags: 00000040 discont ) 0x7ff0ec015020 /GstPipeline:pipeline0/GstIdentity:digital: last-message = chain ******* (digital:sink) (16384 bytes, dts: none, pts: 0:00:00.000000000, duration: 0:00:00.092879818, offset: 0, offset_end: 4096, flags: 00000040 discont ) 0x7ff0ec015680 /GstPipeline:pipeline0/GstIdentity:digital: last-message = chain ******* (digital:sink) (16384 bytes, dts: none, pts: 0:00:00.092879818, duration: 0:00:00.092879819, offset: 4096, offset_end: 8192... To reproduce, I had to run the pipeline 15 times. If I use the pipeline you proposed: $ GST_DEBUG="*SCHED:6" gst-launch-1.0 -v alsasrc device=hw:0,0 ! identity silent=false name=digital ! fakesink alsasrc device=hw:1,0 ! identity silent=false name=ANALOG ! fakesink 2>&1 | grep calling | head -n 30 I do not see any print outs for time stamps. Best regards, Przemek
(In reply to Przemek from comment #5) > To reproduce, I had to run the pipeline 15 times. > If I use the pipeline you proposed: > $ GST_DEBUG="*SCHED:6" gst-launch-1.0 -v alsasrc device=hw:0,0 ! identity > silent=false name=digital ! fakesink alsasrc device=hw:1,0 ! identity > silent=false name=ANALOG ! fakesink 2>&1 | grep calling | head -n 30 > I do not see any print outs for time stamps. I have introduced a typo in the debug category. It's GST_DEBUG="*SCHED*:6" (see the second *). The second * is needed since the debug category name is GST_SCHEDULING . Again, remove -v and ignore last-message, those are racy and does not represent the reality for your test. GST_DEBUG="*SCHED*:6" \ gst-launch-1.0 alsasrc device=hw:0,0 ! fakesink name=digitial \ alsasrc device=hw:1,0 ! fakesink name=ANALOG \ 2>&1 | grep calling | head -n 30
Hi Nicolas, Thank you - I tested your pipeline and I do not see duplicated timestamps when using GST_DEBUG section. There is one more thing here: Why sometimes time stamps start not from 0? What can it mean? Below we can see that first time stamp for digital:sink is 0 and for ANALOG:sink it is 0:00:00.278639455 $ GST_DEBUG="*SCHED*:6" gst-launch-1.0 alsasrc device=hw:2,0 ! fakesink name=digitial alsasrc device=hw:1,0 ! fakesink name=ANALOG 2>&1 | grep calling | head -n 30 0:00:00.083294748 17852 0x1582e30 DEBUG GST_SCHEDULING gstpad.c:4175:gst_pad_chain_data_unchecked:<digitial:sink> calling chainfunction &gst_base_sink_chain with buffer buffer: 0x7f4b380150a0, pts 0:00:00.000000000, dts 99:99:99.999999999, dur 0:00:00.092879818, size 16384, offset 0, offset_end 4096, flags 0x40 0:00:00.159345291 17852 0x1582de0 DEBUG GST_SCHEDULING gstpad.c:4175:gst_pad_chain_data_unchecked:<ANALOG:sink> calling chainfunction &gst_base_sink_chain with buffer buffer: 0x7f4b38015700, pts 0:00:00.278639455, dts 99:99:99.999999999, dur 0:00:00.092879818, size 16384, offset 0, offset_end 4096, flags 0x40 0:00:00.239419724 17852 0x1582e30 DEBUG GST_SCHEDULING gstpad.c:4175:gst_pad_chain_data_unchecked:<digitial:sink> calling chainfunction &gst_base_sink_chain with buffer buffer: 0x7f4b380151b0, pts 0:00:00.278639455, dts 99:99:99.999999999, dur 0:00:00.092879819, size 16384, offset 12288, offset_end 16384, flags 0x40 0:00:00.335248478 17852 0x1582e30 DEBUG GST_SCHEDULING gstpad.c:4175:gst_pad_chain_data_unchecked:<digitial:sink> calling chainfunction &gst_base_sink_chain with buffer buffer: 0x7f4b380152c0, pts 0:00:00.371519274, dts 99:99:99.999999999, dur 0:00:00.092879818, size 16384, offset 16384, offset_end 20480, flags 0x0 0:00:00.347317549 17852 0x1582de0 DEBUG GST_SCHEDULING gstpad.c:4175:gst_pad_chain_data_unchecked:<ANALOG:sink> calling chainfunction &gst_base_sink_chain with buffer buffer: 0x7f4b38015810, pts 0:00:00.371519274, dts 99:99:99.999999999, dur 0:00:00.092879818, size 16384, offset 16384, offset_end 20480, flags 0x0 Best regards, Przemek
In live pipeline, the pipeline will go in PLAYING state regardless of when the capture hardware is ready. Often, one capture will start before another, due to scheduling or other fluctuation in your system.
OK thanks, Przemek