diff --git a/lib/src/upper/rlc_am_lte.cc b/lib/src/upper/rlc_am_lte.cc index a80480bdf..4bf230413 100644 --- a/lib/src/upper/rlc_am_lte.cc +++ b/lib/src/upper/rlc_am_lte.cc @@ -1075,8 +1075,6 @@ void rlc_am_lte::rlc_am_lte_tx::handle_control_pdu(uint8_t* payload, uint32_t no std::unique_lock 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; @@ -1169,7 +1167,6 @@ 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)) { @@ -1185,7 +1182,6 @@ 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(); diff --git a/srsenb/src/stack/enb_stack_lte.cc b/srsenb/src/stack/enb_stack_lte.cc index 3acaa65af..bae30116a 100644 --- a/srsenb/src/stack/enb_stack_lte.cc +++ b/srsenb/src/stack/enb_stack_lte.cc @@ -14,6 +14,7 @@ #include "srsenb/hdr/enb.h" #include "srslte/common/network_utils.h" #include "srslte/interfaces/enb_metrics_interface.h" +#include "srslte/srslog/event_trace.h" using namespace srslte; @@ -166,6 +167,7 @@ void enb_stack_lte::tti_clock() void enb_stack_lte::tti_clock_impl() { + trace_complete_event("enb_stack_lte::tti_clock_impl", "total_time"); task_sched.tic(); rrc.tti_clock(); } diff --git a/srsenb/src/stack/mac/mac.cc b/srsenb/src/stack/mac/mac.cc index fc55aab1e..10084d38e 100644 --- a/srsenb/src/stack/mac/mac.cc +++ b/srsenb/src/stack/mac/mac.cc @@ -20,6 +20,7 @@ #include "srslte/interfaces/enb_phy_interfaces.h" #include "srslte/interfaces/enb_rlc_interfaces.h" #include "srslte/interfaces/enb_rrc_interfaces.h" +#include "srslte/srslog/event_trace.h" // #define WRITE_SIB_PCAP using namespace asn1::rrc; @@ -575,6 +576,7 @@ int mac::get_dl_sched(uint32_t tti_tx_dl, dl_sched_list_t& dl_sched_res_list) return 0; } + trace_complete_event("mac::get_dl_sched", "total_time"); logger.set_context(TTI_SUB(tti_tx_dl, FDD_HARQ_DELAY_UL_MS)); log_h->step(TTI_SUB(tti_tx_dl, FDD_HARQ_DELAY_UL_MS)); diff --git a/srsue/hdr/ue.h b/srsue/hdr/ue.h index 9f7e4d266..5d9e86f0a 100644 --- a/srsue/hdr/ue.h +++ b/srsue/hdr/ue.h @@ -62,6 +62,8 @@ typedef struct { bool metrics_csv_append; int metrics_csv_flush_period_sec; std::string metrics_csv_filename; + bool tracing_enable; + std::string tracing_filename; } general_args_t; typedef struct { diff --git a/srsue/src/main.cc b/srsue/src/main.cc index 0418b6bc0..d177690ae 100644 --- a/srsue/src/main.cc +++ b/srsue/src/main.cc @@ -17,6 +17,7 @@ #include "srslte/common/logmap.h" #include "srslte/common/metrics_hub.h" #include "srslte/common/signal_handler.h" +#include "srslte/srslog/event_trace.h" #include "srslte/srslog/srslog.h" #include "srslte/srslte.h" #include "srslte/version.h" @@ -419,6 +420,14 @@ static int parse_args(all_args_t* args, int argc, char* argv[]) bpo::value(&args->general.metrics_csv_flush_period_sec)->default_value(-1), "Periodicity in s to flush CSV file to disk (-1 for auto)") + ("general.tracing_enable", + bpo::value(&args->general.tracing_enable)->default_value(false), + "Events tracing") + + ("general.tracing_filename", + bpo::value(&args->general.tracing_filename)->default_value("/tmp/ue_tracing.log"), + "Tracing events filename") + ("stack.have_tti_time_stats", bpo::value(&args->stack.have_tti_time_stats)->default_value(true), "Calculate TTI execution statistics") @@ -642,6 +651,14 @@ int main(int argc, char* argv[]) srslte::srslog_wrapper log_wrapper(*chan); srslog::set_default_sink(*log_sink); +#ifdef ENABLE_SRSLOG_EVENT_TRACE + if (args.general.tracing_enable) { + srslog::sink& tracing_sink = srslog::fetch_file_sink(args.general.tracing_filename); + srslog::log_channel& c = srslog::fetch_log_channel("tracing", tracing_sink, {"TRACE", '\0', false}); + srslog::event_trace_init(c); + } +#endif + // Start the log backend. srslog::init(); diff --git a/srsue/src/stack/ue_stack_lte.cc b/srsue/src/stack/ue_stack_lte.cc index 9d22f6654..019c11768 100644 --- a/srsue/src/stack/ue_stack_lte.cc +++ b/srsue/src/stack/ue_stack_lte.cc @@ -13,7 +13,7 @@ #include "srsue/hdr/stack/ue_stack_lte.h" #include "srslte/common/logmap.h" #include "srslte/interfaces/ue_phy_interfaces.h" - +#include "srslte/srslog/event_trace.h" #include #include #include @@ -401,6 +401,9 @@ void ue_stack_lte::run_tti_impl(uint32_t tti, uint32_t tti_jump) if (args.have_tti_time_stats) { tti_tprof.start(); } + + trace_complete_event("ue_stack_lte::run_tti_impl", "total time"); + current_tti = tti_point{tti}; // perform tasks for the received TTI range diff --git a/srsue/ue.conf.example b/srsue/ue.conf.example index 69ae83a71..fa1083217 100644 --- a/srsue/ue.conf.example +++ b/srsue/ue.conf.example @@ -381,7 +381,9 @@ enable = false # ##################################################################### [general] -#metrics_csv_enable = false -#metrics_period_secs = 1 +#metrics_csv_enable = false +#metrics_period_secs = 1 #metrics_csv_filename = /tmp/ue_metrics.csv -#have_tti_time_stats = true +#have_tti_time_stats = true +#tracing_enable = true +#tracing_filename = /tmp/ue_tracing.log