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

@@ -183,11 +183,6 @@ private:
 
     // Mutexes
     pthread_mutex_t mutex;
-
-    // Metrics
-#ifdef ENABLE_TIMESTAMP
-    srslte::rolling_average<double> 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<double> sdu_rx_latency_ms;
   };
 
   // Common variables needed/provided by parent class

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::milliseconds>(
+                                     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::milliseconds>(
+                                 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
  *

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--) {