From 63c7a9ae430db991746dc4b13d26d4f7945b2dc1 Mon Sep 17 00:00:00 2001 From: Havard Graff Date: Wed, 28 Oct 2020 00:29:05 +0100 Subject: [PATCH] rtpjitterbuffer: don't send multiple instant RTX for the same packet Due to us not properly acknowleding the time when the last RTX was sent when scheduling a new one, it can easily happen that due to the packet you are requesting have a PTS that is slightly old (but not too old when adding the latency of the jitterbuffer), both its calculated second and third (etc.) timeout could already have passed. This would lead to a burst of RTX requests, which acts completely against its purpose, potentially spending a lot more bandwidth than needed. This has been properly reproduced in the test: test_rtx_not_bursting_requests The good news is that slightly re-thinking the logic concerning re-requesting RTX, made it a lot simpler to understand, and allows us to remove two members of the RtpTimer which no longer serves any purpose due to the refactoring. If desirable the whole "delay" concept can actually be removed completely from the timers, and simply just added to the timeout by the caller of the API. But that can be a change for a another time. The only external change (other than the improved behavior around bursting RTX) is that the "delay" field now stricly represents the delay between the PTS of the RTX-requested packet and the time it is requested on, whereas before this calculation was more about the theoretical calculated delay. This is visible in three other RTX-tests where the delay had to be adjusted slightly. I am confident however that this change is correct. Part-of: --- gst/rtpmanager/gstrtpjitterbuffer.c | 33 ++++++++++++++--------- gst/rtpmanager/rtptimerqueue.c | 8 ++---- gst/rtpmanager/rtptimerqueue.h | 2 -- tests/check/elements/rtpjitterbuffer.c | 48 +++++++++++++++++++++++++++++++--- tests/check/elements/rtptimerqueue.c | 4 --- 5 files changed, 67 insertions(+), 28 deletions(-) diff --git a/gst/rtpmanager/gstrtpjitterbuffer.c b/gst/rtpmanager/gstrtpjitterbuffer.c index f9c3aef..8046988 100644 --- a/gst/rtpmanager/gstrtpjitterbuffer.c +++ b/gst/rtpmanager/gstrtpjitterbuffer.c @@ -3777,6 +3777,7 @@ do_expected_timeout (GstRtpJitterBuffer * jitterbuffer, RtpTimer * timer, GstClockTime rtx_retry_timeout; GstClock *clock; GstClockTimeDiff offset = 0; + GstClockTime timeout; GST_DEBUG_OBJECT (jitterbuffer, "expected %d didn't arrive, now %" GST_TIME_FORMAT, timer->seqnum, GST_TIME_ARGS (now)); @@ -3784,7 +3785,8 @@ do_expected_timeout (GstRtpJitterBuffer * jitterbuffer, RtpTimer * timer, rtx_retry_timeout = get_rtx_retry_timeout (priv); rtx_retry_period = get_rtx_retry_period (priv, rtx_retry_timeout); - delay = timer->rtx_delay + timer->rtx_retry; + /* delay expresses how late this packet is currently */ + delay = now - timer->rtx_base; delay_ms = GST_TIME_AS_MSECONDS (delay); rtx_retry_timeout_ms = GST_TIME_AS_MSECONDS (rtx_retry_timeout); @@ -3819,28 +3821,33 @@ do_expected_timeout (GstRtpJitterBuffer * jitterbuffer, RtpTimer * timer, } GST_OBJECT_UNLOCK (jitterbuffer); - /* calculate the timeout for the next retransmission attempt */ - timer->rtx_retry += rtx_retry_timeout; - GST_DEBUG_OBJECT (jitterbuffer, "timer #%i base %" GST_TIME_FORMAT ", delay %" - GST_TIME_FORMAT ", retry %" GST_TIME_FORMAT ", num_retry %u", - timer->seqnum, GST_TIME_ARGS (timer->rtx_base), - GST_TIME_ARGS (timer->rtx_delay), GST_TIME_ARGS (timer->rtx_retry), - timer->num_rtx_retry); + /* + Calculate the timeout for the next retransmission attempt: + We have just successfully sent one RTX request, and we need to + find out when to schedule the next one. + + The rtx_retry_timeout tells us the logical timeout between RTX + requests based on things like round-trip time, jitter and packet spacing, + and is how long we are going to wait before attempting another RTX packet + */ + timeout = timer->rtx_last + rtx_retry_timeout; + GST_DEBUG_OBJECT (jitterbuffer, + "timer #%i new timeout %" GST_TIME_FORMAT ", rtx retry timeout%" + GST_TIME_FORMAT ", num_retry %u", timer->seqnum, GST_TIME_ARGS (timeout), + GST_TIME_ARGS (rtx_retry_timeout), timer->num_rtx_retry); if ((priv->rtx_max_retries != -1 && timer->num_rtx_retry >= priv->rtx_max_retries) - || (timer->rtx_retry + timer->rtx_delay > rtx_retry_period) - || (timer->rtx_base + rtx_retry_period < now)) { + || (timeout > timer->rtx_base + rtx_retry_period)) { GST_DEBUG_OBJECT (jitterbuffer, "reschedule #%i as LOST timer", timer->seqnum); /* too many retransmission request, we now convert the timer * to a lost timer, leave the num_rtx_retry as it is for stats */ timer->type = RTP_TIMER_LOST; - timer->rtx_delay = 0; - timer->rtx_retry = 0; + timeout = timer->rtx_base; offset = timeout_offset (jitterbuffer); } rtp_timer_queue_update_timer (priv->timers, timer, timer->seqnum, - timer->rtx_base + timer->rtx_retry, timer->rtx_delay, offset, FALSE); + timeout, 0, offset, FALSE); return FALSE; } diff --git a/gst/rtpmanager/rtptimerqueue.c b/gst/rtpmanager/rtptimerqueue.c index 446a70e..7b13657 100644 --- a/gst/rtpmanager/rtptimerqueue.c +++ b/gst/rtpmanager/rtptimerqueue.c @@ -582,8 +582,6 @@ rtp_timer_queue_set_timer (RtpTimerQueue * queue, RtpTimerType type, if (!timer->queued || timer->seqnum != seqnum) { if (type == RTP_TIMER_EXPECTED) { timer->rtx_base = timeout; - timer->rtx_delay = delay; - timer->rtx_retry = 0; } timer->rtx_last = GST_CLOCK_TIME_NONE; @@ -702,11 +700,9 @@ rtp_timer_queue_update_timer (RtpTimerQueue * queue, RtpTimer * timer, g_return_if_fail (timer != NULL); if (reset) { - GST_DEBUG ("reset rtx delay %" GST_TIME_FORMAT "->%" GST_TIME_FORMAT, - GST_TIME_ARGS (timer->rtx_delay), GST_TIME_ARGS (delay)); + GST_DEBUG ("reset rtx base %" GST_TIME_FORMAT "->%" GST_TIME_FORMAT, + GST_TIME_ARGS (timer->rtx_base), GST_TIME_ARGS (timeout)); timer->rtx_base = timeout; - timer->rtx_delay = delay; - timer->rtx_retry = 0; } if (timer->seqnum != seqnum) { diff --git a/gst/rtpmanager/rtptimerqueue.h b/gst/rtpmanager/rtptimerqueue.h index 969cbd3..283f228 100644 --- a/gst/rtpmanager/rtptimerqueue.h +++ b/gst/rtpmanager/rtptimerqueue.h @@ -65,8 +65,6 @@ typedef struct GstClockTimeDiff offset; GstClockTime duration; GstClockTime rtx_base; - GstClockTime rtx_delay; - GstClockTime rtx_retry; GstClockTime rtx_last; guint num_rtx_retry; guint num_rtx_received; diff --git a/tests/check/elements/rtpjitterbuffer.c b/tests/check/elements/rtpjitterbuffer.c index 99cc57c..6097ef1 100644 --- a/tests/check/elements/rtpjitterbuffer.c +++ b/tests/check/elements/rtpjitterbuffer.c @@ -1318,6 +1318,46 @@ GST_START_TEST (test_rtx_expected_next) GST_END_TEST; +GST_START_TEST (test_rtx_not_bursting_requests) +{ + GstHarness *h = gst_harness_new ("rtpjitterbuffer"); + gint latency_ms = 200; + guint next_seqnum; + guint missing_seqnum; + GstClockTime now; + + g_object_set (h->element, + "do-lost", TRUE, + "do-retransmission", TRUE, + "rtx-next-seqnum", FALSE, "rtx-max-retries", 3, NULL); + + next_seqnum = construct_deterministic_initial_state (h, latency_ms); + now = gst_clock_get_time (GST_ELEMENT_CLOCK (h->element)); + + /* skip a packet and move the time for the next one + quite a bit forward */ + missing_seqnum = next_seqnum; + next_seqnum++; + now += 150 * GST_MSECOND; + gst_harness_set_time (h, now); + + push_test_buffer_now (h, next_seqnum, next_seqnum * TEST_RTP_TS_DURATION, + FALSE); + + /* note the delay here is 130. This is because we advanced the clock 150, + and 20 of those were the duration of the missing seqnum, so this + RTX event is in effect 130ms "late" compared to its ideal time */ + verify_rtx_event (h, missing_seqnum, + missing_seqnum * TEST_BUF_DURATION, 130, TEST_BUF_DURATION); + + /* verify we have not sent any other rtx events */ + fail_unless_equals_int (0, gst_harness_upstream_events_in_queue (h)); + + gst_harness_teardown (h); +} + +GST_END_TEST; + GST_START_TEST (test_rtx_next_seqnum_disabled) { GstHarness *h = gst_harness_new ("rtpjitterbuffer"); @@ -1623,7 +1663,7 @@ GST_START_TEST (test_rtx_original_buffer_does_not_update_rtx_stats) an rtx-request for 7 */ next_seqnum++; verify_rtx_event (h, next_seqnum, - next_seqnum * TEST_BUF_DURATION, rtx_delay_ms, TEST_BUF_DURATION); + next_seqnum * TEST_BUF_DURATION, 60, TEST_BUF_DURATION); /* The original buffer does not count in the RTX stats. */ fail_unless (verify_jb_stats (h->element, @@ -1950,7 +1990,7 @@ GST_START_TEST (test_rtx_no_request_if_time_past_retry_period) * late and unnecessary. However, in order to keep things simple (for now) * we just keep the already scehduled EXPECTED timer, but refrain from * scheduled another EXPECTED timer */ - verify_rtx_event (h, 2, 2 * TEST_BUF_DURATION, 10, TEST_BUF_DURATION); + verify_rtx_event (h, 2, 2 * TEST_BUF_DURATION, 120, TEST_BUF_DURATION); /* "crank" to reach the DEADLINE for packet 0 */ gst_harness_crank_single_clock_wait (h); @@ -2067,7 +2107,7 @@ GST_START_TEST (test_rtx_with_backwards_rtptime) gst_harness_set_time (h, 6 * TEST_BUF_DURATION + 15 * GST_MSECOND); gst_harness_crank_single_clock_wait (h); verify_rtx_event (h, 6, 5 * TEST_BUF_DURATION + 15 * GST_MSECOND, - 17, 35 * GST_MSECOND); + 20, 35 * GST_MSECOND); fail_unless (verify_jb_stats (h->element, gst_structure_new ("application/x-rtp-jitterbuffer-stats", @@ -3180,6 +3220,8 @@ rtpjitterbuffer_suite (void) test_loss_equidistant_spacing_with_parameter_packets); tcase_add_test (tc_chain, test_rtx_expected_next); + tcase_add_test (tc_chain, test_rtx_not_bursting_requests); + tcase_add_test (tc_chain, test_rtx_next_seqnum_disabled); tcase_add_test (tc_chain, test_rtx_two_missing); tcase_add_test (tc_chain, test_rtx_buffer_arrives_just_in_time); diff --git a/tests/check/elements/rtptimerqueue.c b/tests/check/elements/rtptimerqueue.c index a39da7f..30a9dd6 100644 --- a/tests/check/elements/rtptimerqueue.c +++ b/tests/check/elements/rtptimerqueue.c @@ -37,8 +37,6 @@ GST_START_TEST (test_timer_queue_set_timer) fail_unless_equals_uint64 (3 * GST_SECOND, timer10->timeout); fail_unless_equals_uint64 (5 * GST_SECOND, timer10->duration); fail_unless_equals_uint64 (1 * GST_SECOND, timer10->rtx_base); - fail_unless_equals_uint64 (2 * GST_SECOND, timer10->rtx_delay); - fail_unless_equals_uint64 (0, timer10->rtx_retry); fail_unless_equals_uint64 (GST_CLOCK_TIME_NONE, timer10->rtx_last); fail_unless_equals_int (0, timer10->num_rtx_retry); fail_unless_equals_int (0, timer10->num_rtx_received); @@ -52,8 +50,6 @@ GST_START_TEST (test_timer_queue_set_timer) fail_unless_equals_uint64 (2 * GST_SECOND, timer0->timeout); fail_unless_equals_uint64 (0, timer0->duration); fail_unless_equals_uint64 (0, timer0->rtx_base); - fail_unless_equals_uint64 (0, timer0->rtx_delay); - fail_unless_equals_uint64 (0, timer0->rtx_retry); fail_unless_equals_uint64 (GST_CLOCK_TIME_NONE, timer0->rtx_last); fail_unless_equals_int (0, timer0->num_rtx_retry); fail_unless_equals_int (0, timer0->num_rtx_received); -- 2.7.4