Add instrumentation points to rlc_am_lte::rlc_am_lte_tx::handle_control_pdu using srslog.

CMakeLists.txt

@@ -80,6 +80,8 @@ option(ENABLE_TIMEPROF "Enable time profiling"                    ON)
 
 option(FORCE_32BIT     "Add flags to force 32 bit compilation"    OFF)
 
+option(ENABLE_SRSLOG_TRACING "Enable event tracing using srslog"  OFF)
+
 # Users that want to try this feature need to make sure the lto plugin is
 # loaded by bintools (ar, nm, ...). Older versions of bintools will not do
 # it automatically so it is necessary to use the gcc wrappers of the compiler
@@ -94,6 +96,10 @@ else(${CMAKE_SYSTEM_PROCESSOR} MATCHES "aarch64")
 endif(${CMAKE_SYSTEM_PROCESSOR} MATCHES "aarch64")
 
 
+if (ENABLE_SRSLOG_TRACING)
+  add_definitions(-DENABLE_SRSLOG_EVENT_TRACE)
+endif (ENABLE_SRSLOG_TRACING)
+
 ########################################################################
 # Find dependencies
 ########################################################################

lib/include/srslte/srslog/event_trace.h

@@ -46,7 +46,7 @@ void trace_duration_end(const std::string& category, const std::string& name);
 
 /// Generates a complete event.
 #define trace_complete_event(C, N)                                             \
-  auto scoped_complete_event_variable = detail::scoped_complete_event(C, N)
+  auto scoped_complete_event_variable = srslog::detail::scoped_complete_event(C, N)
 
 #else
 

lib/src/upper/rlc_am_lte.cc

@@ -14,7 +14,7 @@
 #include "srslte/common/string_helpers.h"
 #include "srslte/interfaces/ue_pdcp_interfaces.h"
 #include "srslte/interfaces/ue_rrc_interfaces.h"
-
+#include "srslte/srslog/event_trace.h"
 #include <iostream>
 
 #define MOD 1024
@@ -1075,6 +1075,8 @@ void rlc_am_lte::rlc_am_lte_tx::handle_control_pdu(uint8_t* payload, uint32_t no
 
   std::unique_lock<std::mutex> lock(mutex);
 
+  trace_complete_event("rlc_am::handle_control_pdu", "total time");
+
   logger.info(payload, nof_bytes, "%s Rx control PDU", RB_NAME);
 
   rlc_status_pdu_t status;
@@ -1167,6 +1169,7 @@ void rlc_am_lte::rlc_am_lte_tx::handle_control_pdu(uint8_t* payload, uint32_t no
 
   if (not notify_info_vec.empty()) {
     // Remove all SDUs that were fully acked
+    trace_complete_event("rlc_am::handle_control_pdu", "remove acked sdus");
     for (uint32_t acked_pdcp_sn : notify_info_vec) {
       logger.debug("Erasing SDU info: PDCP_SN=%d", acked_pdcp_sn);
       if (not undelivered_sdu_info_queue.has_pdcp_sn(acked_pdcp_sn)) {
@@ -1182,6 +1185,7 @@ void rlc_am_lte::rlc_am_lte_tx::handle_control_pdu(uint8_t* payload, uint32_t no
 
   // Notify PDCP without holding Tx mutex
   if (not notify_info_vec.empty()) {
+    trace_complete_event("rlc_am::handle_control_pdu", "notify_delivery");
     parent->pdcp->notify_delivery(parent->lcid, notify_info_vec);
   }
   notify_info_vec.clear();

srsenb/src/main.cc

@@ -22,6 +22,7 @@
 #include "srslte/common/logger_srslog_wrapper.h"
 #include "srslte/common/logmap.h"
 #include "srslte/common/signal_handler.h"
+#include "srslte/srslog/event_trace.h"
 #include "srslte/srslog/srslog.h"
 
 #include <boost/program_options.hpp>
@@ -501,6 +502,10 @@ int main(int argc, char* argv[])
   srslog::log_channel& alarms_channel = srslog::fetch_log_channel("alarms", alarm_sink, {"ALRM", '\0', false});
   alarms_channel.set_enabled(args.general.alarms_log_enable);
 
+#ifdef ENABLE_SRSLOG_EVENT_TRACE
+  srslog::event_trace_init();
+#endif
+
   // Start the log backend.
   srslog::init();