rtpjitterbuffer: Improved expected-timer handling when gap > 0
authorHavard Graff <havard.graff@gmail.com>
Thu, 11 Aug 2016 10:02:19 +0000 (12:02 +0200)
committerOlivier Crête <olivier.crete@collabora.com>
Wed, 14 Sep 2016 23:37:50 +0000 (19:37 -0400)
https://bugzilla.gnome.org/show_bug.cgi?id=769768

gst/rtpmanager/gstrtpjitterbuffer.c
tests/check/elements/rtpjitterbuffer.c

index f8bfeb9..d00e5f2 100644 (file)
@@ -2404,7 +2404,7 @@ calculate_expected (GstRtpJitterBuffer * jitterbuffer, guint32 expected,
     guint16 seqnum, GstClockTime dts, gint gap)
 {
   GstRtpJitterBufferPrivate *priv = jitterbuffer->priv;
-  GstClockTime total_duration, duration, expected_dts;
+  GstClockTime total_duration, duration, expected_dts, delay;
   TimerType type;
 
   GST_DEBUG_OBJECT (jitterbuffer,
@@ -2466,18 +2466,20 @@ calculate_expected (GstRtpJitterBuffer * jitterbuffer, guint32 expected,
   }
 
   expected_dts = priv->last_in_dts + duration;
+  delay = 0;
 
   if (priv->do_retransmission) {
     TimerData *timer = find_timer (jitterbuffer, expected);
 
     type = TIMER_TYPE_EXPECTED;
+    delay = get_rtx_delay (priv);
+
     /* if we had a timer for the first missing packet, update it. */
     if (timer && timer->type == TIMER_TYPE_EXPECTED) {
       GstClockTime timeout = timer->timeout;
 
       timer->duration = duration;
-      if (timeout > (expected_dts + timer->rtx_retry)) {
-        GstClockTime delay = timeout - expected_dts - timer->rtx_retry;
+      if (timeout > (expected_dts + delay) && timer->num_rtx_retry == 0) {
         reschedule_timer (jitterbuffer, timer, timer->seqnum, expected_dts,
             delay, TRUE);
       }
@@ -2489,7 +2491,7 @@ calculate_expected (GstRtpJitterBuffer * jitterbuffer, guint32 expected,
   }
 
   while (gst_rtp_buffer_compare_seqnum (expected, seqnum) > 0) {
-    add_timer (jitterbuffer, type, expected, 0, expected_dts, 0, duration);
+    add_timer (jitterbuffer, type, expected, 0, expected_dts, delay, duration);
     expected_dts += duration;
     expected++;
   }
index 5db51ba..b2a73ba 100644 (file)
@@ -1009,123 +1009,201 @@ GST_START_TEST (test_rtx_two_missing)
 {
   GstHarness *h = gst_harness_new ("rtpjitterbuffer");
   GstTestClock *testclock;
-  GstBuffer *out_buf;
-  GstEvent *out_event;
-  gint jb_latency_ms = 200;
-  const GstClockTime rtx_retry_timeout = 40 * GST_MSECOND;
-  gint i;
+  gint latency_ms = 200;
+  gint rtx_delay_ms;
+  GstClockTime last_rtx_request, now;
 
-  gst_harness_set_src_caps (h, generate_caps ());
   testclock = gst_harness_get_testclock (h);
+  gst_harness_set_src_caps (h, generate_caps ());
+  g_object_set (h->element, "do-retransmission", TRUE, "latency", latency_ms,
+      NULL);
 
-  g_object_set (h->element, "do-lost", TRUE, NULL);
-  g_object_set (h->element, "do-retransmission", TRUE, NULL);
-  g_object_set (h->element, "latency", jb_latency_ms, NULL);
-  g_object_set (h->element, "rtx-retry-period", 120, NULL);
+  for (gint i = 0; i <= latency_ms / PCMU_BUF_MS; i++) {
+    gst_test_clock_set_time (testclock, i * PCMU_BUF_DURATION);
+    fail_unless_equals_int (GST_FLOW_OK,
+        gst_harness_push (h, generate_test_buffer (i)));
+    gst_harness_wait_for_clock_id_waits (h, 1, 60);
+  }
 
-  /* push the first buffer in */
-  fail_unless_equals_int (GST_FLOW_OK,
-      gst_harness_push (h, generate_test_buffer (0)));
+  gst_harness_crank_single_clock_wait (h);
+  fail_unless_equals_int64 (latency_ms * GST_MSECOND,
+      gst_clock_get_time (GST_CLOCK (testclock)));
 
-  gst_harness_set_time (h, 20 * GST_MSECOND);
+  for (gint i = 0; i <= latency_ms / PCMU_BUF_MS; i++)
+    gst_buffer_unref (gst_harness_pull (h));
 
-  /* put second buffer, the jitterbuffer should now know that the packet
-   * spacing is 20ms and should ask for retransmission of seqnum 2 in
-   * 20ms+10ms because 2*jitter==0 and 0.5*packet_spacing==10ms */
-  fail_unless_equals_int (GST_FLOW_OK,
-      gst_harness_push (h, generate_test_buffer (1)));
+  /* drop reconfigure event */
+  gst_event_unref (gst_harness_pull_upstream_event (h));
+
+  /*
+     The expected sequence of buffers is this:
+          ____   ____   ____   ____
+     ... | 10 | | 11 | | 12 | | 13 |
+          ––––   ––––   ––––   ––––
+          200ms  220ms  240ms  260ms
+
+     But instead we get this:
+          ____    _ _    _ _   ____
+     ... | 10 |  |   |  |   | | 13 |
+          ––––    - -    - -   ––––
+          200ms                260ms
+
+     Now it is important to note that the next thing that happens is that
+     the RTX timeout for packet 11 will happen at time 230ms, so we crank
+     the timer thread to advance the time to this: */
+  gst_harness_crank_single_clock_wait (h);
+  rtx_delay_ms = PCMU_BUF_MS / 2;
+  verify_rtx_event (gst_harness_pull_upstream_event (h),
+      11, 11 * PCMU_BUF_DURATION, rtx_delay_ms, PCMU_BUF_DURATION);
+  last_rtx_request = gst_clock_get_time (GST_CLOCK (testclock));
+  fail_unless_equals_int64 (last_rtx_request,
+      11 * PCMU_BUF_DURATION + rtx_delay_ms * GST_MSECOND);
+  gst_harness_wait_for_clock_id_waits (h, 1, 60);
 
-  /* push buffer 4, 2 and 3 are missing now, we should get
-   * retransmission events for 3 at 100ms*/
+  /* The next scheduled RTX for packet 11 is now at 230 + 40 = 270ms,
+     so the next thing that happens is that buffer 13 arrives in perfect time: */
+  now = 13 * PCMU_BUF_DURATION;
+  gst_harness_set_time (h, now);
   fail_unless_equals_int (GST_FLOW_OK,
-      gst_harness_push (h, generate_test_buffer (4)));
+      gst_harness_push (h,
+          generate_test_buffer_full (now, TRUE, 13,
+              13 * PCMU_RTP_TS_DURATION)));
 
-  /* wait for first retransmission request */
-  gst_test_clock_set_time_and_process (testclock, 50 * GST_MSECOND);
+  /*
 
-  /* drop reconfigure event */
-  gst_event_unref (gst_harness_pull_upstream_event (h));
-  /* drop GstEventStreamStart & GstEventCaps & GstEventSegment */
-  for (int i = 0; i < 3; i++)
-    gst_event_unref (gst_harness_pull_event (h));
+     This will estimate the dts on the two missing packets to:
+          ____   ____
+     ... | 11 | | 12 | ...
+          ––––   ––––
+          220ms  240ms
 
-  /* First event for 2 */
-  out_event = gst_harness_pull_upstream_event (h);
-  verify_rtx_event (out_event, 2, rtx_retry_timeout, 10, PCMU_BUF_DURATION);
+     And given their regular interspacing of 20ms, it will schedule two RTX
+     timers for them like so:
 
-  /* wait for second retransmission request */
-  gst_test_clock_set_time_and_process (testclock, 60 * GST_MSECOND);
+          ____   ____
+     ... | 11 | | 12 | ...
+          ––––   ––––
+          230ms  250ms
 
-  /* Second event for 3 */
-  out_event = gst_harness_pull_upstream_event (h);
-  verify_rtx_event (out_event, 3, 60 * GST_MSECOND, 0, PCMU_BUF_DURATION);
+     There are however two problems, packet 11 we have already sent one RTX for
+     and its timeout is currently at 270ms, so we should not tamper with that,
+     and as for packet 12, 250ms has already expired, so we now expect to see
+     an rtx-event being sent for packet 12 immediately: */
+  verify_rtx_event (gst_harness_pull_upstream_event (h),
+      12, 12 * PCMU_BUF_DURATION, rtx_delay_ms, PCMU_BUF_DURATION);
 
-  /* now we wait for the next timeout for 2 */
-  gst_test_clock_set_time_and_process (testclock, 90 * GST_MSECOND);
+  /* and another crank will see the second RTX event being sent for packet 11 */
+  gst_harness_crank_single_clock_wait (h);
+  rtx_delay_ms += 40;
+  verify_rtx_event (gst_harness_pull_upstream_event (h),
+      11, 11 * PCMU_BUF_DURATION, rtx_delay_ms, PCMU_BUF_DURATION);
+  last_rtx_request = gst_clock_get_time (GST_CLOCK (testclock));
+  fail_unless_equals_int64 (last_rtx_request,
+      11 * PCMU_BUF_DURATION + rtx_delay_ms * GST_MSECOND);
 
-  /* First event for 2 */
-  out_event = gst_harness_pull_upstream_event (h);
-  verify_rtx_event (out_event, 2, rtx_retry_timeout, 50, PCMU_BUF_DURATION);
+  gst_object_unref (testclock);
+  gst_harness_teardown (h);
+}
 
-  /* now we wait for the next timeout for 3 */
-  gst_test_clock_set_time_and_process (testclock, 100 * GST_MSECOND);
+GST_END_TEST;
 
-  /* Second event for 3 */
-  out_event = gst_harness_pull_upstream_event (h);
-  verify_rtx_event (out_event, 3, 60 * GST_MSECOND, 40, PCMU_BUF_DURATION);
+GST_START_TEST (text_rtx_two_missing_early)
+{
+  GstHarness *h = gst_harness_new ("rtpjitterbuffer");
+  GstTestClock *testclock;
+  gint latency_ms = 30;
+  GstClockTime last_rtx_request, now;
 
-  /* make buffer 3 */
-  fail_unless_equals_int (GST_FLOW_OK,
-      gst_harness_push (h,
-          generate_test_buffer_rtx (gst_clock_get_time (GST_CLOCK (testclock)),
-              3)));
+  testclock = gst_harness_get_testclock (h);
+  gst_harness_set_src_caps (h, generate_caps ());
+  g_object_set (h->element, "do-retransmission", TRUE, "latency", latency_ms,
+      NULL);
 
-  /* make more buffers */
-  for (i = 5; i < 15; i++) {
+  for (gint i = 0; i <= latency_ms / PCMU_BUF_MS; i++) {
+    gst_test_clock_set_time (testclock, i * PCMU_BUF_DURATION);
     fail_unless_equals_int (GST_FLOW_OK,
         gst_harness_push (h, generate_test_buffer (i)));
+    gst_harness_wait_for_clock_id_waits (h, 1, 60);
   }
 
-  gst_test_clock_set_time_and_process (testclock, 130 * GST_MSECOND);
+  gst_harness_crank_single_clock_wait (h);
+  fail_unless_equals_int64 (latency_ms * GST_MSECOND,
+      gst_clock_get_time (GST_CLOCK (testclock)));
 
-  /* now we only get requests for 2 */
-  out_event = gst_harness_pull_upstream_event (h);
-  verify_rtx_event (out_event, 2, rtx_retry_timeout, 90, PCMU_BUF_DURATION);
+  for (gint i = 0; i <= latency_ms / PCMU_BUF_MS; i++)
+    gst_buffer_unref (gst_harness_pull (h));
 
-  /* this is when buffer 0 deadline expires */
-  gst_test_clock_set_time_and_process (testclock, 200 * GST_MSECOND);
+  /* drop reconfigure event */
+  gst_event_unref (gst_harness_pull_upstream_event (h));
 
-  for (i = 0; i < 2; i++) {
-    GST_DEBUG ("popping %d", i);
-    out_buf = gst_harness_pull (h);
-    fail_unless_equals_int (i, get_rtp_seq_num (out_buf));
-    gst_buffer_unref (out_buf);
-  }
+  /*
+     The expected sequence of buffers is this:
+      ___   ___   ___   ___   ___
+     | 0 | | 1 | | 2 | | 3 | | 4 |
+      –––   –––   –––   –––   –––
+      0ms  20ms  40ms  60ms  80ms
 
-  /* this is when 2 is lost */
-  gst_test_clock_set_time_and_process (testclock, 240 * GST_MSECOND);
+     But instead we get this:
+      ___   ___   _ _   _ _   ___
+     | 0 | | 1 | |   | |   | | 4 |
+      –––   –––   – –   – –   –––
+      0ms  20ms              41ms
 
-  /* we should now receive a packet-lost-event for buffer 2 */
-  out_event = gst_harness_pull_event (h);
-  verify_lost_event (out_event, 2, 40 * GST_MSECOND, PCMU_BUF_DURATION);
+   */
 
-  /* verify that buffers made it through! */
-  for (i = 3; i < 15; i++) {
-    GST_DEBUG ("popping %d", i);
-    out_buf = gst_harness_pull (h);
-    fail_unless_equals_int (i, get_rtp_seq_num (out_buf));
-    gst_buffer_unref (out_buf);
-  }
-  /* should still have only seen 1 packet lost events,
-     so no events in the queue */
-  fail_unless_equals_int (0, gst_harness_events_in_queue (h));
+  now = 41 * GST_MSECOND;
+  gst_harness_set_time (h, now);
+  fail_unless_equals_int (GST_FLOW_OK,
+      gst_harness_push (h,
+          generate_test_buffer_full (now, TRUE, 4, 4 * PCMU_RTP_TS_DURATION)));
+
+  /*
+
+     With the now calculated packet-spacing of (41-20) / 3 = 7,
+     giving us these expected times:
+      ___   ___   ___   ___   ___
+     | 0 | | 1 | | 2 | | 3 | | 4 |
+      –––   –––   –––   –––   –––
+      0ms  20ms  27ms  34ms  41ms
+
+     For RTX, the inital RTX-timeouts for the missing buffers are
+     the expected arrival time + half the packet-spacing time, like this:
+      ___   ___
+     | 2 | | 3 |
+      –––   –––
+      50ms  70ms
+
+     But since we have re-calculated the estimated arrival-time
+     of these buffers, we have to adjust the RTX timeout as well,
+     and we use the original delay (packet-spacing / 2) = 10ms,
+     and add it on:
+      ___   ___
+     | 2 | | 3 |
+      –––   –––
+      37ms  44ms
+
+     Also note that the first RTX request is now scheduled for a
+     time that is prior to NOW (37ms < 41ms), so it will be sent straight
+     away without us needing to "crank" the timer-thread
 
-  fail_unless (verify_jb_stats (h->element,
-          gst_structure_new ("application/x-rtp-jitterbuffer-stats",
-              "num-lost", G_TYPE_UINT64, (guint64) 1,
-              "rtx-count", G_TYPE_UINT64, (guint64) 5,
-              "rtx-success-count", G_TYPE_UINT64, (guint64) 1,
-              "rtx-rtt", G_TYPE_UINT64, (guint64) 0, NULL)));
+   */
+
+  /* The RTX request for packet 2 has timestamp 27ms and delay 10ms */
+  verify_rtx_event (gst_harness_pull_upstream_event (h),
+      2, 27 * GST_MSECOND, 10, PCMU_BUF_DURATION);
+  /* and is sent immediately after packet 4 arrives (41ms) */
+  last_rtx_request = gst_clock_get_time (GST_CLOCK (testclock));
+  fail_unless_equals_int64 (last_rtx_request, now);
+
+  /* crank the timer thread */
+  gst_harness_crank_single_clock_wait (h);
+
+  /* The RTX request for packet 3 has timestamp 34ms and delay 10ms */
+  verify_rtx_event (gst_harness_pull_upstream_event (h),
+      3, 34 * GST_MSECOND, 10, PCMU_BUF_DURATION);
+  /* and is sent at 44ms */
+  last_rtx_request = gst_clock_get_time (GST_CLOCK (testclock));
+  fail_unless_equals_int64 (last_rtx_request, 44 * GST_MSECOND);
 
   gst_object_unref (testclock);
   gst_harness_teardown (h);
@@ -1178,12 +1256,12 @@ GST_START_TEST (test_rtx_packet_delay)
 
   /* we should now receive retransmission requests for 2 -> 5 */
   out_event = gst_harness_pull_upstream_event (h);
-  verify_rtx_event (out_event, 2, 20 * GST_MSECOND, 30, PCMU_BUF_DURATION);
+  verify_rtx_event (out_event, 2, 20 * GST_MSECOND, 17, PCMU_BUF_DURATION);
 
   for (i = 3; i < 5; i++) {
     GST_DEBUG ("popping %d", i);
     out_event = gst_harness_pull_upstream_event (h);
-    verify_rtx_event (out_event, i, 20 * GST_MSECOND, 0, PCMU_BUF_DURATION);
+    verify_rtx_event (out_event, i, 20 * GST_MSECOND, 17, PCMU_BUF_DURATION);
   }
   fail_unless_equals_int (0, gst_harness_upstream_events_in_queue (h));
 
@@ -1194,7 +1272,7 @@ GST_START_TEST (test_rtx_packet_delay)
 
   /* we should now receive retransmission requests for 5 */
   out_event = gst_harness_pull_upstream_event (h);
-  verify_rtx_event (out_event, 5, 20 * GST_MSECOND, 0, PCMU_BUF_DURATION);
+  verify_rtx_event (out_event, 5, 20 * GST_MSECOND, 17, PCMU_BUF_DURATION);
 
   /* wait for timeout for rtx 6 -> 7 */
   gst_test_clock_set_time_and_process (testclock, 60 * GST_MSECOND);
@@ -1202,7 +1280,7 @@ GST_START_TEST (test_rtx_packet_delay)
   for (i = 6; i < 8; i++) {
     GST_DEBUG ("popping %d", i);
     out_event = gst_harness_pull_upstream_event (h);
-    verify_rtx_event (out_event, i, 20 * GST_MSECOND, 0, PCMU_BUF_DURATION);
+    verify_rtx_event (out_event, i, 20 * GST_MSECOND, 17, PCMU_BUF_DURATION);
   }
 
   /* churn through 7 sync_times until the new buffer gets pushed out */
@@ -1218,9 +1296,6 @@ GST_START_TEST (test_rtx_packet_delay)
     gst_buffer_unref (out_buf);
   }
 
-  /* churn through 1 sync_time until the next buffer gets pushed out */
-  gst_harness_crank_single_clock_wait (h);
-
   for (i = 2; i < 8; i++) {
     GST_DEBUG ("popping lost event %d", i);
     out_event = gst_harness_pull_event (h);
@@ -1237,20 +1312,17 @@ GST_START_TEST (test_rtx_packet_delay)
     gst_buffer_unref (out_buf);
   }
 
-  GST_DEBUG ("waiting for 240ms");
-  gst_test_clock_set_time_and_process (testclock, 240 * GST_MSECOND);
-
   GST_DEBUG ("popping lost event 10");
   out_event = gst_harness_pull_event (h);
   verify_lost_event (out_event, 10, 40 * GST_MSECOND, PCMU_BUF_DURATION);
 
   fail_unless_equals_int (0, gst_harness_events_in_queue (h));
-  fail_unless_equals_int (20, gst_harness_upstream_events_in_queue (h));
+  fail_unless_equals_int (15, gst_harness_upstream_events_in_queue (h));
 
   fail_unless (verify_jb_stats (h->element,
           gst_structure_new ("application/x-rtp-jitterbuffer-stats",
               "num-lost", G_TYPE_UINT64, (guint64) 7,
-              "rtx-count", G_TYPE_UINT64, (guint64) 26,
+              "rtx-count", G_TYPE_UINT64, (guint64) 21,
               "rtx-success-count", G_TYPE_UINT64, (guint64) 0,
               "rtx-rtt", G_TYPE_UINT64, (guint64) 0, NULL)));
 
@@ -1534,10 +1606,10 @@ GST_START_TEST (test_rtx_duplicate_packet_updates_rtx_stats)
 
   gst_harness_crank_single_clock_wait (h);
   verify_rtx_event (gst_harness_pull_upstream_event (h),
-      7, 7 * PCMU_BUF_DURATION, 0, PCMU_BUF_DURATION);
+      7, 7 * PCMU_BUF_DURATION, rtx_delay_ms, PCMU_BUF_DURATION);
   rtx_request_7 = gst_clock_get_time (GST_CLOCK (testclock));
   fail_unless_equals_int64 (rtx_request_7,
-      7 * PCMU_BUF_DURATION);
+      7 * PCMU_BUF_DURATION + rtx_delay_ms * GST_MSECOND);
 
   /* Original packet 7 arrives */
   now = 150 * GST_MSECOND;
@@ -1737,11 +1809,12 @@ GST_START_TEST (test_rtx_rtt_larger_than_retry_timeout)
   /* Simulating RTT > rtx-retry-timeout, we send a new NACK before receiving
    * the RTX packet. Wait for second NACK on 6 */
   gst_harness_crank_single_clock_wait (h);
+  rtx_delay_ms += rtx_retry_timeout_ms;
   verify_rtx_event (gst_harness_pull_upstream_event (h),
       6, 6 * PCMU_BUF_DURATION, rtx_delay_ms, PCMU_BUF_DURATION);
   second_request = gst_clock_get_time (GST_CLOCK (testclock));
   fail_unless_equals_int64 (second_request,
-      6 * PCMU_BUF_DURATION + (rtx_delay_ms + rtx_retry_timeout_ms) * GST_MSECOND);
+      6 * PCMU_BUF_DURATION + rtx_delay_ms * GST_MSECOND);
 
   /* The first retransmitted packet arrives */
   now = first_request + rtt;
@@ -1860,9 +1933,9 @@ GST_START_TEST (test_gap_exceeds_latency)
 
   /* FIXME: something is up with the timestamp here!!?! */
   out_event = gst_harness_pull_upstream_event (h);
-  verify_rtx_event (out_event, 6, 119999994, 0, PCMU_BUF_DURATION);
+  verify_rtx_event (out_event, 6, 119999994, 10, PCMU_BUF_DURATION);
   /* lost more rtx with weird timestamps... */
-  for (i = 0; i < 13; i++) {
+  for (i = 0; i < 12; i++) {
     gst_event_unref (gst_harness_pull_upstream_event (h));
   }
 
@@ -1882,10 +1955,6 @@ GST_START_TEST (test_gap_exceeds_latency)
 
   /* FIXME: and these rtx... */
   gst_harness_crank_single_clock_wait (h);
-  out_event = gst_harness_pull_upstream_event (h);
-  verify_rtx_event (out_event, 7, 141428565, 120, PCMU_BUF_DURATION);
-
-  gst_harness_crank_single_clock_wait (h);
   out_event = gst_harness_pull_event (h);
   verify_lost_event (out_event, 6, 119999994, 21428571);
 
@@ -1926,7 +1995,7 @@ GST_START_TEST (test_gap_exceeds_latency)
           gst_structure_new ("application/x-rtp-jitterbuffer-stats",
               "num-pushed", G_TYPE_UINT64, (guint64) 11,
               "num-lost", G_TYPE_UINT64, (guint64) 7,
-              "rtx-count", G_TYPE_UINT64, (guint64) 21,
+              "rtx-count", G_TYPE_UINT64, (guint64) 19,
               "rtx-success-count", G_TYPE_UINT64, (guint64) 0,
               "rtx-rtt", G_TYPE_UINT64, (guint64) 0, NULL)));
 
@@ -2217,6 +2286,7 @@ rtpjitterbuffer_suite (void)
 
   tcase_add_test (tc_chain, test_rtx_expected_next);
   tcase_add_test (tc_chain, test_rtx_two_missing);
+  tcase_add_test (tc_chain, text_rtx_two_missing_early);
   tcase_add_test (tc_chain, test_rtx_packet_delay);
   tcase_add_test (tc_chain, test_rtx_buffer_arrives_just_in_time);
   tcase_add_test (tc_chain, test_rtx_buffer_arrives_too_late);