changed pdu latency calculation to std chrono

This commit is contained in:
Francisco Paisana 2020-12-14 11:28:11 +00:00
parent 7ffc236a1a
commit 0f693b36b2
6 changed files with 28 additions and 26 deletions

View File

@ -18,6 +18,7 @@
*******************************************************************************/
#include "srslte/adt/span.h"
#include <chrono>
#include <memory>
#include <stdint.h>
#include <string.h>
@ -104,9 +105,6 @@ public:
byte_buffer_t() : N_bytes(0)
{
bzero(buffer, SRSLTE_MAX_BUFFER_SIZE_BYTES);
#ifdef ENABLE_TIMESTAMP
timestamp_is_set = false;
#endif
msg = &buffer[SRSLTE_BUFFER_HEADER_OFFSET];
next = NULL;
#ifdef SRSLTE_BUFFER_POOL_LOG_ENABLED
@ -144,24 +142,23 @@ public:
}
uint32_t get_headroom() { return msg - buffer; }
// Returns the remaining space from what is reported to be the length of msg
uint32_t get_tailroom() { return (sizeof(buffer) - (msg - buffer) - N_bytes); }
long get_latency_us()
uint32_t get_tailroom() { return (sizeof(buffer) - (msg - buffer) - N_bytes); }
std::chrono::microseconds get_latency_us()
{
#ifdef ENABLE_TIMESTAMP
if (!timestamp_is_set)
return 0;
gettimeofday(&timestamp[2], NULL);
get_time_interval(timestamp);
return timestamp[0].tv_usec + timestamp[0].tv_sec * 1000000;
if (!timestamp_is_set) {
return std::chrono::microseconds{0};
}
return std::chrono::duration_cast<std::chrono::microseconds>(std::chrono::high_resolution_clock::now() - tp);
#else
return 0;
return std::chrono::microseconds{0};
#endif
}
void set_timestamp()
{
#ifdef ENABLE_TIMESTAMP
gettimeofday(&timestamp[1], NULL);
tp = std::chrono::high_resolution_clock::now();
timestamp_is_set = true;
#endif
}
@ -174,8 +171,8 @@ public:
private:
#ifdef ENABLE_TIMESTAMP
struct timeval timestamp[3];
bool timestamp_is_set;
std::chrono::high_resolution_clock::time_point tp;
bool timestamp_is_set = false;
#endif
byte_buffer_t* next;
};

View File

@ -838,7 +838,7 @@ int rlc_am_lte::rlc_am_lte_tx::build_data_pdu(uint8_t* payload, uint32_t nof_byt
tx_sdu->msg += to_move;
if (tx_sdu->N_bytes == 0) {
#ifdef ENABLE_TIMESTAMP
long latency_us = tx_sdu->get_latency_us();
long latency_us = tx_sdu->get_latency_us().count();
mean_pdu_latency_us.push(latency_us);
log->debug("%s Complete SDU scheduled for tx. Stack latency (last/average): %ld/%ld us\n",
RB_NAME,
@ -886,7 +886,7 @@ int rlc_am_lte::rlc_am_lte_tx::build_data_pdu(uint8_t* payload, uint32_t nof_byt
tx_sdu->msg += to_move;
if (tx_sdu->N_bytes == 0) {
#ifdef ENABLE_TIMESTAMP
long latency_us = tx_sdu->get_latency_us();
long latency_us = tx_sdu->get_latency_us().count();
mean_pdu_latency_us.push(latency_us);
log->debug("%s Complete SDU scheduled for tx. Stack latency (last/average): %ld/%ld us\n",
RB_NAME,

View File

@ -142,7 +142,7 @@ int rlc_tm::read_pdu(uint8_t* payload, uint32_t nof_bytes)
memcpy(payload, buf->msg, buf->N_bytes);
log->debug("%s Complete SDU scheduled for tx. Stack latency: %ld us\n",
rrc->get_rb_name(lcid).c_str(),
buf->get_latency_us());
buf->get_latency_us().count());
log->info_hex(payload,
pdu_size,
"TX %s, %s PDU, queue size=%d, bytes=%d",

View File

@ -146,7 +146,7 @@ int rlc_um_lte::rlc_um_lte_tx::build_data_pdu(unique_byte_buffer_t pdu, uint8_t*
tx_sdu->msg += to_move;
if (tx_sdu->N_bytes == 0) {
#ifdef ENABLE_TIMESTAMP
long latency_us = tx_sdu->get_latency_us();
auto latency_us = tx_sdu->get_latency_us().count();
mean_pdu_latency_us.push(latency_us);
log->debug("%s Complete SDU scheduled for tx. Stack latency (last/average): %ld/%ld us\n",
rb_name.c_str(),
@ -185,7 +185,7 @@ int rlc_um_lte::rlc_um_lte_tx::build_data_pdu(unique_byte_buffer_t pdu, uint8_t*
tx_sdu->msg += to_move;
if (tx_sdu->N_bytes == 0) {
#ifdef ENABLE_TIMESTAMP
long latency_us = tx_sdu->get_latency_us();
auto latency_us = tx_sdu->get_latency_us().count();
mean_pdu_latency_us.push(latency_us);
log->debug("%s Complete SDU scheduled for tx. Stack latency (last/average): %ld/%ld us\n",
rb_name.c_str(),

View File

@ -139,8 +139,9 @@ int rlc_um_nr::rlc_um_nr_tx::build_data_pdu(unique_byte_buffer_t pdu, uint8_t* p
tx_sdu->N_bytes -= to_move;
tx_sdu->msg += to_move;
if (tx_sdu->N_bytes == 0) {
log->debug(
"%s Complete SDU scheduled for tx. Stack latency: %ld us\n", rb_name.c_str(), tx_sdu->get_latency_us());
log->debug("%s Complete SDU scheduled for tx. Stack latency: %ld us\n",
rb_name.c_str(),
tx_sdu->get_latency_us().count());
tx_sdu.reset();
header.si = rlc_nr_si_field_t::last_segment;
} else {
@ -163,8 +164,9 @@ int rlc_um_nr::rlc_um_nr_tx::build_data_pdu(unique_byte_buffer_t pdu, uint8_t* p
tx_sdu->N_bytes -= to_move;
tx_sdu->msg += to_move;
if (tx_sdu->N_bytes == 0) {
log->debug(
"%s Complete SDU scheduled for tx. Stack latency: %ld us\n", rb_name.c_str(), tx_sdu->get_latency_us());
log->debug("%s Complete SDU scheduled for tx. Stack latency: %ld us\n",
rb_name.c_str(),
tx_sdu->get_latency_us().count());
tx_sdu.reset();
header.si = rlc_nr_si_field_t::full_sdu;
} else {

View File

@ -113,7 +113,7 @@ void gw::get_metrics(gw_metrics_t& m, const uint32_t nof_tti)
*******************************************************************************/
void gw::write_pdu(uint32_t lcid, srslte::unique_byte_buffer_t pdu)
{
log.info_hex(pdu->msg, pdu->N_bytes, "RX PDU. Stack latency: %ld us\n", pdu->get_latency_us());
log.info_hex(pdu->msg, pdu->N_bytes, "RX PDU. Stack latency: %ld us\n", pdu->get_latency_us().count());
dl_tput_bytes += pdu->N_bytes;
if (!if_up) {
log.warning("TUN/TAP not up - dropping gw RX message\n");
@ -137,8 +137,11 @@ void gw::write_pdu(uint32_t lcid, srslte::unique_byte_buffer_t pdu)
void gw::write_pdu_mch(uint32_t lcid, srslte::unique_byte_buffer_t pdu)
{
if (pdu->N_bytes > 2) {
log.info_hex(
pdu->msg, pdu->N_bytes, "RX MCH PDU (%d B). Stack latency: %ld us\n", pdu->N_bytes, pdu->get_latency_us());
log.info_hex(pdu->msg,
pdu->N_bytes,
"RX MCH PDU (%d B). Stack latency: %ld us\n",
pdu->N_bytes,
pdu->get_latency_us().count());
dl_tput_bytes += pdu->N_bytes;
// Hack to drop initial 2 bytes