[Bug 783443] rtp: fix gst_rtp_buffer_ext_timestamp taking into account backwards
GStreamer (GNOME Bugzilla)
bugzilla at gnome.org
Fri Oct 12 06:25:26 UTC 2018
https://bugzilla.gnome.org/show_bug.cgi?id=783443
--- Comment #19 from Kenneth Ekman <bkekman at gmail.com> ---
I tried using pcapdump yesterday but for some reason I didn't find any RTP
traffic in those, but I can do one better, since I modified the code to give
some extra prints that might be helpful.
I modified the gst_rtp_buffer_ext_timestamp() in rtpsource.c in this way:
guint64
gst_rtp_buffer_ext_timestamp (guint64 * exttimestamp, guint32 timestamp)
{
guint64 result, ext;
static int print_count = 1000;
g_return_val_if_fail (exttimestamp != NULL, -1);
ext = *exttimestamp;
if (ext == -1) {
result = timestamp;
GST_WARNING("gst_rtp_buffer_ext_timestamp() init time (-1) %u.",
timestamp);
print_count = 0;
} else {
/* pick wraparound counter from previous timestamp and add to new timestamp
*/
result = timestamp + (ext & ~(G_GUINT64_CONSTANT (0xffffffff)));
if (print_count < 20) {
GST_WARNING("gst_rtp_buffer_ext_timestamp() ext=%llu result=%llu ts=%u",
ext, result, timestamp);
print_count++;
}
/* check for timestamp wraparound */
if (result < ext) {
guint64 diff = ext - result;
if (diff > G_MAXINT32) {
/* timestamp went backwards more than allowed, we wrap around and get
* updated extended timestamp. */
result += (G_GUINT64_CONSTANT (1) << 32);
}
} else {
guint64 diff = result - ext;
if (print_count < 20) {
GST_WARNING("gst_rtp_buffer_ext_timestamp(). diff=%llu ext=%llu
result=%llu ts=%u", diff, ext, result, timestamp);
}
//syslog(LOG_INFO, "gst_rtp_buffer_ext_timestamp(). diff=%llu ext=%llu
result=%llu ts=%u", diff, ext, result, timestamp);
if (diff > G_MAXINT32) {
if (result < (G_GUINT64_CONSTANT (1) << 32)) {
GST_WARNING
("Cannot unwrap, any wrapping took place yet. Returning 0 without
updating extended timestamp. diff=%llu = (result:%llu - ext:%llu) %d", diff,
result, ext, print_count);
return 0;
} else {
/* timestamp went forwards more than allowed, we unwrap around and
get
* updated extended timestamp. */
result -= (G_GUINT64_CONSTANT (1) << 32);
/* We don't want the extended timestamp storage to go back, ever */
return result;
}
}
}
}
*exttimestamp = result;
return result;
}
And then enabled logs which gave me this debug log:
:01:31.375552516 13417 0x74a3d1b0 DEBUG rtpsource
rtpsource.c:310:rtp_source_init: init
0:01:31.376172868 13417 0x74a3d1b0 DEBUG rtpsource
rtpsource.c:420:rtp_source_create_stats: stats have_sr:0 ntp:0 rtp:0
0:01:31.376297632 13417 0x74a3d1b0 DEBUG rtpsource
rtpsource.c:455:rtp_source_create_stats: stats is_sender:0 internal:0
0:01:31.376570109 13417 0x74a3d1b0 DEBUG rtpsource
rtpsource.c:1434:rtp_source_process_rb: got RB packet: SSRC d137e7c8, FL 0, PL
0, HS 13481, jitter 208, LSR 0000:0000, DLSR 0000:0000
0:01:31.376643852 13417 0x74a3d1b0 DEBUG rtpsource
rtpsource.c:1461:rtp_source_process_rb: NTP 7d84:ea07, round trip 0000:0000
0:01:33.407796223 13417 0x20a9a60 DEBUG rtpsource
rtpsource.c:1508:rtp_source_get_new_sr: last_rtime 16:50:53.823602000,
last_rtptime 2921979845
0:01:33.407926541 13417 0x20a9a60 DEBUG rtpsource
rtpsource.c:1525:rtp_source_get_new_sr: running_time 16:50:53.950158501, diff
+0:00:00.126556501
0:01:33.407993301 13417 0x20a9a60 DEBUG rtpsource
rtpsource.c:1545:rtp_source_get_new_sr: NTP df697d86:f2464990, RTP 2921991235
0:01:33.408040838 13417 0x20a9a60 DEBUG rtpsource
rtpsource.c:1381:rtp_source_process_sr: got SR packet: SSRC 6c4fce98, NTP
df697d86:f2464990, RTP 2921991235, PC 93, OC 79703
0:01:33.412803901 13417 0x20a9a60 DEBUG rtpsource
rtpsource.c:420:rtp_source_create_stats: stats have_sr:1
ntp:16098536361556330896 rtp:2921991235
0:01:33.413959887 13417 0x20a9a60 DEBUG rtpsource
rtpsource.c:455:rtp_source_create_stats: stats is_sender:1 internal:1
0:01:35.927665932 13417 0x74a3d1b0 DEBUG rtpsource
rtpsource.c:1434:rtp_source_process_rb: got RB packet: SSRC d137e7c8, FL 0, PL
0, HS 13527, jitter 27, LSR 7d86:f246, DLSR 0002:837f
0:01:35.927810338 13417 0x74a3d1b0 DEBUG rtpsource
rtpsource.c:1461:rtp_source_process_rb: NTP 7d89:7765, round trip 0000:01a0
0:01:38.209085064 13417 0x20a9a60 DEBUG rtpsource
rtpsource.c:1508:rtp_source_get_new_sr: last_rtime 16:50:58.628891000,
last_rtptime 2922412321
0:01:38.209644704 13417 0x20a9a60 DEBUG rtpsource
rtpsource.c:1525:rtp_source_get_new_sr: running_time 16:50:58.751568058, diff
+0:00:00.122677058
0:01:38.209882484 13417 0x20a9a60 DEBUG rtpsource
rtpsource.c:1545:rtp_source_get_new_sr: NTP df697d8b:bf6f7e3d, RTP 2922423361
0:01:38.209984579 13417 0x20a9a60 DEBUG rtpsource
rtpsource.c:1381:rtp_source_process_sr: got SR packet: SSRC 6c4fce98, NTP
df697d8b:bf6f7e3d, RTP 2922423361, PC 141, OC 115062
0:01:38.210617558 13417 0x20a9a60 DEBUG rtpsource
rtpsource.c:420:rtp_source_create_stats: stats have_sr:1
ntp:16098536382178229821 rtp:2922423361
0:01:38.210734410 13417 0x20a9a60 DEBUG rtpsource
rtpsource.c:455:rtp_source_create_stats: stats is_sender:1 internal:1
0:01:38.464507519 13417 0x74921800 DEBUG rtpsource
rtpsource.c:351:rtp_source_finalize: finalize
0:01:38.464825193 13417 0x74921800 DEBUG rtpsource
rtpsource.c:351:rtp_source_finalize: finalize
0:01:43.107109562 13417 0x74903980 DEBUG rtpsource
rtpsource.c:276:rtp_source_reset: reset
0:01:43.107351368 13417 0x74903980 DEBUG rtpsource
rtpsource.c:310:rtp_source_init: init
0:01:43.112255198 13417 0x74903980 DEBUG rtpsource
rtpsource.c:822:rtp_source_update_caps: got payload 98
0:01:43.113232553 13417 0x74903980 DEBUG rtpsource
rtpsource.c:829:rtp_source_update_caps: got clock-rate 90000
0:01:43.113842709 13417 0x74903980 DEBUG rtpsource
rtpsource.c:838:rtp_source_update_caps: got seqnum-offset 12869
0:01:43.114307516 13417 0x74903980 DEBUG rtpsource
rtpsource.c:420:rtp_source_create_stats: stats have_sr:0 ntp:0 rtp:0
0:01:43.114956742 13417 0x74903980 DEBUG rtpsource
rtpsource.c:455:rtp_source_create_stats: stats is_sender:0 internal:1
0:01:43.117941375 13417 0x74903980 DEBUG rtpsource
rtpsource.c:1081:update_receiver_stats: received first packet
0:01:43.118929579 13417 0x74903980 DEBUG rtpsource
rtpsource.c:1018:init_seq: base_seq 12869
0:01:43.119544959 13417 0x74903980 WARN default
gstrtpbuffer.c:1279:gst_rtp_buffer_ext_timestamp:
gst_rtp_buffer_ext_timestamp() init time (-1) 208249398.
0:01:43.181388907 13417 0x2093090 DEBUG rtpsource
rtpsource.c:822:rtp_source_update_caps: got payload 98
0:01:43.181542976 13417 0x2093090 DEBUG rtpsource
rtpsource.c:829:rtp_source_update_caps: got clock-rate 90000
0:01:43.181605056 13417 0x2093090 DEBUG rtpsource
rtpsource.c:838:rtp_source_update_caps: got seqnum-offset 12870
0:01:43.182787457 13417 0x2093090 WARN default
gstrtpbuffer.c:1286:gst_rtp_buffer_ext_timestamp:
gst_rtp_buffer_ext_timestamp() ext=208249398 result=3917904230 ts=3917904230
0:01:43.182947905 13417 0x2093090 WARN default
gstrtpbuffer.c:1304:gst_rtp_buffer_ext_timestamp:
gst_rtp_buffer_ext_timestamp(). diff=3709654832 ext=208249398 result=3917904230
ts=3917904230
0:01:43.183023936 13417 0x2093090 WARN default
gstrtpbuffer.c:1311:gst_rtp_buffer_ext_timestamp: Cannot unwrap, any wrapping
took place yet. Returning 0 without updating extended timestamp.
diff=3709654832 = (result:3917904230 - ext:208249398) 1
0:01:44.168499877 13417 0x2093090 WARN default
gstrtpbuffer.c:1286:gst_rtp_buffer_ext_timestamp:
gst_rtp_buffer_ext_timestamp() ext=0 result=3917993368 ts=3917993368
0:01:44.169888692 13417 0x2093090 WARN default
gstrtpbuffer.c:1304:gst_rtp_buffer_ext_timestamp:
gst_rtp_buffer_ext_timestamp(). diff=3917993368 ext=0 result=3917993368
ts=3917993368
0:01:44.178445591 13417 0x2093090 WARN default
gstrtpbuffer.c:1311:gst_rtp_buffer_ext_timestamp: Cannot unwrap, any wrapping
took place yet. Returning 0 without updating extended timestamp.
diff=3917993368 = (result:3917993368 - ext:0) 2
0:01:44.183058848 13417 0x2093090 WARN default
gstrtpbuffer.c:1286:gst_rtp_buffer_ext_timestamp:
gst_rtp_buffer_ext_timestamp() ext=0 result=3917994751 ts=3917994751
0:01:44.183195251 13417 0x2093090 WARN default
gstrtpbuffer.c:1304:gst_rtp_buffer_ext_timestamp:
gst_rtp_buffer_ext_timestamp(). diff=3917994751 ext=0 result=3917994751
ts=3917994751
0:01:44.183291742 13417 0x2093090 WARN default
gstrtpbuffer.c:1311:gst_rtp_buffer_ext_timestamp: Cannot unwrap, any wrapping
took place yet. Returning 0 without updating extended timestamp.
diff=3917994751 = (result:3917994751 - ext:0) 3
0:01:44.183671362 13417 0x2093090 WARN default
gstrtpbuffer.c:1286:gst_rtp_buffer_ext_timestamp:
gst_rtp_buffer_ext_timestamp() ext=0 result=3917994751 ts=3917994751
0:01:44.183946057 13417 0x2093090 WARN default
gstrtpbuffer.c:1304:gst_rtp_buffer_ext_timestamp:
gst_rtp_buffer_ext_timestamp(). diff=3917994751 ext=0 result=3917994751
ts=3917994751
0:01:44.184031228 13417 0x2093090 WARN default
gstrtpbuffer.c:1311:gst_rtp_buffer_ext_timestamp: Cannot unwrap, any wrapping
took place yet. Returning 0 without updating extended timestamp.
diff=3917994751 = (result:3917994751 - ext:0) 4
0:01:44.188884042 13417 0x2093090 WARN default
gstrtpbuffer.c:1286:gst_rtp_buffer_ext_timestamp:
gst_rtp_buffer_ext_timestamp() ext=0 result=3917995281 ts=3917995281
0:01:44.189032189 13417 0x2093090 WARN default
gstrtpbuffer.c:1304:gst_rtp_buffer_ext_timestamp:
gst_rtp_buffer_ext_timestamp(). diff=3917995281 ext=0 result=3917995281
ts=3917995281
0:01:44.189095814 13417 0x2093090 WARN default
gstrtpbuffer.c:1311:gst_rtp_buffer_ext_timestamp: Cannot unwrap, any wrapping
took place yet. Returning 0 without updating extended timestamp.
diff=3917995281 = (result:3917995281 - ext:0) 5
0:01:44.192241405 13417 0x2093090 WARN default
gstrtpbuffer.c:1286:gst_rtp_buffer_ext_timestamp:
gst_rtp_buffer_ext_timestamp() ext=0 result=3917995578 ts=3917995578
0:01:44.192893085 13417 0x2093090 WARN default
gstrtpbuffer.c:1304:gst_rtp_buffer_ext_timestamp:
gst_rtp_buffer_ext_timestamp(). diff=3917995578 ext=0 result=3917995578
ts=3917995578
0:01:44.193222023 13417 0x2093090 WARN default
gstrtpbuffer.c:1311:gst_rtp_buffer_ext_timestamp: Cannot unwrap, any wrapping
took place yet. Returning 0 without updating extended timestamp.
diff=3917995578 = (result:3917995578 - ext:0) 6
0:01:44.196872319 13417 0x2093090 WARN default
gstrtpbuffer.c:1286:gst_rtp_buffer_ext_timestamp:
gst_rtp_buffer_ext_timestamp() ext=0 result=3917995843 ts=3917995843
0:01:44.208496302 13417 0x2093090 WARN default
gstrtpbuffer.c:1304:gst_rtp_buffer_ext_timestamp:
gst_rtp_buffer_ext_timestamp(). diff=3917995843 ext=0 result=3917995843
ts=3917995843
0:01:44.209510260 13417 0x2093090 WARN default
gstrtpbuffer.c:1311:gst_rtp_buffer_ext_timestamp: Cannot unwrap, any wrapping
took place yet. Returning 0 without updating extended timestamp.
diff=3917995843 = (result:3917995843 - ext:0) 7
0:01:44.210317310 13417 0x2093090 WARN default
gstrtpbuffer.c:1286:gst_rtp_buffer_ext_timestamp:
gst_rtp_buffer_ext_timestamp() ext=0 result=3917995985 ts=3917995985
0:01:44.210769165 13417 0x2093090 WARN default
gstrtpbuffer.c:1304:gst_rtp_buffer_ext_timestamp:
gst_rtp_buffer_ext_timestamp(). diff=3917995985 ext=0 result=3917995985
ts=3917995985
0:01:44.211106777 13417 0x2093090 WARN default
gstrtpbuffer.c:1311:gst_rtp_buffer_ext_timestamp: Cannot unwrap, any wrapping
took place yet. Returning 0 without updating extended timestamp.
diff=3917995985 = (result:3917995985 - ext:0) 8
0:01:44.234353079 13417 0x2093090 WARN default
gstrtpbuffer.c:1286:gst_rtp_buffer_ext_timestamp:
gst_rtp_buffer_ext_timestamp() ext=0 result=3917999357 ts=3917999357
--
You are receiving this mail because:
You are the QA Contact for the bug.
You are the assignee for the bug.
More information about the gstreamer-bugs
mailing list