diff options
-rw-r--r-- | include/osmocom/netif/Makefile.am | 1 | ||||
-rw-r--r-- | include/osmocom/netif/jibuf.h | 63 | ||||
-rw-r--r-- | src/Makefile.am | 1 | ||||
-rw-r--r-- | src/jibuf.c | 381 | ||||
-rw-r--r-- | tests/Makefile.am | 8 | ||||
-rw-r--r-- | tests/jibuf/jibuf_test.c | 598 | ||||
-rw-r--r-- | tests/jibuf/jibuf_test.ok | 351 | ||||
-rw-r--r-- | tests/testsuite.at | 6 |
8 files changed, 1407 insertions, 2 deletions
diff --git a/include/osmocom/netif/Makefile.am b/include/osmocom/netif/Makefile.am index cbaff5c..0db78fb 100644 --- a/include/osmocom/netif/Makefile.am +++ b/include/osmocom/netif/Makefile.am @@ -3,6 +3,7 @@ SUBDIRS = channel osmonetif_HEADERS = amr.h \ channel.h \ datagram.h \ + jibuf.h \ osmux.h \ ipa.h \ ipa_unit.h \ diff --git a/include/osmocom/netif/jibuf.h b/include/osmocom/netif/jibuf.h new file mode 100644 index 0000000..6273983 --- /dev/null +++ b/include/osmocom/netif/jibuf.h @@ -0,0 +1,63 @@ +#pragma once + +#include <stdint.h> +#include <stdbool.h> +#include <time.h> + +#include <osmocom/core/timer.h> + +/*! \defgroup jibuf Osmocom Jitter Buffer + * @{ + */ + +/*! \file jibuf.h + * \brief Osmocom Jitter Buffer helpers + */ + +typedef void (*osmo_jibuf_dequeue_cb)(struct msgb *msg, void *data); + +/*! \brief A structure representing a single instance of a jitter buffer */ +struct osmo_jibuf { + void *talloc_ctx; + bool started; + struct osmo_timer_list timer; + struct llist_head msg_list; /* sorted by output ts */ + uint32_t min_delay; /* in msec */ + uint32_t max_delay; /* in msec */ + uint32_t threshold_delay; /* in msec */ + + osmo_jibuf_dequeue_cb dequeue_cb; + void *dequeue_cb_data; + + /* number of pkt drops since we last changed the buffer size */ + uint32_t last_dropped; + uint32_t consecutive_drops; + + uint32_t ref_rx_ts; + uint32_t ref_tx_ts; + uint16_t ref_tx_seq; + + struct timeval last_enqueue_time; + struct timeval next_dequeue_time; + + struct { + uint32_t total_enqueued; + uint64_t total_dropped; + } stats; +}; + + +struct osmo_jibuf *osmo_jibuf_alloc(void *talloc_ctx); + +void osmo_jibuf_delete(struct osmo_jibuf *jb); + +int osmo_jibuf_enqueue(struct osmo_jibuf *jb, struct msgb *msg); + +bool osmo_jibuf_empty(struct osmo_jibuf *jb); + +void osmo_jibuf_set_min_delay(struct osmo_jibuf *jb, uint32_t min_delay); +void osmo_jibuf_set_max_delay(struct osmo_jibuf *jb, uint32_t max_delay); + +void osmo_jibuf_set_dequeue_cb(struct osmo_jibuf *jb, osmo_jibuf_dequeue_cb dequeue_cb, void* cb_data); + +/*! @} */ diff --git a/src/Makefile.am b/src/Makefile.am index 81a55b4..79e3685 100644 --- a/src/Makefile.am +++ b/src/Makefile.am @@ -18,6 +18,7 @@ libosmonetif_la_SOURCES = amr.c \ datagram.c \ ipa.c \ ipa_unit.c \ + jibuf.c \ osmux.c \ rs232.c \ rtp.c \ diff --git a/src/jibuf.c b/src/jibuf.c new file mode 100644 index 0000000..c3d6bad --- /dev/null +++ b/src/jibuf.c @@ -0,0 +1,381 @@ +/* (C) 2017 by sysmocom - s.f.m.c. GmbH <info@sysmocom.de> + * + * Author: Pau Espin Pedrol <pespin@sysmocom.de> + * + * SPDX-License-Identifier: GPL-2.0+ + * + * This program is free software; you can redistribute it and/or modify + * it under the terms of the GNU General Public License as published by + * the Free Software Foundation; either version 2 of the License, or + * (at your option) any later version. + */ + +#include <stdio.h> +#include <string.h> +#include <inttypes.h> + +#include <osmocom/core/msgb.h> +#include <osmocom/core/timer.h> +#include <osmocom/core/talloc.h> +#include <osmocom/core/logging.h> +#include <osmocom/core/utils.h> + +#include <osmocom/netif/amr.h> +#include <osmocom/netif/rtp.h> +#include <osmocom/netif/jibuf.h> + +#include <arpa/inet.h> + +/*! \addtogroup jibuf Osmocom Jitter Buffer + * @{ + */ + +/*! \file jibuf.c + * \brief Osmocom Jitter Buffer helpers + */ + +/* Sampling rate (in Hz) */ +/* TODO: SAMPLE RATE can be guessed from rtp.p_type */ +#define SAMPLE_RATE 8000 + +/* TUNABLE PARAMETERS: */ + +/* default {min,max}_delay values if set_{min,max}_delay() is never called */ +#define JIBUF_DEFAULT_MIN_DELAY_MS 60 +#define JIBUF_DEFAULT_MAX_DELAY_MS 200 + +/* How frequently (num of input packets) do we reselect a new reference? */ +#define JIBUF_REFERENCE_TS_FREQ 60 + +/* How frequently (num of input packets) do we check if we should adapt the + * buffer size (threshold_delay) ? */ +#define JIBUF_BUFFER_RECALC_FREQ 40 +/* How many pkts should be dropped at max every JIBUF_BUFFER_RECALC_FREQ input + * pkts? */ +#define JIBUF_ALLOWED_PKT_DROP 3 +/* How many consecutive pkts can be dropped before triggering a buffer size incr ? */ +#define JIBUF_ALLOWED_PKT_CONSECUTIVE_DROP 1 +/* How much do we incr/decr the buffer size every time we recalculate it? */ +#define JIBUF_BUFFER_INC_STEP 20 +#define JIBUF_BUFFER_DEC_STEP 5 + +struct osmo_jibuf_msgb_cb { + struct timeval ts; + unsigned long *old_cb; +}; + +#define JIBUF_MSGB_CB(__msgb) ((struct osmo_jibuf_msgb_cb *)&((__msgb)->cb[0])) + +static void ms2timeval(struct timeval *ts, uint32_t ms) +{ + ts->tv_sec = ms / 1000; + ts->tv_usec = (ms % 1000) * 1000; +} + +static uint32_t timeval2ms(const struct timeval *ts) +{ + return ts->tv_sec * 1000 + ts->tv_usec / 1000; +} + +static int clock_gettime_timeval(clockid_t clk_id, struct timeval *tp) +{ + struct timespec now; + int n; + + n = osmo_clock_gettime(clk_id, &now); + tp->tv_sec = now.tv_sec; + tp->tv_usec = now.tv_nsec / 1000; + + return n; +} + +static struct timeval *msgb_scheduled_ts(const struct msgb *msg) +{ + struct osmo_jibuf_msgb_cb *jbcb = JIBUF_MSGB_CB(msg); + return &jbcb->ts; +} + +/* Add msgb to the list sorted by its scheduled output ts */ +static void llist_add_sorted(struct msgb *msg, struct llist_head *msg_list) +{ + struct msgb *cur; + struct timeval *msg_ts = msgb_scheduled_ts(msg); + + /* TODO: not sure if I need to use _safe here */ + llist_for_each_entry(cur, msg_list, list) { + struct timeval *cur_ts = msgb_scheduled_ts(cur); + if (timercmp(msg_ts, cur_ts, <)) { + __llist_add(&msg->list, cur->list.prev, &cur->list); + return; + } + } + + /* we reached the end, add to the tail: */ + llist_add_tail(&msg->list, msg_list); + +} + +static uint16_t msg_get_sequence(struct msgb *msg) +{ + struct rtp_hdr *rtph = osmo_rtp_get_hdr(msg); + return ntohs(rtph->sequence); +} + +static uint32_t msg_get_timestamp(struct msgb *msg) +{ + struct rtp_hdr *rtph = osmo_rtp_get_hdr(msg); + return ntohl(rtph->timestamp); +} + +static int32_t samples2ms(int32_t samples) +{ + /* XXX: SAMPLE RATE can be guessed from rtp.p_type */ + return samples * 1000 / SAMPLE_RATE; +} + +/* Calculates pkt delay related to reference pkt. Similar concept to D(i,j) as + * defined in RFC3550 (RTP). */ +static int calc_pkt_rel_delay(struct osmo_jibuf *jb, struct msgb *msg) +{ + uint32_t current_rx_ts = timeval2ms(&jb->last_enqueue_time); + uint32_t current_tx_ts = msg_get_timestamp(msg); + + return samples2ms((current_tx_ts - jb->ref_tx_ts)) - (current_rx_ts - jb->ref_rx_ts); +} + +static void msg_set_as_reference(struct osmo_jibuf *jb, struct msgb *msg) +{ + jb->ref_rx_ts = timeval2ms(&jb->last_enqueue_time); + jb->ref_tx_ts = msg_get_timestamp(msg); + jb->ref_tx_seq = msg_get_sequence(msg); + + LOGP(DLJIBUF, LOGL_DEBUG, "New reference (seq=%"PRIu16" rx=%"PRIu32 \ + " tx=%"PRIu32")\n", jb->ref_tx_seq, jb->ref_rx_ts, jb->ref_tx_ts); +} + +static void dequeue_msg(struct osmo_jibuf *jb, struct msgb *msg) +{ + unsigned long *old_cb = JIBUF_MSGB_CB(msg)->old_cb; + memcpy(msg->cb, old_cb, sizeof(msg->cb)); + talloc_free(old_cb); + llist_del(&msg->list); + + jb->dequeue_cb(msg, jb->dequeue_cb_data); +} + +static void timer_expired(void *data) +{ + struct osmo_jibuf *jb = (struct osmo_jibuf*) data; + struct timeval delay_ts, now; + struct msgb *msg, *next; + + llist_for_each_entry_safe(msg, next, &jb->msg_list, list) { + struct timeval *msg_ts = msgb_scheduled_ts(msg); + clock_gettime_timeval(CLOCK_MONOTONIC, &now); + if (timercmp(msg_ts, &now, >)) { + jb->next_dequeue_time = *msg_ts; + timersub(msg_ts, &now, &delay_ts); + osmo_timer_schedule(&jb->timer, + delay_ts.tv_sec, delay_ts.tv_usec); + return; + } + + dequeue_msg(jb, msg); + } + + /* XXX: maybe try to tune the threshold based on the calculated output jitter? */ + /* XXX: try to find holes in the list and create fake pkts to improve the + jitter when packets do not arrive on time */ +} + +static void recalc_threshold_delay(struct osmo_jibuf *jb) +{ + + /* Recalculate every JIBUF_RECALC_FREQ_PKTS handled packets, or if we have too + many consecutive drops */ + uint32_t sum_pkts = jb->stats.total_enqueued + jb->stats.total_dropped + + jb->last_dropped; + + if (jb->consecutive_drops <= JIBUF_ALLOWED_PKT_CONSECUTIVE_DROP && + sum_pkts % JIBUF_BUFFER_RECALC_FREQ != 0) + return; + + if (jb->consecutive_drops > JIBUF_ALLOWED_PKT_CONSECUTIVE_DROP || + jb->last_dropped > JIBUF_ALLOWED_PKT_DROP) + jb->threshold_delay = OSMO_MIN( + jb->threshold_delay + JIBUF_BUFFER_INC_STEP, + jb->max_delay); + else + jb->threshold_delay = OSMO_MAX( + jb->threshold_delay - JIBUF_BUFFER_DEC_STEP, + jb->min_delay); + LOGP(DLJIBUF, LOGL_DEBUG, "New threshold: %u ms (freq=%d dropped=%d/%d consecutive=%d/%d)\n", + jb->threshold_delay, JIBUF_BUFFER_RECALC_FREQ, + jb->last_dropped, JIBUF_ALLOWED_PKT_DROP, + jb->consecutive_drops, JIBUF_ALLOWED_PKT_CONSECUTIVE_DROP); + + jb->stats.total_dropped += jb->last_dropped; + jb->last_dropped = 0; + +} + +//---------------------------------- + +/*! \brief Allocate a new jitter buffer instance + * \return the new allocated instance + */ +struct osmo_jibuf *osmo_jibuf_alloc(void *talloc_ctx) +{ + struct osmo_jibuf *jb; + jb = talloc_zero(talloc_ctx, struct osmo_jibuf); + + jb->min_delay = JIBUF_DEFAULT_MIN_DELAY_MS; + jb->max_delay = JIBUF_DEFAULT_MAX_DELAY_MS; + jb->threshold_delay = jb->min_delay; + + INIT_LLIST_HEAD(&jb->msg_list); + + jb->timer.cb = timer_expired; + jb->timer.data = jb; + + return jb; +} + +/*! \brief Destroy a previously allocated jitter buffer instance + * \param[in] jb Previously allocated (non-null) jitter buffer instance + * + * All the queued packets are dequeued before deleting the instance. + */ +void osmo_jibuf_delete(struct osmo_jibuf *jb) +{ + struct msgb *msg, *tmp; + osmo_timer_del(&jb->timer); + llist_for_each_entry_safe(msg, tmp, &jb->msg_list, list) + dequeue_msg(jb, msg); + + talloc_free(jb); +} + +/*! \brief Try to enqueue a packet into the jitter buffer + * \param[in] jb jitter buffer instance + * \param[in] msg msgb to enqueue, containing an RTP packet + * \return <0 if the packet was dropped, 0 otherwise + * + * This function calculates the delay for the enqueued packet. If the delay is + * bigger than the current buffer size, the function returns -1 and the caller + * owns the packet again and can free it if required. If the packet is enqueued, + * 0 is returned and the exact same packet (ownership transfer, no copy is made) + * will be available again through the dequeue_cb() when the queue timer for + * this packet expires. + */ +int osmo_jibuf_enqueue(struct osmo_jibuf *jb, struct msgb *msg) +{ + int rel_delay, delay; + struct timeval delay_ts, sched_ts; + + clock_gettime_timeval(CLOCK_MONOTONIC, &jb->last_enqueue_time); + + if (!jb->started) { + jb->started = true; + msg_set_as_reference(jb, msg); + rel_delay = 0; + } else { + rel_delay = calc_pkt_rel_delay(jb, msg); + } + + /* Avoid time skew with sender (or drop-everything state), + reselect a new reference from time to time */ + //if ((int)(msg_get_sequence(msg) - jb->ref_tx_seq) > JIBUF_REFERENCE_TS_FREQ) + // msg_set_as_reference(jb, msg); + + delay = jb->threshold_delay + rel_delay; + + /* packet too late, let's drop it and incr buffer size if encouraged */ + if (delay < 0) { + jb->last_dropped++; + jb->consecutive_drops++; + + LOGP(DLJIBUF, LOGL_DEBUG, "dropped %u > %u (seq=%"PRIu16" ts=%"PRIu32")\n", + rel_delay, jb->threshold_delay, msg_get_sequence(msg), + msg_get_timestamp(msg)); + + recalc_threshold_delay(jb); + return -1; + } else { + jb->consecutive_drops = 0; + jb->stats.total_enqueued++; + } + + ms2timeval(&delay_ts, (uint32_t) delay); + timeradd(&jb->last_enqueue_time, &delay_ts, &sched_ts); + + LOGP(DLJIBUF, LOGL_DEBUG, "enqueuing packet seq=%"PRIu16" rel=%d delay=%d" \ + " thres=%d {%lu.%06lu -> %lu.%06lu}\n", + msg_get_sequence(msg), rel_delay, delay, jb->threshold_delay, + jb->last_enqueue_time.tv_sec, jb->last_enqueue_time.tv_usec, + sched_ts.tv_sec, sched_ts.tv_usec); + + /* Add scheduled dequeue time in msg->cb so we can check it later */ + unsigned long *old_cb = talloc_memdup(jb->talloc_ctx, msg->cb, sizeof(msg->cb)); + struct osmo_jibuf_msgb_cb *jbcb = JIBUF_MSGB_CB(msg); + jbcb->ts = sched_ts; + jbcb->old_cb = old_cb; + + llist_add_sorted(msg, &jb->msg_list); + + + /* See if updating the timer is needed: */ + if (!osmo_timer_pending(&jb->timer) || + timercmp(&sched_ts, &jb->next_dequeue_time, <)) { + jb->next_dequeue_time = sched_ts; + osmo_timer_schedule(&jb->timer, 0, delay * 1000); + } + + /* Let's check packet loss stats to see if buffer_size must be changed */ + recalc_threshold_delay(jb); + + return 0; +} + +/*! \brief Check whether the jitter buffer instance has packets queued or not. + * \param[in] jb jitter buffer instance + * \return true if the queue is empty, false otherwise. + */ +bool osmo_jibuf_empty(struct osmo_jibuf *jb) +{ + return llist_empty(&jb->msg_list); +} + +/*! \brief Set minimum buffer size for the jitter buffer + * \param[in] jb jitter buffer instance + * \param[in] min_delay Minimum buffer size, as in minimum delay in milliseconds + */ +void osmo_jibuf_set_min_delay(struct osmo_jibuf *jb, uint32_t min_delay) +{ + jb->min_delay = min_delay ? min_delay : JIBUF_DEFAULT_MIN_DELAY_MS; + jb->threshold_delay = OSMO_MAX(jb->min_delay, jb->threshold_delay); +} + +/*! \brief Set maximum buffer size for the jitter buffer + * \param[in] jb jitter buffer instance + * \param[in] max_delay Maximum buffer size, as in maximum delay in milliseconds + */ +void osmo_jibuf_set_max_delay(struct osmo_jibuf *jb, uint32_t max_delay) +{ + jb->max_delay = max_delay ? max_delay : JIBUF_DEFAULT_MAX_DELAY_MS; + jb->threshold_delay = OSMO_MIN(jb->max_delay, jb->threshold_delay); +} + +/*! \brief Set dequeue callback for the jitter buffer + * \param[in] jb jitter buffer instance + * \param[in] dequeue_cb function pointer to call back when the dequeue timer for a given packet expires + * \param[in] cb_data data pointer to be passed to dequeue_cb together with the msgb. + */ +void osmo_jibuf_set_dequeue_cb(struct osmo_jibuf *jb, osmo_jibuf_dequeue_cb + dequeue_cb, void* cb_data) +{ + jb->dequeue_cb = dequeue_cb; + jb->dequeue_cb_data = cb_data; +} + +/*! @} */ diff --git a/tests/Makefile.am b/tests/Makefile.am index f99e276..bf1db1f 100644 --- a/tests/Makefile.am +++ b/tests/Makefile.am @@ -1,11 +1,14 @@ AM_CFLAGS = -Wall -I$(top_srcdir)/include $(LIBOSMOCORE_CFLAGS) -g AM_LDFLAGS = $(LIBOSMOCORE_LDFLAGS) -check_PROGRAMS = osmux/osmux_test +check_PROGRAMS = osmux/osmux_test jibuf/jibuf_test osmux_osmux_test_SOURCES = osmux/osmux_test.c osmux_osmux_test_LDADD = $(LIBOSMOCORE_LIBS) $(top_builddir)/src/libosmonetif.la +jibuf_jibuf_test_SOURCES = jibuf/jibuf_test.c +jibuf_jibuf_test_LDADD = $(LIBOSMOCORE_LIBS) $(top_builddir)/src/libosmonetif.la + # The `:;' works around a Bash 3.2 bug when the output is not writeable. $(srcdir)/package.m4: $(top_srcdir)/configure.ac :;{ \ @@ -25,7 +28,8 @@ $(srcdir)/package.m4: $(top_srcdir)/configure.ac } >'$(srcdir)/package.m4' EXTRA_DIST = testsuite.at $(srcdir)/package.m4 $(TESTSUITE) \ - osmux/osmux_test.ok + osmux/osmux_test.ok \ + jibuf/jibuf_test.ok DISTCLEANFILES = atconfig diff --git a/tests/jibuf/jibuf_test.c b/tests/jibuf/jibuf_test.c new file mode 100644 index 0000000..ba21906 --- /dev/null +++ b/tests/jibuf/jibuf_test.c @@ -0,0 +1,598 @@ +/* (C) 2017 by sysmocom - s.f.m.c. GmbH <info@sysmocom.de> + * + * Author: Pau Espin Pedrol <pespin@sysmocom.de> + * + * SPDX-License-Identifier: GPL-2.0+ + * + * This program is free software; you can redistribute it and/or modify + * it under the terms of the GNU General Public License as published by + * the Free Software Foundation; either version 2 of the License, or + * (at your option) any later version. + */ + +#include <stdio.h> +#include <stdlib.h> +#include <stdbool.h> +#include <unistd.h> +#include <stdint.h> +#include <inttypes.h> +#include <string.h> +#include <signal.h> +#include <arpa/inet.h> +#include <sys/time.h> +#include <getopt.h> + +#include <osmocom/core/select.h> +#include <osmocom/core/application.h> +#include <osmocom/core/logging.h> +#include <osmocom/core/msgb.h> +#include <osmocom/netif/jibuf.h> +#include <osmocom/netif/rtp.h> + +static struct osmo_jibuf *jb; + +static uint16_t rtp_next_seq; +static uint32_t rtp_next_ts; + +#define SAMPLES_PER_PKT 160 +#define TIME_RTP_PKT_MS 20 +/* RTP packet with AMR payload */ +static uint8_t rtp_pkt[] = { + 0x80, 0x62, 0x3f, 0xcc, 0x00, 0x01, 0xa7, 0x6f, /* RTP */ + 0x07, 0x09, 0x00, 0x62, 0x20, 0x14, 0xff, 0xd4, /* AMR */ + 0xf9, 0xff, 0xfb, 0xe7, 0xeb, 0xf9, 0x9f, 0xf8, + 0xf2, 0x26, 0x33, 0x65, 0x54, +}; + +/* ----------------------------- */ + +/* Logging related stuff */ +#define INT2IDX(x) (-1*(x)-1) +struct log_info_cat jibuf_test_cat[] = { + [INT2IDX(DLJIBUF)] = { + .name = "DLJIBUF", + .description = "Osmocom Jitter Buffer", + .enabled = 1, .loglevel = LOGL_DEBUG, + }, +}; +const struct log_info jibuf_test_log_info = { + .filter_fn = NULL, + .cat = jibuf_test_cat, + .num_cat = ARRAY_SIZE(jibuf_test_cat), +}; +/* ----------------------------- */ + +static void rtp_init(uint16_t seq, uint32_t timestamp) +{ + rtp_next_seq = seq; + rtp_next_ts = timestamp; +} + +static struct msgb *rtp_new(uint16_t seq, uint32_t timestamp) +{ + struct msgb *msg; + struct rtp_hdr *rtph; + + msg = msgb_alloc(1500, "test"); + if (!msg) + exit(EXIT_FAILURE); + memcpy(msg->data, rtp_pkt, sizeof(rtp_pkt)); + msgb_put(msg, sizeof(rtp_pkt)); + + rtph = osmo_rtp_get_hdr(msg); + rtph->sequence = htons(rtp_next_seq); + rtph->timestamp = htonl(rtp_next_ts); + return msg; +} + +static struct msgb *rtp_next(void) +{ + rtp_next_seq++; + rtp_next_ts += SAMPLES_PER_PKT; + return rtp_new(rtp_next_seq, rtp_next_ts); +} + +static void sigalarm_handler(int foo) +{ + printf("FAIL: test did not run successfully\n"); + exit(EXIT_FAILURE); +} + + +static void clock_debug(char* str) +{ + struct timespec ts; + struct timeval tv; + osmo_clock_gettime(CLOCK_MONOTONIC, &ts); + osmo_gettimeofday(&tv, NULL); + printf("sys={%lu.%06lu}, mono={%lu.%06lu}: %s\n", + tv.tv_sec, tv.tv_usec, ts.tv_sec, ts.tv_nsec/1000, str); +} + +static void clock_override_enable(bool enable) +{ + osmo_gettimeofday_override = enable; + osmo_clock_override_enable(CLOCK_MONOTONIC, enable); +} + +static void clock_override_set(long sec, long usec) +{ + struct timespec *mono; + osmo_gettimeofday_override_time.tv_sec = sec; + osmo_gettimeofday_override_time.tv_usec = usec; + mono = osmo_clock_override_gettimespec(CLOCK_MONOTONIC); + mono->tv_sec = sec; + mono->tv_nsec = usec*1000; + + clock_debug("clock_override_set"); +} + +static void clock_override_add(long sec, long usec) +{ + osmo_gettimeofday_override_add(sec, usec); + osmo_clock_override_add(CLOCK_MONOTONIC, sec, usec*1000); + clock_debug("clock_override_add"); +} + + +static void dequeue_cb(struct msgb *msg, void *data) +{ + struct rtp_hdr *rtph; + bool check_latest; + char buf[250]; + rtph = osmo_rtp_get_hdr(msg); + check_latest = rtph->sequence == htons(rtp_next_seq) && rtph->timestamp == htonl(rtp_next_ts); + snprintf(buf, sizeof(buf), "dequeue: seq=%"PRIu16" ts=%"PRIu32" %s", + ntohs(rtph->sequence), ntohl(rtph->timestamp), check_latest ? "LATEST" : "INTERMEDIATE"); + clock_debug(buf); + msgb_free(msg); +} + +#define ENQUEUE_NEXT(jb) { \ + struct msgb *_msg; \ + int _rc; \ + _msg = rtp_next(); \ + _rc = osmo_jibuf_enqueue(jb, _msg); \ + OSMO_ASSERT(!_rc); \ + } + +static void test_normal(void) +{ + int min_delay = 60; + + printf("===test_normal===\n"); + + clock_override_enable(true); + clock_override_set(0, 0); + rtp_init(32, 400); + jb = osmo_jibuf_alloc(NULL); + osmo_jibuf_set_dequeue_cb(jb, dequeue_cb, NULL); + osmo_jibuf_set_min_delay(jb, min_delay); + osmo_jibuf_set_max_delay(jb, 200); + + /* First rtp at t=0, should be scheduled in min_delay time */ + ENQUEUE_NEXT(jb); + clock_override_add(0, min_delay*1000); + clock_debug("first select, first dequed"); + osmo_select_main(0); + + /* We are at t=60, if we add a new packet and wait for 20msecs (next packet), we should show it dequeued*/ + ENQUEUE_NEXT(jb); + clock_override_add(0, TIME_RTP_PKT_MS*1000); + clock_debug("second select, one packet should be dequeued"); + osmo_select_main(0); + + /* We are at t=80, and only 2 packets were introduced. Let's add 2 more, should be dequeued by 80+40: */ + ENQUEUE_NEXT(jb); + ENQUEUE_NEXT(jb); + clock_override_add(0, TIME_RTP_PKT_MS*2*1000); + clock_debug("third select, two more dequed"); + osmo_select_main(0); + + /* t=120, 4 enqueued, 4 dequeued.*/ + OSMO_ASSERT(osmo_jibuf_empty(jb)); + + osmo_jibuf_delete(jb); +} + +static void test_delete_nonempty(void) +{ + int min_delay = 100; + + printf("===test_delete_nonempty===\n"); + + clock_override_enable(true); + clock_override_set(0, 0); + rtp_init(32, 400); + jb = osmo_jibuf_alloc(NULL); + osmo_jibuf_set_dequeue_cb(jb, dequeue_cb, NULL); + osmo_jibuf_set_min_delay(jb, min_delay); + osmo_jibuf_set_max_delay(jb, 200); + + ENQUEUE_NEXT(jb); + clock_override_add(0, TIME_RTP_PKT_MS*1000); + ENQUEUE_NEXT(jb); + clock_override_add(0, TIME_RTP_PKT_MS*1000); + ENQUEUE_NEXT(jb); + clock_override_add(0, TIME_RTP_PKT_MS*1000); + ENQUEUE_NEXT(jb); + + /* No need to update the time, all msgs should be dequeued at this time */ + OSMO_ASSERT(!osmo_jibuf_empty(jb)); + osmo_jibuf_delete(jb); +} + +static void test_packet_lost(void) +{ + int min_delay = 60; + + printf("===test_packet_lost===\n"); + + clock_override_enable(true); + clock_override_set(0, 0); + rtp_init(32, 400); + jb = osmo_jibuf_alloc(NULL); + osmo_jibuf_set_dequeue_cb(jb, dequeue_cb, NULL); + osmo_jibuf_set_min_delay(jb, min_delay); + osmo_jibuf_set_max_delay(jb, 200); + + /* First rtp at t=0, should be scheduled in min_delay time */ + clock_debug("enqueue 1st packet"); + ENQUEUE_NEXT(jb); + clock_override_add(0, TIME_RTP_PKT_MS*1000); + + clock_debug("packet lost: 2nd"); + clock_override_add(0, TIME_RTP_PKT_MS*1000); + clock_debug("packet lost: 3rd"); + clock_override_add(0, TIME_RTP_PKT_MS*1000); + clock_debug("packet lost: 4th"); + clock_override_add(0, TIME_RTP_PKT_MS*1000); + + /* We are at t=80 */ + clock_debug("enqueue 5th packet"); + ENQUEUE_NEXT(jb); + clock_override_add(0, min_delay*1000); + + /* We are at t=140, all out in order */ + osmo_select_main(0); + + OSMO_ASSERT(osmo_jibuf_empty(jb)); + + osmo_jibuf_delete(jb); +} + + +static void test_packet_drop(void) +{ + int min_delay = 60; + struct msgb *msg; + + printf("===test_packet_drop===\n"); + + clock_override_enable(true); + clock_override_set(0, 0); + rtp_init(32, 400); + jb = osmo_jibuf_alloc(NULL); + osmo_jibuf_set_dequeue_cb(jb, dequeue_cb, NULL); + osmo_jibuf_set_min_delay(jb, min_delay); + osmo_jibuf_set_max_delay(jb, 200); + + /* First rtp at t=0, should be scheduled in min_delay time */ + clock_debug("enqueue 1st packet"); + ENQUEUE_NEXT(jb); + clock_override_add(0, TIME_RTP_PKT_MS*1000); + clock_debug("enqueue 2nd packet"); + ENQUEUE_NEXT(jb); + clock_override_add(0, TIME_RTP_PKT_MS*1000); + clock_debug("enqueue 3rd packet"); + ENQUEUE_NEXT(jb); + clock_override_add(0, TIME_RTP_PKT_MS*1000); + clock_debug("enqueue 4th packet"); + ENQUEUE_NEXT(jb); + + /* We are at t=60, first comes out */ + osmo_select_main(0); + + /* We move to t=160, next packet in stream is too late:*/ + clock_override_add(0, 100*1000); + clock_debug("next packet should be dropped, too late"); + msg = rtp_next(); + OSMO_ASSERT(osmo_jibuf_enqueue(jb, msg) < 0); + msgb_free(msg); + + /* However, if we try to add a later one, it should work: */ + clock_debug("next packet should be enqueued"); + ENQUEUE_NEXT(jb); + + /* We are at t=160, all of them should be dequeued */ + osmo_select_main(0); + + /* t=160, 4 enqueued, 4 dequeued.*/ + OSMO_ASSERT(osmo_jibuf_empty(jb)); + + osmo_jibuf_delete(jb); +} + +static void test_packet_out_of_order(void) +{ + int min_delay = 60; + struct msgb *msg2, *msg3; + + printf("===test_packet_out_of_order===\n"); + + clock_override_enable(true); + clock_override_set(0, 0); + rtp_init(32, 400); + jb = osmo_jibuf_alloc(NULL); + osmo_jibuf_set_dequeue_cb(jb, dequeue_cb, NULL); + osmo_jibuf_set_min_delay(jb, min_delay); + osmo_jibuf_set_max_delay(jb, 200); + + /* First rtp at t=0, should be scheduled in min_delay time */ + clock_debug("enqueue 1st packet"); + ENQUEUE_NEXT(jb); + + /* 3rd packet arrives instead of 2nd one */ + msg2 = rtp_next(); + msg3 = rtp_next(); + clock_override_add(0, TIME_RTP_PKT_MS*2*1000); + clock_debug("enqueue 3rd packet"); + OSMO_ASSERT(osmo_jibuf_enqueue(jb, msg3) == 0); + clock_debug("enqueue 2nd packet"); + OSMO_ASSERT(osmo_jibuf_enqueue(jb, msg2) == 0); + + /* We are at t=100, all out in order */ + clock_override_add(0, min_delay*1000); + osmo_select_main(0); + + OSMO_ASSERT(osmo_jibuf_empty(jb)); + + osmo_jibuf_delete(jb); +} + +static void test_start_2nd_packet(void) +{ + int min_delay = 60; + struct msgb *msg1; + + printf("===test_start_2nd_packet===\n"); + + clock_override_enable(true); + clock_override_set(0, 0); + rtp_init(32, 400); + jb = osmo_jibuf_alloc(NULL); + osmo_jibuf_set_dequeue_cb(jb, dequeue_cb, NULL); + osmo_jibuf_set_min_delay(jb, min_delay); + osmo_jibuf_set_max_delay(jb, 200); + + /* First rtp at t=0, should be scheduled in min_delay time */ + clock_debug("1st packet is not yet enqueued"); + msg1 = rtp_next(); + clock_override_add(0, TIME_RTP_PKT_MS*2*1000); + + /* 2nd packet arrives instead of 2nd one */ + clock_debug("2nd packet is enqueuded as first"); + ENQUEUE_NEXT(jb); + + clock_debug("1st packet is enqueuded as second, should be enqueued with preference"); + OSMO_ASSERT(osmo_jibuf_enqueue(jb, msg1) == 0); + + /* 1st packet is dequeued */ + clock_override_add(0, (min_delay-TIME_RTP_PKT_MS)*1000); + osmo_select_main(0); + + /* 2nst packet is dequeued */ + clock_override_add(0, TIME_RTP_PKT_MS*1000); + osmo_select_main(0); + + OSMO_ASSERT(osmo_jibuf_empty(jb)); + + osmo_jibuf_delete(jb); +} + +static void test_buffer_threshold_change(void) +{ + int min_delay = 60; + struct msgb *msg; + uint32_t threshold_delay; + int i; + + printf("===test_buffer_threshold_change===\n"); + + clock_override_enable(true); + clock_override_set(0, 0); + rtp_init(32, 400); + jb = osmo_jibuf_alloc(NULL); + osmo_jibuf_set_dequeue_cb(jb, dequeue_cb, NULL); + osmo_jibuf_set_min_delay(jb, min_delay); + osmo_jibuf_set_max_delay(jb, 200); + + OSMO_ASSERT(min_delay == jb->threshold_delay); + threshold_delay = jb->threshold_delay; + + /* First rtp at t=0, should be scheduled in min_delay time */ + clock_debug("enqueue 1st packet"); + ENQUEUE_NEXT(jb); + clock_override_add(0, TIME_RTP_PKT_MS*1000); + clock_debug("enqueue 2nd packet"); + ENQUEUE_NEXT(jb); + clock_override_add(0, TIME_RTP_PKT_MS*1000); + clock_debug("enqueue 3rd packet"); + ENQUEUE_NEXT(jb); + clock_override_add(0, TIME_RTP_PKT_MS*1000); + clock_debug("enqueue 4th packet"); + ENQUEUE_NEXT(jb); + + /* We are at t=60, first comes out */ + osmo_select_main(0); + + /* We move to t=160, next packet in stream is too late:*/ + clock_override_add(0, 100*1000); + clock_debug("next packet should be dropped, too late"); + msg = rtp_next(); + OSMO_ASSERT(osmo_jibuf_enqueue(jb, msg) < 0); + msgb_free(msg); + + clock_override_add(0, TIME_RTP_PKT_MS*1000); + clock_debug("next packet is dropped, but buffer is increased"); + msg = rtp_next(); + OSMO_ASSERT(osmo_jibuf_enqueue(jb, msg) < 0); + msgb_free(msg); + OSMO_ASSERT(jb->threshold_delay > threshold_delay); + threshold_delay = jb->threshold_delay; + + clock_override_add(0, TIME_RTP_PKT_MS*1000); + clock_debug("next packet is enqueued since the buffer increased"); + ENQUEUE_NEXT(jb); + + /* As the last buffer was really late but still accepted, it is not delayed: */ + osmo_select_main(0); + + clock_debug("Enqueue late packets"); + for (i = 0; i<4; i++) { + ENQUEUE_NEXT(jb); + } + + clock_debug("Run perfectly for a while, buffer should decrease"); + for (i = 0; i<100; i++) { + clock_override_add(0, TIME_RTP_PKT_MS*1000); + ENQUEUE_NEXT(jb); + osmo_select_main(0); + } + clock_debug("Done, checking threshold and cleaning"); + OSMO_ASSERT(jb->threshold_delay < threshold_delay); + clock_override_add(0, jb->threshold_delay*1000); + osmo_select_main(0); + + OSMO_ASSERT(osmo_jibuf_empty(jb)); + + osmo_jibuf_delete(jb); +} + +static void test_seq_wraparound(void) +{ + int min_delay = 80; + + printf("===test_seq_wraparound===\n"); + + clock_override_enable(true); + clock_override_set(0, 0); + rtp_init(65533, 400); /* seq = 2^16 -3 */ + jb = osmo_jibuf_alloc(NULL); + osmo_jibuf_set_dequeue_cb(jb, dequeue_cb, NULL); + osmo_jibuf_set_min_delay(jb, min_delay); + osmo_jibuf_set_max_delay(jb, 200); + + clock_debug("enqueue 1st packet (seq=65534)"); + ENQUEUE_NEXT(jb); + clock_override_add(0, TIME_RTP_PKT_MS*1000); + clock_debug("enqueue 2nd packet (seq=65535)"); + ENQUEUE_NEXT(jb); + clock_override_add(0, TIME_RTP_PKT_MS*1000); + clock_debug("enqueue 3rd packet (seq=0, wraparound)"); + ENQUEUE_NEXT(jb); + clock_override_add(0, TIME_RTP_PKT_MS*1000); + clock_debug("enqueue 4th packet (seq=1)"); + ENQUEUE_NEXT(jb); + clock_override_add(0, TIME_RTP_PKT_MS*1000); + clock_debug("enqueue 5th packet (seq=2)"); + ENQUEUE_NEXT(jb); + + clock_debug("dequeue 1st packet (seq=65534)"); + osmo_select_main(0); + clock_override_add(0, TIME_RTP_PKT_MS*1000); + clock_debug("dequeue 2nd packet (seq=65535)"); + osmo_select_main(0); + clock_override_add(0, TIME_RTP_PKT_MS*1000); + clock_debug("dequeue 3rd packet (seq=0, wraparound)"); + osmo_select_main(0); + clock_override_add(0, TIME_RTP_PKT_MS*1000); + clock_debug("dequeue 4th packet (seq=1)"); + osmo_select_main(0); + clock_override_add(0, TIME_RTP_PKT_MS*1000); + clock_debug("dequeue 5th packet (seq=2)"); + osmo_select_main(0); + + OSMO_ASSERT(osmo_jibuf_empty(jb)); + + osmo_jibuf_delete(jb); +} + +static void test_timestamp_wraparound(void) +{ + int min_delay = 80; + unsigned int offset = 14; + + printf("===test_timestamp_wraparound===\n"); + + clock_override_enable(true); + clock_override_set(0, 0); + rtp_init(32, 4294966816 + offset); /* timestamp = 2^32 - 3*SAMPLES_PER_PKT + offset */ + jb = osmo_jibuf_alloc(NULL); + osmo_jibuf_set_dequeue_cb(jb, dequeue_cb, NULL); + osmo_jibuf_set_min_delay(jb, min_delay); + osmo_jibuf_set_max_delay(jb, 200); + + clock_debug("enqueue 1st packet (ts=4294966990)"); + ENQUEUE_NEXT(jb); + clock_override_add(0, TIME_RTP_PKT_MS*1000); + clock_debug("enqueue 2nd packet (ts=4294967150)"); + ENQUEUE_NEXT(jb); + clock_override_add(0, TIME_RTP_PKT_MS*1000); + clock_debug("enqueue 3rd packet (ts=14, wraparound)"); + ENQUEUE_NEXT(jb); + clock_override_add(0, TIME_RTP_PKT_MS*1000); + clock_debug("enqueue 4th packet (ts=174)"); + ENQUEUE_NEXT(jb); + clock_override_add(0, TIME_RTP_PKT_MS*1000); + clock_debug("enqueue 5th packet (ts=334)"); + ENQUEUE_NEXT(jb); + + clock_debug("dequeue 1st packet (ts=4294966990)"); + osmo_select_main(0); + clock_override_add(0, TIME_RTP_PKT_MS*1000); + clock_debug("dequeue 2nd packet (ts=4294967150)"); + osmo_select_main(0); + clock_override_add(0, TIME_RTP_PKT_MS*1000); + clock_debug("dequeue 3rd packet (ts=14, wraparound)"); + osmo_select_main(0); + clock_override_add(0, TIME_RTP_PKT_MS*1000); + clock_debug("dequeue 4th packet (ts=174)"); + osmo_select_main(0); + clock_override_add(0, TIME_RTP_PKT_MS*1000); + clock_debug("dequeue 5th packet (ts=334)"); + osmo_select_main(0); + + OSMO_ASSERT(osmo_jibuf_empty(jb)); + + osmo_jibuf_delete(jb); +} + +int main(int argc, char **argv) +{ + + if (signal(SIGALRM, sigalarm_handler) == SIG_ERR) { + perror("signal"); + exit(EXIT_FAILURE); + } + + osmo_init_logging(&jibuf_test_log_info); + log_set_print_filename(osmo_stderr_target, 0); + log_set_log_level(osmo_stderr_target, LOGL_DEBUG); + log_set_category_filter(osmo_stderr_target, DLJIBUF, 1, LOGL_DEBUG); + + alarm(10); + + test_normal(); + test_delete_nonempty(); + test_packet_lost(); + test_packet_drop(); + test_packet_out_of_order(); + test_start_2nd_packet(); + test_buffer_threshold_change(); + test_seq_wraparound(); + test_timestamp_wraparound(); + + fprintf(stdout, "OK: Test passed\n"); + return EXIT_SUCCESS; +} diff --git a/tests/jibuf/jibuf_test.ok b/tests/jibuf/jibuf_test.ok new file mode 100644 index 0000000..5a0f121 --- /dev/null +++ b/tests/jibuf/jibuf_test.ok @@ -0,0 +1,351 @@ +===test_normal=== +sys={0.000000}, mono={0.000000}: clock_override_set +sys={0.060000}, mono={0.060000}: clock_override_add +sys={0.060000}, mono={0.060000}: first select, first dequed +sys={0.060000}, mono={0.060000}: dequeue: seq=33 ts=560 LATEST +sys={0.080000}, mono={0.080000}: clock_override_add +sys={0.080000}, mono={0.080000}: second select, one packet should be dequeued +sys={0.080000}, mono={0.080000}: dequeue: seq=34 ts=720 LATEST +sys={0.120000}, mono={0.120000}: clock_override_add +sys={0.120000}, mono={0.120000}: third select, two more dequed +sys={0.120000}, mono={0.120000}: dequeue: seq=35 ts=880 INTERMEDIATE +sys={0.120000}, mono={0.120000}: dequeue: seq=36 ts=1040 LATEST +===test_delete_nonempty=== +sys={0.000000}, mono={0.000000}: clock_override_set +sys={0.020000}, mono={0.020000}: clock_override_add +sys={0.040000}, mono={0.040000}: clock_override_add +sys={0.060000}, mono={0.060000}: clock_override_add +sys={0.060000}, mono={0.060000}: dequeue: seq=33 ts=560 INTERMEDIATE +sys={0.060000}, mono={0.060000}: dequeue: seq=34 ts=720 INTERMEDIATE +sys={0.060000}, mono={0.060000}: dequeue: seq=35 ts=880 INTERMEDIATE +sys={0.060000}, mono={0.060000}: dequeue: seq=36 ts=1040 LATEST +===test_packet_lost=== +sys={0.000000}, mono={0.000000}: clock_override_set +sys={0.000000}, mono={0.000000}: enqueue 1st packet +sys={0.020000}, mono={0.020000}: clock_override_add +sys={0.020000}, mono={0.020000}: packet lost: 2nd +sys={0.040000}, mono={0.040000}: clock_override_add +sys={0.040000}, mono={0.040000}: packet lost: 3rd +sys={0.060000}, mono={0.060000}: clock_override_add +sys={0.060000}, mono={0.060000}: packet lost: 4th +sys={0.080000}, mono={0.080000}: clock_override_add +sys={0.080000}, mono={0.080000}: enqueue 5th packet +sys={0.140000}, mono={0.140000}: clock_override_add +sys={0.140000}, mono={0.140000}: dequeue: seq=33 ts=560 INTERMEDIATE +sys={0.140000}, mono={0.140000}: dequeue: seq=34 ts=720 LATEST +===test_packet_drop=== +sys={0.000000}, mono={0.000000}: clock_override_set +sys={0.000000}, mono={0.000000}: enqueue 1st packet +sys={0.020000}, mono={0.020000}: clock_override_add +sys={0.020000}, mono={0.020000}: enqueue 2nd packet +sys={0.040000}, mono={0.040000}: clock_override_add +sys={0.040000}, mono={0.040000}: enqueue 3rd packet +sys={0.060000}, mono={0.060000}: clock_override_add +sys={0.060000}, mono={0.060000}: enqueue 4th packet +sys={0.060000}, mono={0.060000}: dequeue: seq=33 ts=560 INTERMEDIATE +sys={0.160000}, mono={0.160000}: clock_override_add +sys={0.160000}, mono={0.160000}: next packet should be dropped, too late +sys={0.160000}, mono={0.160000}: next packet should be enqueued +sys={0.160000}, mono={0.160000}: dequeue: seq=34 ts=720 INTERMEDIATE +sys={0.160000}, mono={0.160000}: dequeue: seq=35 ts=880 INTERMEDIATE +sys={0.160000}, mono={0.160000}: dequeue: seq=36 ts=1040 INTERMEDIATE +sys={0.160000}, mono={0.160000}: dequeue: seq=38 ts=1360 LATEST +===test_packet_out_of_order=== +sys={0.000000}, mono={0.000000}: clock_override_set +sys={0.000000}, mono={0.000000}: enqueue 1st packet +sys={0.040000}, mono={0.040000}: clock_override_add +sys={0.040000}, mono={0.040000}: enqueue 3rd packet +sys={0.040000}, mono={0.040000}: enqueue 2nd packet +sys={0.100000}, mono={0.100000}: clock_override_add +sys={0.100000}, mono={0.100000}: dequeue: seq=33 ts=560 INTERMEDIATE +sys={0.100000}, mono={0.100000}: dequeue: seq=34 ts=720 INTERMEDIATE +sys={0.100000}, mono={0.100000}: dequeue: seq=35 ts=880 LATEST +===test_start_2nd_packet=== +sys={0.000000}, mono={0.000000}: clock_override_set +sys={0.000000}, mono={0.000000}: 1st packet is not yet enqueued +sys={0.040000}, mono={0.040000}: clock_override_add +sys={0.040000}, mono={0.040000}: 2nd packet is enqueuded as first +sys={0.040000}, mono={0.040000}: 1st packet is enqueuded as second, should be enqueued with preference +sys={0.080000}, mono={0.080000}: clock_override_add +sys={0.080000}, mono={0.080000}: dequeue: seq=33 ts=560 INTERMEDIATE +sys={0.100000}, mono={0.100000}: clock_override_add +sys={0.100000}, mono={0.100000}: dequeue: seq=34 ts=720 LATEST +===test_buffer_threshold_change=== +sys={0.000000}, mono={0.000000}: clock_override_set +sys={0.000000}, mono={0.000000}: enqueue 1st packet +sys={0.020000}, mono={0.020000}: clock_override_add +sys={0.020000}, mono={0.020000}: enqueue 2nd packet +sys={0.040000}, mono={0.040000}: clock_override_add +sys={0.040000}, mono={0.040000}: enqueue 3rd packet +sys={0.060000}, mono={0.060000}: clock_override_add +sys={0.060000}, mono={0.060000}: enqueue 4th packet +sys={0.060000}, mono={0.060000}: dequeue: seq=33 ts=560 INTERMEDIATE +sys={0.160000}, mono={0.160000}: clock_override_add +sys={0.160000}, mono={0.160000}: next packet should be dropped, too late +sys={0.180000}, mono={0.180000}: clock_override_add +sys={0.180000}, mono={0.180000}: next packet is dropped, but buffer is increased +sys={0.200000}, mono={0.200000}: clock_override_add +sys={0.200000}, mono={0.200000}: next packet is enqueued since the buffer increased +sys={0.200000}, mono={0.200000}: dequeue: seq=34 ts=720 INTERMEDIATE +sys={0.200000}, mono={0.200000}: dequeue: seq=35 ts=880 INTERMEDIATE +sys={0.200000}, mono={0.200000}: dequeue: seq=36 ts=1040 INTERMEDIATE +sys={0.200000}, mono={0.200000}: dequeue: seq=39 ts=1520 LATEST +sys={0.200000}, mono={0.200000}: Enqueue late packets +sys={0.200000}, mono={0.200000}: Run perfectly for a while, buffer should decrease +sys={0.220000}, mono={0.220000}: clock_override_add +sys={0.220000}, mono={0.220000}: dequeue: seq=40 ts=1680 INTERMEDIATE +sys={0.240000}, mono={0.240000}: clock_override_add +sys={0.240000}, mono={0.240000}: dequeue: seq=41 ts=1840 INTERMEDIATE +sys={0.260000}, mono={0.260000}: clock_override_add +sys={0.260000}, mono={0.260000}: dequeue: seq=42 ts=2000 INTERMEDIATE +sys={0.280000}, mono={0.280000}: clock_override_add +sys={0.280000}, mono={0.280000}: dequeue: seq=43 ts=2160 INTERMEDIATE +sys={0.300000}, mono={0.300000}: clock_override_add +sys={0.300000}, mono={0.300000}: dequeue: seq=44 ts=2320 INTERMEDIATE +sys={0.320000}, mono={0.320000}: clock_override_add +sys={0.320000}, mono={0.320000}: dequeue: seq=45 ts=2480 INTERMEDIATE +sys={0.340000}, mono={0.340000}: clock_override_add +sys={0.340000}, mono={0.340000}: dequeue: seq=46 ts=2640 INTERMEDIATE +sys={0.360000}, mono={0.360000}: clock_override_add +sys={0.360000}, mono={0.360000}: dequeue: seq=47 ts=2800 INTERMEDIATE +sys={0.380000}, mono={0.380000}: clock_override_add +sys={0.380000}, mono={0.380000}: dequeue: seq=48 ts=2960 INTERMEDIATE +sys={0.400000}, mono={0.400000}: clock_override_add +sys={0.400000}, mono={0.400000}: dequeue: seq=49 ts=3120 INTERMEDIATE +sys={0.420000}, mono={0.420000}: clock_override_add +sys={0.420000}, mono={0.420000}: dequeue: seq=50 ts=3280 INTERMEDIATE +sys={0.440000}, mono={0.440000}: clock_override_add +sys={0.440000}, mono={0.440000}: dequeue: seq=51 ts=3440 INTERMEDIATE +sys={0.460000}, mono={0.460000}: clock_override_add +sys={0.460000}, mono={0.460000}: dequeue: seq=52 ts=3600 INTERMEDIATE +sys={0.480000}, mono={0.480000}: clock_override_add +sys={0.480000}, mono={0.480000}: dequeue: seq=53 ts=3760 INTERMEDIATE +sys={0.500000}, mono={0.500000}: clock_override_add +sys={0.500000}, mono={0.500000}: dequeue: seq=54 ts=3920 INTERMEDIATE +sys={0.520000}, mono={0.520000}: clock_override_add +sys={0.520000}, mono={0.520000}: dequeue: seq=55 ts=4080 INTERMEDIATE +sys={0.540000}, mono={0.540000}: clock_override_add +sys={0.540000}, mono={0.540000}: dequeue: seq=56 ts=4240 INTERMEDIATE +sys={0.560000}, mono={0.560000}: clock_override_add +sys={0.560000}, mono={0.560000}: dequeue: seq=57 ts=4400 INTERMEDIATE +sys={0.580000}, mono={0.580000}: clock_override_add +sys={0.580000}, mono={0.580000}: dequeue: seq=58 ts=4560 INTERMEDIATE +sys={0.600000}, mono={0.600000}: clock_override_add +sys={0.600000}, mono={0.600000}: dequeue: seq=59 ts=4720 INTERMEDIATE +sys={0.620000}, mono={0.620000}: clock_override_add +sys={0.620000}, mono={0.620000}: dequeue: seq=60 ts=4880 INTERMEDIATE +sys={0.640000}, mono={0.640000}: clock_override_add +sys={0.640000}, mono={0.640000}: dequeue: seq=61 ts=5040 INTERMEDIATE +sys={0.660000}, mono={0.660000}: clock_override_add +sys={0.660000}, mono={0.660000}: dequeue: seq=62 ts=5200 INTERMEDIATE +sys={0.680000}, mono={0.680000}: clock_override_add +sys={0.680000}, mono={0.680000}: dequeue: seq=63 ts=5360 INTERMEDIATE +sys={0.700000}, mono={0.700000}: clock_override_add +sys={0.700000}, mono={0.700000}: dequeue: seq=64 ts=5520 INTERMEDIATE +sys={0.720000}, mono={0.720000}: clock_override_add +sys={0.720000}, mono={0.720000}: dequeue: seq=65 ts=5680 INTERMEDIATE +sys={0.740000}, mono={0.740000}: clock_override_add +sys={0.740000}, mono={0.740000}: dequeue: seq=66 ts=5840 INTERMEDIATE +sys={0.760000}, mono={0.760000}: clock_override_add +sys={0.760000}, mono={0.760000}: dequeue: seq=67 ts=6000 INTERMEDIATE +sys={0.780000}, mono={0.780000}: clock_override_add +sys={0.780000}, mono={0.780000}: dequeue: seq=68 ts=6160 INTERMEDIATE +sys={0.800000}, mono={0.800000}: clock_override_add +sys={0.800000}, mono={0.800000}: dequeue: seq=69 ts=6320 INTERMEDIATE +sys={0.820000}, mono={0.820000}: clock_override_add +sys={0.820000}, mono={0.820000}: dequeue: seq=70 ts=6480 INTERMEDIATE +sys={0.840000}, mono={0.840000}: clock_override_add +sys={0.840000}, mono={0.840000}: dequeue: seq=71 ts=6640 INTERMEDIATE +sys={0.860000}, mono={0.860000}: clock_override_add +sys={0.860000}, mono={0.860000}: dequeue: seq=72 ts=6800 INTERMEDIATE +sys={0.880000}, mono={0.880000}: clock_override_add +sys={0.880000}, mono={0.880000}: dequeue: seq=73 ts=6960 INTERMEDIATE +sys={0.900000}, mono={0.900000}: clock_override_add +sys={0.900000}, mono={0.900000}: dequeue: seq=74 ts=7120 INTERMEDIATE +sys={0.920000}, mono={0.920000}: clock_override_add +sys={0.920000}, mono={0.920000}: dequeue: seq=75 ts=7280 INTERMEDIATE +sys={0.940000}, mono={0.940000}: clock_override_add +sys={0.940000}, mono={0.940000}: dequeue: seq=76 ts=7440 INTERMEDIATE +sys={0.960000}, mono={0.960000}: clock_override_add +sys={0.960000}, mono={0.960000}: dequeue: seq=77 ts=7600 INTERMEDIATE +sys={0.980000}, mono={0.980000}: clock_override_add +sys={0.980000}, mono={0.980000}: dequeue: seq=78 ts=7760 INTERMEDIATE +sys={1.000000}, mono={1.000000}: clock_override_add +sys={1.000000}, mono={1.000000}: dequeue: seq=79 ts=7920 INTERMEDIATE +sys={1.020000}, mono={1.020000}: clock_override_add +sys={1.020000}, mono={1.020000}: dequeue: seq=80 ts=8080 INTERMEDIATE +sys={1.040000}, mono={1.040000}: clock_override_add +sys={1.040000}, mono={1.040000}: dequeue: seq=81 ts=8240 INTERMEDIATE +sys={1.060000}, mono={1.060000}: clock_override_add +sys={1.060000}, mono={1.060000}: dequeue: seq=82 ts=8400 INTERMEDIATE +sys={1.080000}, mono={1.080000}: clock_override_add +sys={1.080000}, mono={1.080000}: dequeue: seq=83 ts=8560 INTERMEDIATE +sys={1.100000}, mono={1.100000}: clock_override_add +sys={1.100000}, mono={1.100000}: dequeue: seq=84 ts=8720 INTERMEDIATE +sys={1.120000}, mono={1.120000}: clock_override_add +sys={1.120000}, mono={1.120000}: dequeue: seq=85 ts=8880 INTERMEDIATE +sys={1.140000}, mono={1.140000}: clock_override_add +sys={1.140000}, mono={1.140000}: dequeue: seq=86 ts=9040 INTERMEDIATE +sys={1.160000}, mono={1.160000}: clock_override_add +sys={1.160000}, mono={1.160000}: dequeue: seq=87 ts=9200 INTERMEDIATE +sys={1.180000}, mono={1.180000}: clock_override_add +sys={1.180000}, mono={1.180000}: dequeue: seq=88 ts=9360 INTERMEDIATE +sys={1.200000}, mono={1.200000}: clock_override_add +sys={1.200000}, mono={1.200000}: dequeue: seq=89 ts=9520 INTERMEDIATE +sys={1.220000}, mono={1.220000}: clock_override_add +sys={1.220000}, mono={1.220000}: dequeue: seq=90 ts=9680 INTERMEDIATE +sys={1.240000}, mono={1.240000}: clock_override_add +sys={1.240000}, mono={1.240000}: dequeue: seq=91 ts=9840 INTERMEDIATE +sys={1.260000}, mono={1.260000}: clock_override_add +sys={1.260000}, mono={1.260000}: dequeue: seq=92 ts=10000 INTERMEDIATE +sys={1.280000}, mono={1.280000}: clock_override_add +sys={1.280000}, mono={1.280000}: dequeue: seq=93 ts=10160 INTERMEDIATE +sys={1.300000}, mono={1.300000}: clock_override_add +sys={1.300000}, mono={1.300000}: dequeue: seq=94 ts=10320 INTERMEDIATE +sys={1.320000}, mono={1.320000}: clock_override_add +sys={1.320000}, mono={1.320000}: dequeue: seq=95 ts=10480 INTERMEDIATE +sys={1.340000}, mono={1.340000}: clock_override_add +sys={1.340000}, mono={1.340000}: dequeue: seq=96 ts=10640 INTERMEDIATE +sys={1.360000}, mono={1.360000}: clock_override_add +sys={1.360000}, mono={1.360000}: dequeue: seq=97 ts=10800 INTERMEDIATE +sys={1.380000}, mono={1.380000}: clock_override_add +sys={1.380000}, mono={1.380000}: dequeue: seq=98 ts=10960 INTERMEDIATE +sys={1.400000}, mono={1.400000}: clock_override_add +sys={1.400000}, mono={1.400000}: dequeue: seq=99 ts=11120 INTERMEDIATE +sys={1.420000}, mono={1.420000}: clock_override_add +sys={1.420000}, mono={1.420000}: dequeue: seq=100 ts=11280 INTERMEDIATE +sys={1.440000}, mono={1.440000}: clock_override_add +sys={1.440000}, mono={1.440000}: dequeue: seq=101 ts=11440 INTERMEDIATE +sys={1.460000}, mono={1.460000}: clock_override_add +sys={1.460000}, mono={1.460000}: dequeue: seq=102 ts=11600 INTERMEDIATE +sys={1.480000}, mono={1.480000}: clock_override_add +sys={1.480000}, mono={1.480000}: dequeue: seq=103 ts=11760 INTERMEDIATE +sys={1.500000}, mono={1.500000}: clock_override_add +sys={1.500000}, mono={1.500000}: dequeue: seq=104 ts=11920 INTERMEDIATE +sys={1.520000}, mono={1.520000}: clock_override_add +sys={1.520000}, mono={1.520000}: dequeue: seq=105 ts=12080 INTERMEDIATE +sys={1.540000}, mono={1.540000}: clock_override_add +sys={1.540000}, mono={1.540000}: dequeue: seq=106 ts=12240 INTERMEDIATE +sys={1.560000}, mono={1.560000}: clock_override_add +sys={1.560000}, mono={1.560000}: dequeue: seq=107 ts=12400 INTERMEDIATE +sys={1.580000}, mono={1.580000}: clock_override_add +sys={1.580000}, mono={1.580000}: dequeue: seq=108 ts=12560 INTERMEDIATE +sys={1.600000}, mono={1.600000}: clock_override_add +sys={1.600000}, mono={1.600000}: dequeue: seq=109 ts=12720 INTERMEDIATE +sys={1.620000}, mono={1.620000}: clock_override_add +sys={1.620000}, mono={1.620000}: dequeue: seq=110 ts=12880 INTERMEDIATE +sys={1.640000}, mono={1.640000}: clock_override_add +sys={1.640000}, mono={1.640000}: dequeue: seq=111 ts=13040 INTERMEDIATE +sys={1.660000}, mono={1.660000}: clock_override_add +sys={1.660000}, mono={1.660000}: dequeue: seq=112 ts=13200 INTERMEDIATE +sys={1.680000}, mono={1.680000}: clock_override_add +sys={1.680000}, mono={1.680000}: dequeue: seq=113 ts=13360 INTERMEDIATE +sys={1.700000}, mono={1.700000}: clock_override_add +sys={1.700000}, mono={1.700000}: dequeue: seq=114 ts=13520 INTERMEDIATE +sys={1.720000}, mono={1.720000}: clock_override_add +sys={1.720000}, mono={1.720000}: dequeue: seq=115 ts=13680 INTERMEDIATE +sys={1.740000}, mono={1.740000}: clock_override_add +sys={1.740000}, mono={1.740000}: dequeue: seq=116 ts=13840 INTERMEDIATE +sys={1.760000}, mono={1.760000}: clock_override_add +sys={1.760000}, mono={1.760000}: dequeue: seq=117 ts=14000 INTERMEDIATE +sys={1.780000}, mono={1.780000}: clock_override_add +sys={1.780000}, mono={1.780000}: dequeue: seq=118 ts=14160 INTERMEDIATE +sys={1.800000}, mono={1.800000}: clock_override_add +sys={1.800000}, mono={1.800000}: dequeue: seq=119 ts=14320 INTERMEDIATE +sys={1.820000}, mono={1.820000}: clock_override_add +sys={1.820000}, mono={1.820000}: dequeue: seq=120 ts=14480 INTERMEDIATE +sys={1.840000}, mono={1.840000}: clock_override_add +sys={1.840000}, mono={1.840000}: dequeue: seq=121 ts=14640 INTERMEDIATE +sys={1.860000}, mono={1.860000}: clock_override_add +sys={1.860000}, mono={1.860000}: dequeue: seq=122 ts=14800 INTERMEDIATE +sys={1.880000}, mono={1.880000}: clock_override_add +sys={1.880000}, mono={1.880000}: dequeue: seq=123 ts=14960 INTERMEDIATE +sys={1.900000}, mono={1.900000}: clock_override_add +sys={1.900000}, mono={1.900000}: dequeue: seq=124 ts=15120 INTERMEDIATE +sys={1.920000}, mono={1.920000}: clock_override_add +sys={1.920000}, mono={1.920000}: dequeue: seq=125 ts=15280 INTERMEDIATE +sys={1.940000}, mono={1.940000}: clock_override_add +sys={1.940000}, mono={1.940000}: dequeue: seq=126 ts=15440 INTERMEDIATE +sys={1.960000}, mono={1.960000}: clock_override_add +sys={1.960000}, mono={1.960000}: dequeue: seq=127 ts=15600 INTERMEDIATE +sys={1.980000}, mono={1.980000}: clock_override_add +sys={1.980000}, mono={1.980000}: dequeue: seq=128 ts=15760 INTERMEDIATE +sys={2.000000}, mono={2.000000}: clock_override_add +sys={2.000000}, mono={2.000000}: dequeue: seq=129 ts=15920 INTERMEDIATE +sys={2.020000}, mono={2.020000}: clock_override_add +sys={2.020000}, mono={2.020000}: dequeue: seq=130 ts=16080 INTERMEDIATE +sys={2.040000}, mono={2.040000}: clock_override_add +sys={2.040000}, mono={2.040000}: dequeue: seq=131 ts=16240 INTERMEDIATE +sys={2.060000}, mono={2.060000}: clock_override_add +sys={2.060000}, mono={2.060000}: dequeue: seq=132 ts=16400 INTERMEDIATE +sys={2.080000}, mono={2.080000}: clock_override_add +sys={2.080000}, mono={2.080000}: dequeue: seq=133 ts=16560 INTERMEDIATE +sys={2.100000}, mono={2.100000}: clock_override_add +sys={2.100000}, mono={2.100000}: dequeue: seq=134 ts=16720 INTERMEDIATE +sys={2.120000}, mono={2.120000}: clock_override_add +sys={2.120000}, mono={2.120000}: dequeue: seq=135 ts=16880 INTERMEDIATE +sys={2.140000}, mono={2.140000}: clock_override_add +sys={2.140000}, mono={2.140000}: dequeue: seq=136 ts=17040 INTERMEDIATE +sys={2.160000}, mono={2.160000}: clock_override_add +sys={2.160000}, mono={2.160000}: dequeue: seq=137 ts=17200 INTERMEDIATE +sys={2.180000}, mono={2.180000}: clock_override_add +sys={2.180000}, mono={2.180000}: dequeue: seq=138 ts=17360 INTERMEDIATE +sys={2.200000}, mono={2.200000}: clock_override_add +sys={2.200000}, mono={2.200000}: dequeue: seq=139 ts=17520 INTERMEDIATE +sys={2.200000}, mono={2.200000}: Done, checking threshold and cleaning +sys={2.270000}, mono={2.270000}: clock_override_add +sys={2.270000}, mono={2.270000}: dequeue: seq=140 ts=17680 INTERMEDIATE +sys={2.270000}, mono={2.270000}: dequeue: seq=141 ts=17840 INTERMEDIATE +sys={2.270000}, mono={2.270000}: dequeue: seq=142 ts=18000 INTERMEDIATE +sys={2.270000}, mono={2.270000}: dequeue: seq=143 ts=18160 LATEST +===test_seq_wraparound=== +sys={0.000000}, mono={0.000000}: clock_override_set +sys={0.000000}, mono={0.000000}: enqueue 1st packet (seq=65534) +sys={0.020000}, mono={0.020000}: clock_override_add +sys={0.020000}, mono={0.020000}: enqueue 2nd packet (seq=65535) +sys={0.040000}, mono={0.040000}: clock_override_add +sys={0.040000}, mono={0.040000}: enqueue 3rd packet (seq=0, wraparound) +sys={0.060000}, mono={0.060000}: clock_override_add +sys={0.060000}, mono={0.060000}: enqueue 4th packet (seq=1) +sys={0.080000}, mono={0.080000}: clock_override_add +sys={0.080000}, mono={0.080000}: enqueue 5th packet (seq=2) +sys={0.080000}, mono={0.080000}: dequeue 1st packet (seq=65534) +sys={0.080000}, mono={0.080000}: dequeue: seq=65534 ts=560 INTERMEDIATE +sys={0.100000}, mono={0.100000}: clock_override_add +sys={0.100000}, mono={0.100000}: dequeue 2nd packet (seq=65535) +sys={0.100000}, mono={0.100000}: dequeue: seq=65535 ts=720 INTERMEDIATE +sys={0.120000}, mono={0.120000}: clock_override_add +sys={0.120000}, mono={0.120000}: dequeue 3rd packet (seq=0, wraparound) +sys={0.120000}, mono={0.120000}: dequeue: seq=0 ts=880 INTERMEDIATE +sys={0.140000}, mono={0.140000}: clock_override_add +sys={0.140000}, mono={0.140000}: dequeue 4th packet (seq=1) +sys={0.140000}, mono={0.140000}: dequeue: seq=1 ts=1040 INTERMEDIATE +sys={0.160000}, mono={0.160000}: clock_override_add +sys={0.160000}, mono={0.160000}: dequeue 5th packet (seq=2) +sys={0.160000}, mono={0.160000}: dequeue: seq=2 ts=1200 LATEST +===test_timestamp_wraparound=== +sys={0.000000}, mono={0.000000}: clock_override_set +sys={0.000000}, mono={0.000000}: enqueue 1st packet (ts=4294966990) +sys={0.020000}, mono={0.020000}: clock_override_add +sys={0.020000}, mono={0.020000}: enqueue 2nd packet (ts=4294967150) +sys={0.040000}, mono={0.040000}: clock_override_add +sys={0.040000}, mono={0.040000}: enqueue 3rd packet (ts=14, wraparound) +sys={0.060000}, mono={0.060000}: clock_override_add +sys={0.060000}, mono={0.060000}: enqueue 4th packet (ts=174) +sys={0.080000}, mono={0.080000}: clock_override_add +sys={0.080000}, mono={0.080000}: enqueue 5th packet (ts=334) +sys={0.080000}, mono={0.080000}: dequeue 1st packet (ts=4294966990) +sys={0.080000}, mono={0.080000}: dequeue: seq=33 ts=4294966990 INTERMEDIATE +sys={0.100000}, mono={0.100000}: clock_override_add +sys={0.100000}, mono={0.100000}: dequeue 2nd packet (ts=4294967150) +sys={0.100000}, mono={0.100000}: dequeue: seq=34 ts=4294967150 INTERMEDIATE +sys={0.120000}, mono={0.120000}: clock_override_add +sys={0.120000}, mono={0.120000}: dequeue 3rd packet (ts=14, wraparound) +sys={0.120000}, mono={0.120000}: dequeue: seq=35 ts=14 INTERMEDIATE +sys={0.140000}, mono={0.140000}: clock_override_add +sys={0.140000}, mono={0.140000}: dequeue 4th packet (ts=174) +sys={0.140000}, mono={0.140000}: dequeue: seq=36 ts=174 INTERMEDIATE +sys={0.160000}, mono={0.160000}: clock_override_add +sys={0.160000}, mono={0.160000}: dequeue 5th packet (ts=334) +sys={0.160000}, mono={0.160000}: dequeue: seq=37 ts=334 LATEST +OK: Test passed diff --git a/tests/testsuite.at b/tests/testsuite.at index d0e55f6..81d40ba 100644 --- a/tests/testsuite.at +++ b/tests/testsuite.at @@ -6,3 +6,9 @@ AT_KEYWORDS([osmux_test]) cat $abs_srcdir/osmux/osmux_test.ok > expout AT_CHECK([$abs_top_builddir/tests/osmux/osmux_test], [0], [expout], [ignore]) AT_CLEANUP + +AT_SETUP([jibuf_test]) +AT_KEYWORDS([jibuf_test]) +cat $abs_srcdir/jibuf/jibuf_test.ok > expout +AT_CHECK([$abs_top_builddir/tests/jibuf/jibuf_test], [0], [expout], [ignore]) +AT_CLEANUP |