From bc4c9606ce3b20d050761a254353a1df7b125cb4 Mon Sep 17 00:00:00 2001 From: Andre Puschmann Date: Wed, 16 Dec 2020 22:07:04 +0100 Subject: [PATCH] rlc_am: add extended bearer metrics this patch adds support for measuring the: * SDU rx latency (Average time in ms from first RLC segment to full SDU) * amount of buffered bytes (sum of payload of PDUs buffered in rx_window) the implementation is using std::chrono --- lib/include/srslte/upper/rlc_am_lte.h | 10 +++---- lib/src/upper/rlc_am_lte.cc | 41 +++++++++++++++++++++++++-- lib/test/upper/rlc_am_test.cc | 4 +++ 3 files changed, 46 insertions(+), 9 deletions(-) diff --git a/lib/include/srslte/upper/rlc_am_lte.h b/lib/include/srslte/upper/rlc_am_lte.h index f2d3774ab..f3c39e735 100644 --- a/lib/include/srslte/upper/rlc_am_lte.h +++ b/lib/include/srslte/upper/rlc_am_lte.h @@ -183,11 +183,6 @@ private: // Mutexes pthread_mutex_t mutex; - - // Metrics -#ifdef ENABLE_TIMESTAMP - srslte::rolling_average mean_pdu_latency_us; -#endif }; // Receiver sub-class @@ -203,7 +198,8 @@ private: void write_pdu(uint8_t* payload, uint32_t nof_bytes); - uint32_t get_num_rx_bytes(); + uint32_t get_rx_buffered_bytes(); // returns sum of PDUs in rx_window + uint32_t get_sdu_rx_latency_ms(); // Timeout callback interface void timer_expired(uint32_t timeout_id); @@ -264,6 +260,8 @@ private: ***************************************************************************/ srslte::timer_handler::unique_timer reordering_timer; + + srslte::rolling_average sdu_rx_latency_ms; }; // Common variables needed/provided by parent class diff --git a/lib/src/upper/rlc_am_lte.cc b/lib/src/upper/rlc_am_lte.cc index d4c506695..dcbf335bd 100644 --- a/lib/src/upper/rlc_am_lte.cc +++ b/lib/src/upper/rlc_am_lte.cc @@ -99,6 +99,9 @@ uint32_t rlc_am_lte::get_bearer() rlc_bearer_metrics_t rlc_am_lte::get_metrics() { + // update values that aren't calculated on the fly + metrics.rx_latency_ms = rx.get_sdu_rx_latency_ms(); + metrics.rx_buffered_bytes = rx.get_rx_buffered_bytes(); return metrics; } @@ -1255,6 +1258,7 @@ void rlc_am_lte::rlc_am_lte_rx::handle_data_pdu(uint8_t* payload, uint32_t nof_b return; #endif } + pdu.buf->set_timestamp(); // check available space for payload if (nof_bytes > pdu.buf->get_tailroom()) { @@ -1459,7 +1463,10 @@ void rlc_am_lte::rlc_am_lte_rx::reassemble_rx_sdus() rx_sdu.reset(); goto exit; } - + // store timestamp of the first segment when starting to assemble SDUs + if (rx_sdu->N_bytes == 0) { + rx_sdu->set_timestamp(rx_window[vr_r].buf->get_timestamp()); + } memcpy(&rx_sdu->msg[rx_sdu->N_bytes], rx_window[vr_r].buf->msg, len); rx_sdu->N_bytes += len; @@ -1467,7 +1474,9 @@ void rlc_am_lte::rlc_am_lte_rx::reassemble_rx_sdus() rx_window[vr_r].buf->N_bytes -= len; log->info_hex(rx_sdu->msg, rx_sdu->N_bytes, "%s Rx SDU (%d B)", RB_NAME, rx_sdu->N_bytes); - rx_sdu->set_timestamp(); + sdu_rx_latency_ms.push(std::chrono::duration_cast( + std::chrono::high_resolution_clock::now() - rx_sdu->get_timestamp()) + .count()); parent->pdcp->write_pdu(parent->lcid, std::move(rx_sdu)); parent->metrics.num_rx_sdus++; @@ -1498,6 +1507,10 @@ void rlc_am_lte::rlc_am_lte_rx::reassemble_rx_sdus() len = rx_window[vr_r].buf->N_bytes; log->debug_hex(rx_window[vr_r].buf->msg, len, "Handling last segment of length %d B of SN=%d\n", len, vr_r); if (rx_sdu->get_tailroom() >= len) { + // store timestamp of the first segment when starting to assemble SDUs + if (rx_sdu->N_bytes == 0) { + rx_sdu->set_timestamp(rx_window[vr_r].buf->get_timestamp()); + } memcpy(&rx_sdu->msg[rx_sdu->N_bytes], rx_window[vr_r].buf->msg, len); rx_sdu->N_bytes += rx_window[vr_r].buf->N_bytes; } else { @@ -1511,7 +1524,9 @@ void rlc_am_lte::rlc_am_lte_rx::reassemble_rx_sdus() if (rlc_am_end_aligned(rx_window[vr_r].header.fi)) { log->info_hex(rx_sdu->msg, rx_sdu->N_bytes, "%s Rx SDU (%d B)", RB_NAME, rx_sdu->N_bytes); - rx_sdu->set_timestamp(); + sdu_rx_latency_ms.push(std::chrono::duration_cast( + std::chrono::high_resolution_clock::now() - rx_sdu->get_timestamp()) + .count()); parent->pdcp->write_pdu(parent->lcid, std::move(rx_sdu)); parent->metrics.num_rx_sdus++; @@ -1593,6 +1608,26 @@ void rlc_am_lte::rlc_am_lte_rx::write_pdu(uint8_t* payload, const uint32_t nof_b } } +uint32_t rlc_am_lte::rlc_am_lte_rx::get_rx_buffered_bytes() +{ + uint32_t buff_size = 0; + pthread_mutex_lock(&mutex); + for (const auto& pdu : rx_window) { + buff_size += pdu.second.buf->N_bytes; + } + pthread_mutex_unlock(&mutex); + return buff_size; +} + +uint32_t rlc_am_lte::rlc_am_lte_rx::get_sdu_rx_latency_ms() +{ + uint32_t latency = 0; + pthread_mutex_lock(&mutex); + latency = sdu_rx_latency_ms.value(); + pthread_mutex_unlock(&mutex); + return latency; +} + /** * Function called from stack thread when timer has expired * diff --git a/lib/test/upper/rlc_am_test.cc b/lib/test/upper/rlc_am_test.cc index 9ba3945b8..6ad587a9d 100644 --- a/lib/test/upper/rlc_am_test.cc +++ b/lib/test/upper/rlc_am_test.cc @@ -365,6 +365,10 @@ bool retx_test() rlc2.write_pdu(pdu_bufs[i].msg, pdu_bufs[i].N_bytes); } + // check buffered bytes at receiver, 3 PDUs with one 1 B each (SN=0 has been delivered already) + rlc_bearer_metrics_t metrics = rlc2.get_metrics(); + assert(metrics.rx_buffered_bytes == 3); + // Step timers until reordering timeout expires int cnt = 5; while (cnt--) {