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 763325 - Multiple netclocks do not work anymore
Multiple netclocks do not work anymore
Product: GStreamer
Classification: Platform
Component: gstreamer (core)
Other All
: Normal blocker
: 1.7.91
Assigned To: GStreamer Maintainers
GStreamer Maintainers
Depends on:
Reported: 2016-03-08 14:26 UTC by Xavi Artigas
Modified: 2016-03-11 15:56 UTC
See Also:
GNOME target: ---
GNOME version: ---

Debug output (189.01 KB, text/plain)
2016-03-08 14:26 UTC, Xavi Artigas
test.diff (3.03 KB, patch)
2016-03-08 15:09 UTC, Sebastian Dröge (slomo)
none Details | Review
Testcase (3.02 KB, text/plain)
2016-03-08 16:29 UTC, Xavi Artigas
rtpjitterbuffer log GST_DEBUG=2,rtpjitter*:6 (179.23 KB, application/octet-stream)
2016-03-08 16:38 UTC, Xavi Artigas
Log output with GST_DEBUG=2,rtp*:6 (29.08 KB, application/x-zip-compressed)
2016-03-09 07:38 UTC, Xavi Artigas
Debug output from original app with GST_DEBUG=2,rtp*:7 (362.40 KB, application/x-zip-compressed)
2016-03-09 09:58 UTC, Xavi Artigas
Debug output with GST_DEBUG=3,udp*:6,basesrc:6,rtp*:6 (466.90 KB, application/x-zip-compressed)
2016-03-09 10:45 UTC, Xavi Artigas
Lots and lots of debug info (802.49 KB, application/x-zip-compressed)
2016-03-09 11:06 UTC, Xavi Artigas
netclientclock: Don't reset calibration of internal clock whenever a new netclient clock is created (3.28 KB, patch)
2016-03-09 11:46 UTC, Sebastian Dröge (slomo)
committed Details | Review
Debug output after patch (same debug levels) (819.29 KB, application/x-bzip)
2016-03-09 13:35 UTC, Xavi Artigas

Description Xavi Artigas 2016-03-08 14:26:01 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.
Comment 1 Sebastian Dröge (slomo) 2016-03-08 15:09:57 UTC
Created attachment 323406 [details] [review]

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?
Comment 2 Xavi Artigas 2016-03-08 15:14:08 UTC
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)
Comment 3 Sebastian Dröge (slomo) 2016-03-08 15:30:03 UTC
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?
Comment 4 Sebastian Dröge (slomo) 2016-03-08 15:30:33 UTC
And if it does, please also print clock times of both clocks in your application. And check if wait_for_sync() makes a difference.
Comment 5 Xavi Artigas 2016-03-08 15:36:32 UTC
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.
Comment 6 Sebastian Dröge (slomo) 2016-03-08 15:49:38 UTC
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?
Comment 7 Xavi Artigas 2016-03-08 16:03:03 UTC
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.
Comment 8 Xavi Artigas 2016-03-08 16:10:04 UTC
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.
Comment 9 Xavi Artigas 2016-03-08 16:29:46 UTC
Created attachment 323414 [details]
Comment 10 Sebastian Dröge (slomo) 2016-03-08 16:34:35 UTC
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.
Comment 11 Xavi Artigas 2016-03-08 16:35:10 UTC
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 )"
Comment 12 Xavi Artigas 2016-03-08 16:38:20 UTC
Created attachment 323416 [details]
rtpjitterbuffer log GST_DEBUG=2,rtpjitter*:6
Comment 13 Sebastian Dröge (slomo) 2016-03-08 18:51:37 UTC
In this log the timestamps seem to become GST_CLOCK_TIME_NONE, which is different than before.
Comment 14 Sebastian Dröge (slomo) 2016-03-08 18:53:28 UTC
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.
Comment 15 Xavi Artigas 2016-03-09 07:38:48 UTC
Created attachment 323475 [details]
Log output with GST_DEBUG=2,rtp*:6
Comment 16 Xavi Artigas 2016-03-09 09:58:13 UTC
Created attachment 323485 [details]
Debug output from original app with GST_DEBUG=2,rtp*:7
Comment 17 Xavi Artigas 2016-03-09 09:59:13 UTC
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
Comment 18 Sebastian Dröge (slomo) 2016-03-09 10:42:07 UTC
Problem here seems that udpsrc on one pipeline suddenly reports the clock time as DTS... probably a base time problem?
Comment 19 Xavi Artigas 2016-03-09 10:45:42 UTC
Created attachment 323497 [details]
Debug output with GST_DEBUG=3,udp*:6,basesrc:6,rtp*:6
Comment 20 Xavi Artigas 2016-03-09 11:06:58 UTC
Created attachment 323499 [details]
Lots and lots of debug info
Comment 21 Sebastian Dröge (slomo) 2016-03-09 11:46:40 UTC
Created attachment 323500 [details] [review]
netclientclock: Don't reset calibration of internal clock whenever a new netclient clock is created
Comment 22 Xavi Artigas 2016-03-09 13:35:08 UTC
Created attachment 323507 [details]
Debug output after patch (same debug levels)
Comment 23 Sebastian Dröge (slomo) 2016-03-09 13:41:08 UTC
Attachment 323500 [details] pushed as 7124e56 - netclientclock: Don't reset calibration of internal clock whenever a new netclient clock is created