GNOME Bugzilla – Bug 763325
Multiple netclocks do not work anymore
Last modified: 2016-03-11 15:56:18 UTC
Created attachment 323398 [details] Debug output On 1.6.1 this used to work, and does not work anymore on 1.7.90. My setup has two different GstNetClientClock, on two different Pipelines, running in the same application, synchronizing to the same remote master clock (gst-rtsp-server's test-netclock server). Both clocks share the same internal clock, which is fine. The attached debug output combines GST_DEBUG=2,netclock:7 with output from the program, including the PTS of all buffers received at the sinks plus the current clock at the time (gst_clock_get_time). As can be seen from the debug output, both clocks start at 0, and so does the remote clock. After a while, the remote clock jumps to the actual remote clock value. After a bit more, one of the clocks slaves to the remote clock, but the other does not, and stalls. On 1.6.1, all clocks stayed close to zero (which is probably wrong), but both pipelines run happily. I am currently working on a smaller test case that reproduces the issue.
Created attachment 323406 [details] [review] test.diff This seems to work just fine. Do you have a proper testcase for this problem, ideally one that only uses the clocks and does not potentially have problems in completely different areas?
I haven't succeeded in producing such testcase yet, but I am trying :) My original scenario involves NetClockClient (not PTP), rtsp:// and untimestamped H.264 data (it has to be untimestamped so I can use multifilesrc loop=1)
Note that my patch makes the PTP application use NTP (i.e. same clock code you're having problems with). Does that application work for you with NTP?
And if it does, please also print clock times of both clocks in your application. And check if wait_for_sync() makes a difference.
Your patch for ptp-print-times.c works for me, yes. In the log I attached there are already the times for both cloks, one for [pipeline 0x0000000009BD8A50] and the other for [pipeline 0x000000000D2F2D20]. Both clocks already wait for sync ("Trying to synchronize to network clock..."). The first one synchronizes in 0.15 seconds, and the other in 0 seconds.
Where do you print "Buffer PTS is 0:00:00.452795228 and current is 1169:43:06.740463543"? The second is the current clock time? Can you also print the pipelines' base times in the same line?
This is the relevant code: GstBuffer *buff = gst_sample_get_buffer(pipeline->last_sample); GstClockTime pts = GST_BUFFER_PTS(buff); GstClockTime curr = gst_clock_get_time(pipeline->net_clock) - gst_element_get_base_time(pipeline->pipeline); gub_log_pipeline(pipeline, "Buffer PTS is %" GST_TIME_FORMAT " and current is %" GST_TIME_FORMAT, GST_TIME_ARGS(pts), GST_TIME_ARGS(curr)); It is executed periodically, asynchronously from the gstreamer flow, and the sample is taken from fakesink's last-sample property.
Printed separatedly, gst_element_get_base_time() stays close to 0 for both pipelines, and gst_clock_get_time() jumps to 1176:... on both pipelines at the same time.
Created attachment 323414 [details] Testcase
The question is why the timestamps are jumping only on one pipeline but not the other. A log with rtpjitterbuffer:6 can probably help here.
I added a testcase. Unfortunately, it is not small. The source H.264 file contains no PTS, only DTS, so I had to add a decoder. Once I did, the jump in timestamps is evident. This test does not show the same behaviour I initially observed with my app, but it shows something odd already. One of the sinks keeps receiving increasing PTS, and the other suddently receives GST_CLOCK_NONE PTS. The source rtsp comes from gst-rtsp-server's test-netclock, with the following pipeline: test-netclock "( multifilesrc loop=1 location=llamadrama.h264 ! h264parse ! rtph264pay config-interval=1 name=pay0 )"
Created attachment 323416 [details] rtpjitterbuffer log GST_DEBUG=2,rtpjitter*:6
In this log the timestamps seem to become GST_CLOCK_TIME_NONE, which is different than before.
The PTS and DTS of the buffers coming out of the jitterbuffer also look fine. Maybe you can enable some more debug... rtp*:6 might help.
Created attachment 323475 [details] Log output with GST_DEBUG=2,rtp*:6
Created attachment 323485 [details] Debug output from original app with GST_DEBUG=2,rtp*:7
The test case produced the same results with 1.6.1 so it does not behave like the original app. I am removing the attachment. I added debug output from original app with rtp*:7
Problem here seems that udpsrc on one pipeline suddenly reports the clock time as DTS... probably a base time problem?
Created attachment 323497 [details] Debug output with GST_DEBUG=3,udp*:6,basesrc:6,rtp*:6
Created attachment 323499 [details] Lots and lots of debug info
Created attachment 323500 [details] [review] netclientclock: Don't reset calibration of internal clock whenever a new netclient clock is created
Created attachment 323507 [details] Debug output after patch (same debug levels)
Attachment 323500 [details] pushed as 7124e56 - netclientclock: Don't reset calibration of internal clock whenever a new netclient clock is created