GNOME Bugzilla – Bug 657221
Bug with clock dv
Last modified: 2016-02-21 12:45:56 UTC
I think i have a bug with clock dv. You can found more detail about it in the link below. http://pastebin.com/zF9gfxyt
Content of the pastebin linked above: My aim is to get dv source to make different treatment. - In first time, I record the dv source in mkv file where video is in mjpeg and audio is raw. - In second time, I want to stream in flv so the video is encoded in x264 and the audio in faac. When I build the pipeline that can do this thing, i have a error of dv clock. this is my pipeline : gst-launch-0.10 dv1394src port=0 guid=0x0020110114009d97 ! queue max-size-time=30000000000 ! dvdemux name=dv_src ! queue max-size-time=30000000000 ! dvdec ! ffmpegcolorspace ! ffdeinterlace ! videoscale ! videorate ! "video/x-raw-yuv, format=(fourcc)I420, width=(int)768, height=(int)576, framerate=(fraction)25/1, pixel-aspect-ratio=(fraction)1/1" ! queue name=decoded0 ! queue ! tee name=v_src_tee dv_src. ! "audio/x-raw-int" ! queue ! volume ! audiorate tolerance=40000000 ! identity ! level ! tee name=a_src_tee v_src_tee. ! queue ! ffenc_mjpeg bitrate=40000000 ! queue ! tee name=v_enc_0_tee a_src_tee. ! queue ! matroskamux name=muxer ! queue ! tee name=muxer_tee v_enc_0_tee. ! queue ! muxer. muxer_tee. ! filesink location=/mnt/recordings/original.mkv v_src_tee. ! queue ! ffmpegcolorspace ! videorate ! videoscale ! "video/x-raw-yuv, format=(fourcc)I420, width=(int)256, height=(int)144, framerate=(fraction)25/1" ! x264enc bitrate=160 threads=2 byte-stream=False name=vencoder_1 ! queue ! tee name=v_enc_1_tee a_src_tee. ! queue ! faac bitrate=32000 profile=2 ! queue ! tee name=a_enc_1_tee a_enc_1_tee. ! queue ! flvmux streamable=True name=flvmux ! queue leaky=2 ! rtmpsink location=rtmp://fms.ubicast.net:1935/live/live-test-server-53 v_enc_1_tee. ! queue ! flvmux. -v I added identity just beside audiorate to have more information that you can see just below. At the begining the duration is 40ms but after a while the duration change. /GstPipeline:pipeline0/GstIdentity:identity0: last-message = "chain ******* (identity0:sink)i (7680 bytes, timestamp: 0:00:16.736625000, duration: 0:00:00.040000000, offset: 803358, offset_end: 805278, flags: 0) 0xac857698" /GstPipeline:pipeline0/GstIdentity:identity0: last-message = "chain ******* (identity0:sink)i (7680 bytes, timestamp: 0:00:16.776625000, duration: 0:00:00.040000000, offset: 805278, offset_end: 807198, flags: 0) 0x9000400" /GstPipeline:pipeline0/GstIdentity:identity0: last-message = "chain ******* (identity0:sink)i (192000 bytes, timestamp: 0:00:16.816625000, duration: 0:00:01.000000000, offset: 807198, offset_end: 855198, flags: 128) 0xac803690" /GstPipeline:pipeline0/GstIdentity:identity0: last-message = "chain ******* (identity0:sink)i (192000 bytes, timestamp: 0:00:17.816625000, duration: 0:00:01.000000000, offset: 855198, offset_end: 903198, flags: 128) 0xac8035f0"
Looks correct to me. DV cameras occasionally "forget" to send audio with a frame, so you might get one or more frames with no audio data. The audiorate element cleans this up, and it appears you're getting 1.0 s buffers as a result.
I found an interesting information In function gst_1394_clock_get_internal_time of gst1394clock.c file, i added an usleep of 200 microseconds to see the behavior. ''' GST_OBJECT_LOCK (clock); raw1394_read_cycle_timer (_1394clock->handle, &cycle_timer, &local_time); if (cycle_timer < _1394clock->cycle_timer_lo) { GST_LOG_OBJECT (clock, "overflow %u to %u", _1394clock->cycle_timer_lo, cycle_timer); _1394clock->cycle_timer_hi++; } _1394clock->cycle_timer_lo = cycle_timer; /* get the seconds from the cycleSeconds counter */ result = (((((guint64) _1394clock->cycle_timer_hi) << 32) | cycle_timer) >> 25) * GST_SECOND; /* add the microseconds from the cycleCount counter */ result += (((cycle_timer >> 12) & 0x1fff) * 125) * GST_USECOND; usleep (200); GST_LOG_OBJECT (clock, "result %" GST_TIME_FORMAT, GST_TIME_ARGS (result)); GST_OBJECT_UNLOCK (clock); ''' I notice when I added usleep, the clock seems worked perfectly. I'm running the same pipeline for 1:30 while before she rans only 10 minutes. I know that adding an usleep function is not something good. What could be doing to replace it? Is that the problem is hardware or software (gstreamer plugin)? I hope this information will help you.
This looks like a driver bug, or possibly hardware. Also, it appears you aren't doing anything to check if the encoder gets really far behind and the queues fill up. This can cause drops in the dv source.
Sorry, i will do others tests to try if the problem may be encoder. I will try to locate the problem more precisely.
I found something, again a pipeline that doesn't work with dv source and alsasink I share dv source for 2 alsasink and i have the same bug with timestamp audio. Pipeline exemple : gst-launch dv1394src port=0 guid=0x0020110114009d97 ! dvdemux name=dv_src ! "audio/x-raw-int" ! volume name=volume volume=0.479999989271 ! audiorate tolerance=40000000 ! identity ! level ! tee name=a_src_tee a_src_tee. ! queue ! audioconvert ! alsasink a_src_tee. ! queue ! audioconvert ! alsasink -v It's difficult to try different pipeline and locate precisely a bug. I don't know if this can help you.
Created attachment 200025 [details] [review] dv1394src: check return value of raw1394_ready_cycle_timer
The return type is never checked, which happens when it's not supported by the kernel (see #662775). Can you check in the logs if this is happening when you see those jumps?
I try many test but i still can't figure out what is the problem. I think it comes from my device. I add your patch, but when i have the bug raw1394_read_cycle_timer return the same value than when it works well. I dont know if the value returned is the good one. I noticed that : 1. When the bug arrived with alsasink, i have this warn : "baseaudiosink gstbaseaudiosink.c:1088:gst_base_audio_sink_skew_slaving:<alsasink0> correct clock skew 20002520 > 20000000" so when i add slave-method=2 et provide-clock=true properties in alsasink, the pipeline works. 2. when i want to make a streaming i have other warm : "x264enc :0::<vencoder_2> VBV underflow (frame 308, -7488 bits)" and i try to add printf to have more informations. Here is the result obtained: {{{ /GstPipeline:pipeline0/GstIdentity:identity0: last-message = "chain ******* (identity0:sink)i (7680 bytes, timestamp: 0:00:36.288375000, duration: 0:00:00.040000000, offset: 1741842, offset_end: 1743762, flags: 0) 0x9086060" ---------------------------------------------------------------- cycle_timer : -1266673534, local_time : 1320417289863809 cycle : -1266673534, _1394clock->cycle_timer_lo : -1266823081 calcul second : 0, cycle_timer ; -1266673534 ---------------------------------------------------------------- cycle_timer : -1266670707, local_time : 1320417289863883 cycle : -1266670707, _1394clock->cycle_timer_lo : -1266673534 calcul second : 0, cycle_timer ; -1266670707 ---------------------------------------------------------------- cycle_timer : -1266227878, local_time : 1320417289877400 cycle : -1266227878, _1394clock->cycle_timer_lo : -1266670707 calcul second : 0, cycle_timer ; -1266227878 ---------------------------------------------------------------- cycle_timer : -1266227131, local_time : 1320417289877430 cycle : -1266227131, _1394clock->cycle_timer_lo : -1266227878 calcul second : 0, cycle_timer ; -1266227131 ---------------------------------------------------------------- cycle_timer : -1265977228, local_time : 1320417289885056 cycle : -1265977228, _1394clock->cycle_timer_lo : -1266227131 calcul second : 0, cycle_timer ; -1265977228 ---------------------------------------------------------------- cycle_timer : -1265979391, local_time : 1320417289885093 cycle : -1265979391, _1394clock->cycle_timer_lo : -1265977228 pass here!! calcul second : 1, cycle_timer ; -1265979391 ---------------------------------------------------------------- cycle_timer : -1265798285, local_time : 1320417289890503 cycle : -1265798285, _1394clock->cycle_timer_lo : -1265979391 calcul second : 1, cycle_timer ; -1265798285 ---------------------------------------------------------------- /GstPipeline:pipeline0/GstIdentity:identity0: last-message = "chain ******* (identity0:sink)i (192000 bytes, timestamp: 0:00:36.328375000, duration: 0:00:01.000000000, offset: 1743762, offset_end: 1791762, flags: 128) 0xb4c06620" }}} We can noticed that when _1394clock->cycle_timer_lo seems smaller than cycle and when this arrive, i have a overflow log message and _1394clock->cycle_timer_hi is incremented. So result is incorrect and that why i have duration which is modified. Maybe the better solution is to add property to use clock hardware. i hope this will help to correct the bug or to add property provide-clock like alsasink
Any news on this?
Unfortunately not, we ended up not using alsa sources nor sinks in pipelines having a firewire source element. One possible solution which we briefly discussed with David at the gst conference would be to add a property which enables or disables the use of hardware-based clocking; if disabled, it would use the former method for dv clocking (i.e. software clocking).
Ok, so what should we do with this bug? Andoni, is your patch still relevant?
Closing this bug report as no further information has been provided. Please feel free to reopen this bug report if you can provide the information that was asked for in a previous comment. Thanks!