Enable pdu stack latency measurements in the eNB.

lib/include/srslte/common/common.h

@@ -82,7 +82,7 @@
 
 namespace srslte {
 
-//#define ENABLE_TIMESTAMP
+#define ENABLE_TIMESTAMP
 
 /******************************************************************************
  * Byte and Bit buffers
@@ -152,7 +152,7 @@ public:
       return 0;
     gettimeofday(&timestamp[2], NULL);
     get_time_interval(timestamp);
-    return timestamp[0].tv_usec;
+    return timestamp[0].tv_usec + timestamp[0].tv_sec * 1000000;
 #else
     return 0;
 #endif
@@ -263,7 +263,7 @@ typedef std::unique_ptr<byte_buffer_t, byte_buffer_deleter> unique_byte_buffer_t
 /// Utilities to create a span out of a byte_buffer.
 ///
 
-using byte_span = span<uint8_t>;
+using byte_span       = span<uint8_t>;
 using const_byte_span = span<const uint8_t>;
 
 inline byte_span make_span(byte_buffer_t& b)

lib/include/srslte/upper/rlc_am_lte.h

@@ -13,6 +13,7 @@
 #ifndef SRSLTE_RLC_AM_LTE_H
 #define SRSLTE_RLC_AM_LTE_H
 
+#include "srslte/adt/accumulators.h"
 #include "srslte/common/buffer_pool.h"
 #include "srslte/common/common.h"
 #include "srslte/common/log.h"
@@ -182,6 +183,9 @@ private:
 
     // Mutexes
     pthread_mutex_t mutex;
+
+    // Metrics
+    srslte::rolling_average<float> mean_pdu_latency_us;
   };
 
   // Receiver sub-class

lib/include/srslte/upper/rlc_um_lte.h

@@ -13,6 +13,7 @@
 #ifndef SRSLTE_RLC_UM_LTE_H
 #define SRSLTE_RLC_UM_LTE_H
 
+#include "srslte/adt/accumulators.h"
 #include "srslte/common/buffer_pool.h"
 #include "srslte/common/common.h"
 #include "srslte/common/log.h"
@@ -63,6 +64,9 @@ private:
      ***************************************************************************/
     uint32_t vt_us = 0; // Send state. SN to be assigned for next PDU.
 
+    // Metrics
+    srslte::rolling_average<float> mean_pdu_latency_us;
+
     void debug_state();
   };
 

lib/src/upper/rlc_am_lte.cc

@@ -837,7 +837,12 @@ int rlc_am_lte::rlc_am_lte_tx::build_data_pdu(uint8_t* payload, uint32_t nof_byt
     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, tx_sdu->get_latency_us());
+      long latency_us = tx_sdu->get_latency_us();
+      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,
+                 latency_us,
+                 (long)mean_pdu_latency_us.value());
       tx_sdu.reset();
     }
     if (pdu_space > to_move) {
@@ -876,7 +881,12 @@ int rlc_am_lte::rlc_am_lte_tx::build_data_pdu(uint8_t* payload, uint32_t nof_byt
     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, tx_sdu->get_latency_us());
+      long latency_us = tx_sdu->get_latency_us();
+      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,
+                 latency_us,
+                 (long)mean_pdu_latency_us.value());
       tx_sdu.reset();
     }
     if (pdu_space > to_move) {

lib/src/upper/rlc_um_lte.cc

@@ -23,8 +23,7 @@ rlc_um_lte::rlc_um_lte(srslte::log_ref            log_,
                        srsue::rrc_interface_rlc*  rrc_,
                        srslte::timer_handler*     timers_) :
   rlc_um_base(log_, lcid_, pdcp_, rrc_, timers_)
-{
+{}
-}
 
 // Warning: must call stop() to properly deallocate all buffers
 rlc_um_lte::~rlc_um_lte()
@@ -146,8 +145,12 @@ int rlc_um_lte::rlc_um_lte_tx::build_data_pdu(unique_byte_buffer_t pdu, uint8_t*
     tx_sdu->N_bytes -= to_move;
     tx_sdu->msg += to_move;
     if (tx_sdu->N_bytes == 0) {
-      log->debug(
+      long latency_us = tx_sdu->get_latency_us();
-          "%s Complete SDU scheduled for tx. Stack latency: %ld us\n", rb_name.c_str(), tx_sdu->get_latency_us());
+      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(),
+                 latency_us,
+                 (long)mean_pdu_latency_us.value());
 
       tx_sdu.reset();
     }
@@ -178,8 +181,12 @@ int rlc_um_lte::rlc_um_lte_tx::build_data_pdu(unique_byte_buffer_t pdu, uint8_t*
     tx_sdu->N_bytes -= to_move;
     tx_sdu->msg += to_move;
     if (tx_sdu->N_bytes == 0) {
-      log->debug(
+      long latency_us = tx_sdu->get_latency_us();
-          "%s Complete SDU scheduled for tx. Stack latency: %ld us\n", rb_name.c_str(), tx_sdu->get_latency_us());
+      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(),
+                 latency_us,
+                 (long)mean_pdu_latency_us.value());
 
       tx_sdu.reset();
     }
@@ -220,10 +227,8 @@ void rlc_um_lte::rlc_um_lte_tx::reset()
  ***************************************************************************/
 
 rlc_um_lte::rlc_um_lte_rx::rlc_um_lte_rx(rlc_um_base* parent_) :
-  rlc_um_base_rx(parent_),
+  rlc_um_base_rx(parent_), reordering_timer(timers->get_unique_timer())
-  reordering_timer(timers->get_unique_timer())
+{}
-{
-}
 
 rlc_um_lte::rlc_um_lte_rx::~rlc_um_lte_rx() {}
 

srsenb/src/stack/upper/gtpu.cc

@@ -227,6 +227,7 @@ void gtpu::rem_user(uint16_t rnti)
 void gtpu::handle_gtpu_s1u_rx_packet(srslte::unique_byte_buffer_t pdu, const sockaddr_in& addr)
 {
   gtpu_log->debug("Received %d bytes from S1-U interface\n", pdu->N_bytes);
+  pdu->set_timestamp();
 
   gtpu_header_t header;
   if (not gtpu_read_header(pdu.get(), &header, gtpu_log)) {