From 173dcdd42197b6f5ad64dcd57a879c29908a0c3f Mon Sep 17 00:00:00 2001 From: faluco Date: Tue, 9 Mar 2021 18:19:25 +0100 Subject: [PATCH] - Import latest srslog version. - Remove string allocs in some log lines in radio.cc. Add new tracing buffer capcity options into srsenb and srsue. Add missing file. --- .../srslte/srslog/detail/log_entry_metadata.h | 2 +- .../srslog/detail/support/memory_buffer.h | 12 +- .../srslte/srslog/detail/support/work_queue.h | 4 +- lib/include/srslte/srslog/event_trace.h | 22 ++- lib/include/srslte/srslog/log_channel.h | 19 +-- lib/src/radio/radio.cc | 22 ++- lib/src/srslog/backend_worker.cpp | 7 +- lib/src/srslog/backend_worker.h | 1 + lib/src/srslog/event_trace.cpp | 33 ++++- lib/src/srslog/formatters/json_formatter.cpp | 2 +- lib/src/srslog/formatters/text_formatter.cpp | 69 ++++++--- lib/src/srslog/formatters/text_formatter.h | 51 +++++-- lib/src/srslog/sinks/file_sink.h | 4 +- lib/src/srslog/sinks/single_write_file_sink.h | 90 ++++++++++++ lib/test/srslog/CMakeLists.txt | 9 +- lib/test/srslog/json_formatter_test.cpp | 6 +- lib/test/srslog/log_channel_test.cpp | 25 ++-- lib/test/srslog/text_formatter_test.cpp | 138 ++++++++++++++---- srsenb/enb.conf.example | 2 + srsenb/hdr/enb.h | 3 +- srsenb/src/main.cc | 7 +- srsue/hdr/ue.h | 1 + srsue/src/main.cc | 10 +- srsue/src/stack/mac_nr/proc_ra_nr.cc | 2 +- srsue/ue.conf.example | 3 + 25 files changed, 407 insertions(+), 137 deletions(-) create mode 100644 lib/src/srslog/sinks/single_write_file_sink.h diff --git a/lib/include/srslte/srslog/detail/log_entry_metadata.h b/lib/include/srslte/srslog/detail/log_entry_metadata.h index be40fa791..57f306a6d 100644 --- a/lib/include/srslte/srslog/detail/log_entry_metadata.h +++ b/lib/include/srslte/srslog/detail/log_entry_metadata.h @@ -33,7 +33,7 @@ struct log_context { struct log_entry_metadata { std::chrono::high_resolution_clock::time_point tp; log_context context; - std::string fmtstring; + const char* fmtstring; fmt::dynamic_format_arg_store store; std::string log_name; char log_tag; diff --git a/lib/include/srslte/srslog/detail/support/memory_buffer.h b/lib/include/srslte/srslog/detail/support/memory_buffer.h index 6d85fba25..30e27bdfe 100644 --- a/lib/include/srslte/srslog/detail/support/memory_buffer.h +++ b/lib/include/srslte/srslog/detail/support/memory_buffer.h @@ -28,18 +28,22 @@ class memory_buffer public: memory_buffer(const char* buffer, size_t length) : - buffer(buffer), - length(length) + buffer(buffer), length(length) {} explicit memory_buffer(const std::string& s) : - buffer(s.data()), - length(s.size()) + buffer(s.data()), length(s.size()) {} /// Returns a pointer to the start of the memory block. const char* data() const { return buffer; } + /// Returns an iterator to the beginning of the buffer. + const char* begin() const { return buffer; } + + /// Returns an iterator to the end of the buffer. + const char* end() const { return buffer + length; } + /// Returns the size of the memory block. size_t size() const { return length; } }; diff --git a/lib/include/srslte/srslog/detail/support/work_queue.h b/lib/include/srslte/srslog/detail/support/work_queue.h index 2d2eef3cf..4f1a57d0a 100644 --- a/lib/include/srslte/srslog/detail/support/work_queue.h +++ b/lib/include/srslte/srslog/detail/support/work_queue.h @@ -51,8 +51,8 @@ public: return false; } queue.push(value); - cond_var.signal(); cond_var.unlock(); + cond_var.signal(); return true; } @@ -68,8 +68,8 @@ public: return false; } queue.push(std::move(value)); - cond_var.signal(); cond_var.unlock(); + cond_var.signal(); return true; } diff --git a/lib/include/srslte/srslog/event_trace.h b/lib/include/srslte/srslog/event_trace.h index ad1386745..8b894508a 100644 --- a/lib/include/srslte/srslog/event_trace.h +++ b/lib/include/srslte/srslog/event_trace.h @@ -36,6 +36,13 @@ void event_trace_init(); /// all trace events. void event_trace_init(log_channel& c); +/// Initializes the event trace framework. +/// The event trace data will be written into the specified filename after +/// capacity bytes of data have been generated or at program exit. +/// Returns true on success, otherwise false. +bool event_trace_init(const std::string& filename, + std::size_t capacity = 1024 * 1024); + #ifdef ENABLE_SRSLOG_EVENT_TRACE /// Generates the begin phase of a duration event. @@ -45,8 +52,11 @@ void trace_duration_begin(const std::string& category, const std::string& name); void trace_duration_end(const std::string& category, const std::string& name); /// Generates a complete event. +#define SRSLOG_TRACE_COMBINE1(X, Y) X##Y +#define SRSLOG_TRACE_COMBINE(X, Y) SRSLOG_TRACE_COMBINE1(X, Y) #define trace_complete_event(C, N) \ - auto scoped_complete_event_variable = srslog::detail::scoped_complete_event(C, N) + auto SRSLOG_TRACE_COMBINE(scoped_complete_event, __LINE__) = \ + srslog::detail::scoped_complete_event(C, N) #else @@ -63,17 +73,15 @@ namespace detail { class scoped_complete_event { public: - scoped_complete_event(std::string cat, std::string n) : - category(std::move(cat)), - name(std::move(n)), - start(std::chrono::steady_clock::now()) + scoped_complete_event(const char* cat, const char* n) : + category(cat), name(n), start(std::chrono::steady_clock::now()) {} ~scoped_complete_event(); private: - const std::string category; - const std::string name; + const char* const category; + const char* const name; std::chrono::time_point start; }; diff --git a/lib/include/srslte/srslog/log_channel.h b/lib/include/srslte/srslog/log_channel.h index 0acd80146..8a5cd9678 100644 --- a/lib/include/srslte/srslog/log_channel.h +++ b/lib/include/srslte/srslog/log_channel.h @@ -89,7 +89,7 @@ public: /// Builds the provided log entry and passes it to the backend. When the /// channel is disabled the log entry will be discarded. template - void operator()(const std::string& fmtstr, Args&&... args) + void operator()(const char* fmtstr, Args&&... args) { if (!enabled()) { return; @@ -97,7 +97,8 @@ public: // Populate the store with all incoming arguments. fmt::dynamic_format_arg_store store; - (void)std::initializer_list{(store.push_back(args), 0)...}; + (void)std::initializer_list{ + (store.push_back(std::forward(args)), 0)...}; // Send the log entry to the backend. log_formatter& formatter = log_sink.get_formatter(); @@ -121,7 +122,7 @@ public: template void operator()(const uint8_t* buffer, size_t len, - const std::string& fmtstr, + const char* fmtstr, Args&&... args) { if (!enabled()) { @@ -130,7 +131,8 @@ public: // Populate the store with all incoming arguments. fmt::dynamic_format_arg_store store; - (void)std::initializer_list{(store.push_back(args), 0)...}; + (void)std::initializer_list{ + (store.push_back(std::forward(args)), 0)...}; // Calculate the length to capture in the buffer. if (hex_max_size >= 0) @@ -173,7 +175,7 @@ public: }, {std::chrono::high_resolution_clock::now(), {ctx_value, should_print_context}, - "", + nullptr, {}, log_name, log_tag}}; @@ -183,9 +185,7 @@ public: /// Builds the provided log entry and passes it to the backend. When the /// channel is disabled the log entry will be discarded. template - void operator()(const context& ctx, - const std::string& fmtstr, - Args&&... args) + void operator()(const context& ctx, const char* fmtstr, Args&&... args) { if (!enabled()) { return; @@ -193,7 +193,8 @@ public: // Populate the store with all incoming arguments. fmt::dynamic_format_arg_store store; - (void)std::initializer_list{(store.push_back(args), 0)...}; + (void)std::initializer_list{ + (store.push_back(std::forward(args)), 0)...}; // Send the log entry to the backend. log_formatter& formatter = log_sink.get_formatter(); diff --git a/lib/src/radio/radio.cc b/lib/src/radio/radio.cc index c918e3f46..fbfc68cf7 100644 --- a/lib/src/radio/radio.cc +++ b/lib/src/radio/radio.cc @@ -288,10 +288,13 @@ bool radio::rx_now(rf_buffer_interface& buffer, rf_timestamp_interface& rxd_time if (ratio > 1 && nof_samples > rx_buffer[0].size()) { // This is a corner case that could happen during sample rate change transitions, as it does not have a negative // impact, log it as info. - logger.info(fmt::format("Rx number of samples ({}/{}) exceeds buffer size ({})\n", - buffer.get_nof_samples(), - buffer.get_nof_samples() * ratio, - rx_buffer[0].size())); + fmt::memory_buffer buff; + fmt::format_to(buff, + "Rx number of samples ({}/{}) exceeds buffer size ({})", + buffer.get_nof_samples(), + buffer.get_nof_samples() * ratio, + rx_buffer[0].size()); + logger.info("%s", to_c_str(buff)); // Limit number of samples to receive nof_samples = rx_buffer[0].size(); @@ -406,10 +409,13 @@ bool radio::tx(rf_buffer_interface& buffer, const rf_timestamp_interface& tx_tim if (ratio > 1 && nof_samples * ratio > tx_buffer[0].size()) { // This is a corner case that could happen during sample rate change transitions, as it does not have a negative // impact, log it as info. - logger.info(fmt::format("Tx number of samples ({}/{}) exceeds buffer size ({})\n", - buffer.get_nof_samples(), - buffer.get_nof_samples() * ratio, - tx_buffer[0].size())); + fmt::memory_buffer buff; + fmt::format_to(buff, + "Tx number of samples ({}/{}) exceeds buffer size ({})\n", + buffer.get_nof_samples(), + buffer.get_nof_samples() * ratio, + tx_buffer[0].size()); + logger.info("%s", to_c_str(buff)); // Limit number of samples to transmit nof_samples = tx_buffer[0].size() / ratio; diff --git a/lib/src/srslog/backend_worker.cpp b/lib/src/srslog/backend_worker.cpp index f45721f53..26b63460e 100644 --- a/lib/src/srslog/backend_worker.cpp +++ b/lib/src/srslog/backend_worker.cpp @@ -88,14 +88,11 @@ void backend_worker::process_log_entry(detail::log_entry&& entry) return; } - fmt::memory_buffer fmt_buffer; - assert(entry.format_func && "Invalid format function"); + fmt_buffer.clear(); entry.format_func(std::move(entry.metadata), fmt_buffer); - const auto str = fmt::to_string(fmt_buffer); - detail::memory_buffer buffer(str); - if (auto err_str = entry.s->write(buffer)) { + if (auto err_str = entry.s->write({fmt_buffer.data(), fmt_buffer.size()})) { err_handler(err_str.get_error()); } } diff --git a/lib/src/srslog/backend_worker.h b/lib/src/srslog/backend_worker.h index f697044aa..1dae40a90 100644 --- a/lib/src/srslog/backend_worker.h +++ b/lib/src/srslog/backend_worker.h @@ -111,6 +111,7 @@ private: }; std::once_flag start_once_flag; std::thread worker_thread; + fmt::memory_buffer fmt_buffer; }; } // namespace srslog diff --git a/lib/src/srslog/event_trace.cpp b/lib/src/srslog/event_trace.cpp index e039bfe85..d3bc13328 100644 --- a/lib/src/srslog/event_trace.cpp +++ b/lib/src/srslog/event_trace.cpp @@ -11,6 +11,7 @@ */ #include "srslte/srslog/event_trace.h" +#include "sinks/single_write_file_sink.h" #include "srslte/srslog/srslog.h" #include @@ -23,6 +24,9 @@ using namespace srslog; /// Log channel where event traces will get sent. static log_channel* tracer = nullptr; +/// Tracer sink name. +static constexpr char sink_name[] = "srslog_trace_sink"; + void srslog::event_trace_init() { // Nothing to do if the user previously set a custom channel or this is not @@ -50,6 +54,30 @@ void srslog::event_trace_init(log_channel& c) } } +bool srslog::event_trace_init(const std::string& filename, std::size_t capacity) +{ + // Nothing to do if the user previously set a custom channel or this is not + // the first time this function is called. + if (tracer) { + return false; + } + + auto tracer_sink = std::unique_ptr(new single_write_file_sink( + filename, capacity, get_default_log_formatter())); + if (!install_custom_sink(sink_name, std::move(tracer_sink))) { + return false; + } + + if (sink* s = find_sink(sink_name)) { + log_channel& c = + fetch_log_channel("event_trace_channel", *s, {"TRACE", '\0', false}); + tracer = &c; + return true; + } + + return false; +} + /// Fills in the input buffer with the current time. static void format_time(char* buffer, size_t len) { @@ -104,10 +132,7 @@ srslog::detail::scoped_complete_event::~scoped_complete_event() std::chrono::duration_cast(end - start) .count(); - char fmt_time[24]; - format_time(fmt_time, sizeof(fmt_time)); - (*tracer)("[%s] [TID:%0u] Complete event \"%s\" (duration %lld us): %s", - fmt_time, + (*tracer)("[TID:%0u] Complete event \"%s\" (duration %lld us): %s", (unsigned)::pthread_self(), category, diff, diff --git a/lib/src/srslog/formatters/json_formatter.cpp b/lib/src/srslog/formatters/json_formatter.cpp index f5eb16bd6..8923107cb 100644 --- a/lib/src/srslog/formatters/json_formatter.cpp +++ b/lib/src/srslog/formatters/json_formatter.cpp @@ -49,7 +49,7 @@ void json_formatter::format_context_begin(const detail::log_entry_metadata& md, fmt::format_to(buffer, "{{\n"); push_scope(size); - if (!md.fmtstring.empty()) { + if (md.fmtstring) { fmt::format_to(buffer, " \"log_entry\": \"{}\",\n", fmt::vsprintf(md.fmtstring, std::move(md.store))); diff --git a/lib/src/srslog/formatters/text_formatter.cpp b/lib/src/srslog/formatters/text_formatter.cpp index ae313607c..82d74e0ea 100644 --- a/lib/src/srslog/formatters/text_formatter.cpp +++ b/lib/src/srslog/formatters/text_formatter.cpp @@ -90,13 +90,16 @@ void text_formatter::format_context_begin(const detail::log_entry_metadata& md, unsigned size, fmt::memory_buffer& buffer) { - do_one_line_ctx_format = !md.fmtstring.empty(); + // Entries without a log message are printed using a richer format. + do_one_line_ctx_format = md.fmtstring; format_metadata(md, buffer); if (do_one_line_ctx_format) { + assert(scope_stack.empty() && "Stack should be empty"); fmt::format_to(buffer, "["); return; } + fmt::format_to(buffer, "Context dump for \"{}\"\n", ctx_name); } @@ -104,10 +107,12 @@ void text_formatter::format_context_end(const detail::log_entry_metadata& md, const std::string& ctx_name, fmt::memory_buffer& buffer) { - if (do_one_line_ctx_format) { - fmt::format_to(buffer, "]: {}\n", fmt::vsprintf(md.fmtstring, md.store)); + if (!do_one_line_ctx_format) { return; } + + fmt::format_to(buffer, "]: {}\n", fmt::vsprintf(md.fmtstring, md.store)); + assert(scope_stack.empty() && "Stack should be empty"); } void text_formatter::format_metric_set_begin(const std::string& set_name, @@ -115,21 +120,26 @@ void text_formatter::format_metric_set_begin(const std::string& set_name, unsigned level, fmt::memory_buffer& buffer) { - /*if (do_one_line_ctx_format) { - fmt::format_to(buffer, "{}", is_first ? "[" : " ["); + if (do_one_line_ctx_format) { + scope_stack.emplace_back(size, set_name); + fmt::format_to(buffer, "["); return; } - fmt::format_to(buffer, " {}\n", set_name);*/ + + fmt::format_to( + buffer, "{: <{}}> Set: {}\n", ' ', get_indents(level), set_name); } void text_formatter::format_metric_set_end(const std::string& set_name, unsigned level, fmt::memory_buffer& buffer) { - if (do_one_line_ctx_format) { - fmt::format_to(buffer, "]"); + if (!do_one_line_ctx_format) { return; } + + scope_stack.pop_back(); + fmt::format_to(buffer, "]"); } void text_formatter::format_metric(const std::string& metric_name, @@ -139,22 +149,37 @@ void text_formatter::format_metric(const std::string& metric_name, unsigned level, fmt::memory_buffer& buffer) { - //:TODO: re-enable - /*if (do_one_line_ctx_format) { + if (do_one_line_ctx_format) { + consume_element(); fmt::format_to(buffer, - "{}{}_{}: {}{}{}", - ctx.is_first_metric ? "" : ", ", - ctx.set_name, - ctx.metric_name, - ctx.metric_value, - ctx.metric_units.empty() ? "" : " ", - ctx.metric_units); + "{}_{}: {}{}{}{}", + get_current_set_name(), + metric_name, + metric_value, + metric_units.empty() ? "" : " ", + metric_units, + needs_comma() ? ", " : ""); return; } + fmt::format_to(buffer, - " {}: {}{}{}\n", - ctx.metric_name, - ctx.metric_value, - ctx.metric_units.empty() ? "" : " ", - ctx.metric_units);*/ + "{: <{}}{}: {}{}{}\n", + ' ', + get_indents(level), + metric_name, + metric_value, + metric_units.empty() ? "" : " ", + metric_units); +} + +void text_formatter::format_list_begin(const std::string& list_name, + unsigned size, + unsigned level, + fmt::memory_buffer& buffer) +{ + if (do_one_line_ctx_format) { + return; + } + fmt::format_to( + buffer, "{: <{}}> List: {}\n", ' ', get_indents(level), list_name); } diff --git a/lib/src/srslog/formatters/text_formatter.h b/lib/src/srslog/formatters/text_formatter.h index b8dcf32cd..336ad326a 100644 --- a/lib/src/srslog/formatters/text_formatter.h +++ b/lib/src/srslog/formatters/text_formatter.h @@ -18,11 +18,11 @@ namespace srslog { /// Plain text formatter implementation class. -//:TODO: this class needs refactoring to be compatible with multiple nesting of -// metrics. class text_formatter : public log_formatter { public: + text_formatter() { scope_stack.reserve(16); } + std::unique_ptr clone() const override; void format(detail::log_entry_metadata&& metadata, @@ -50,17 +50,12 @@ private: void format_list_begin(const std::string& list_name, unsigned size, unsigned level, - fmt::memory_buffer& buffer) override - { - //:TODO: implement me - } + fmt::memory_buffer& buffer) override; void format_list_end(const std::string& list_name, unsigned level, fmt::memory_buffer& buffer) override - { - //:TODO: implement me - } + {} void format_metric(const std::string& metric_name, const std::string& metric_value, @@ -69,9 +64,47 @@ private: unsigned level, fmt::memory_buffer& buffer) override; + /// Returns the set name of current scope. + const std::string& get_current_set_name() const + { + assert(!scope_stack.empty() && "Empty scope stack"); + return scope_stack.back().set_name; + } + + /// Consumes an element in the current scope. + void consume_element() + { + assert(!scope_stack.empty() && "Consuming element in void scope"); + assert(scope_stack.back().size && "No more elements to consume"); + --scope_stack.back().size; + } + + /// Returns true if the current element needs a comma. + bool needs_comma() const + { + assert(!scope_stack.empty() && "No scope exists"); + return scope_stack.back().size; + } + + /// Returns the number of indentations required for the input nesting level. + unsigned get_indents(unsigned level) const { return level * 2; } + +private: + /// Keeps track of some state required for formatting. + struct scope { + scope(unsigned size, std::string set_name) : + size(size), set_name(std::move(set_name)) + {} + /// Number of elements this scope holds. + unsigned size; + /// Set name in this scope. + std::string set_name; + }; + private: /// Flags that the formatting should take place into a single line. bool do_one_line_ctx_format = false; + std::vector scope_stack; }; } // namespace srslog diff --git a/lib/src/srslog/sinks/file_sink.h b/lib/src/srslog/sinks/file_sink.h index 3e7c085fd..fe61e09eb 100644 --- a/lib/src/srslog/sinks/file_sink.h +++ b/lib/src/srslog/sinks/file_sink.h @@ -28,8 +28,8 @@ public: size_t max_size, std::unique_ptr f) : sink(std::move(f)), - base_filename(std::move(name)), - max_size((max_size == 0) ? 0 : std::max(max_size, 4 * 1024)) + max_size((max_size == 0) ? 0 : std::max(max_size, 4 * 1024)), + base_filename(std::move(name)) {} file_sink(const file_sink& other) = delete; diff --git a/lib/src/srslog/sinks/single_write_file_sink.h b/lib/src/srslog/sinks/single_write_file_sink.h new file mode 100644 index 000000000..37485e9e0 --- /dev/null +++ b/lib/src/srslog/sinks/single_write_file_sink.h @@ -0,0 +1,90 @@ +/** + * + * \section COPYRIGHT + * + * Copyright 2013-2020 Software Radio Systems Limited + * + * By using this file, you agree to the terms and conditions set + * forth in the LICENSE file which can be found at the top level of + * the distribution. + * + */ + +#ifndef SRSLOG_SINGLE_WRITE_FILE_SINK_H +#define SRSLOG_SINGLE_WRITE_FILE_SINK_H + +#include "file_utils.h" +#include "srslte/srslog/sink.h" + +namespace srslog { + +/// This class is a wrapper of a file handle that stores the input data into an +/// internal buffer and writes its contents to the file once the buffer is full +/// or in object destruction. +class single_write_file_sink : public sink +{ +public: + single_write_file_sink(std::string filename, + std::size_t capacity, + std::unique_ptr f) : + sink(std::move(f)), filename(std::move(filename)) + { + buffer.reserve(capacity); + } + + ~single_write_file_sink() override + { + if (!is_written) { + write_contents(); + } + } + + single_write_file_sink(const single_write_file_sink& other) = delete; + single_write_file_sink& + operator=(const single_write_file_sink& other) = delete; + + detail::error_string write(detail::memory_buffer input_buffer) override + { + // Nothing to do when the contents have been already written. + if (is_written) { + return {}; + } + + if (has_room_for(input_buffer.size())) { + buffer.insert(buffer.end(), input_buffer.begin(), input_buffer.end()); + return {}; + } + + return write_contents(); + } + + detail::error_string flush() override { return handler.flush(); } + +private: + /// Returns true if the internal buffer has room for the specified input size, + /// otherwise returns false. + bool has_room_for(std::size_t s) const + { + return s + buffer.size() < buffer.capacity(); + } + + /// Writes the buffer contents into the file. + detail::error_string write_contents() + { + is_written = true; + if (auto err_str = handler.create(filename)) { + return err_str; + } + return handler.write(detail::memory_buffer(buffer.data(), buffer.size())); + } + +private: + const std::string filename; + file_utils::file handler; + std::vector buffer; + bool is_written = false; +}; + +} // namespace srslog + +#endif // SRSLOG_SINGLE_WRITE_FILE_SINK_H diff --git a/lib/test/srslog/CMakeLists.txt b/lib/test/srslog/CMakeLists.txt index 7209b87df..b87eb04aa 100644 --- a/lib/test/srslog/CMakeLists.txt +++ b/lib/test/srslog/CMakeLists.txt @@ -42,11 +42,10 @@ add_definitions(-DENABLE_SRSLOG_EVENT_TRACE) target_link_libraries(tracer_test srslog) add_test(tracer_test tracer_test) -#:TODO: re-enable test. -#add_executable(text_formatter_test text_formatter_test.cpp) -#target_include_directories(text_formatter_test PUBLIC ../../) -#target_link_libraries(text_formatter_test srslog) -#add_test(text_formatter_test text_formatter_test) +add_executable(text_formatter_test text_formatter_test.cpp) +target_include_directories(text_formatter_test PUBLIC ../../) +target_link_libraries(text_formatter_test srslog) +add_test(text_formatter_test text_formatter_test) add_executable(json_formatter_test json_formatter_test.cpp) target_include_directories(json_formatter_test PUBLIC ../../) diff --git a/lib/test/srslog/json_formatter_test.cpp b/lib/test/srslog/json_formatter_test.cpp index 33bbd84dc..e10f1028c 100644 --- a/lib/test/srslog/json_formatter_test.cpp +++ b/lib/test/srslog/json_formatter_test.cpp @@ -82,7 +82,7 @@ static bool when_log_entry_with_only_basic_context_is_passed_then_context_is_formatted() { auto entry = build_log_entry_metadata(); - entry.fmtstring = ""; + entry.fmtstring = nullptr; basic_ctx_t ctx("UL Context"); ctx.get().write(-55.1); @@ -173,7 +173,7 @@ when_log_entry_with_only_complex_context_is_passed_then_context_is_formatted() { complex_ctx_t ctx("UL Context"); auto entry = build_log_entry_metadata(); - entry.fmtstring = ""; + entry.fmtstring = nullptr; ctx.get().emplace_back(); ctx.at(0).get().emplace_back(); @@ -260,7 +260,7 @@ static bool when_context_with_empty_list_is_passed_then_list_object_is_empty() { list_ctx_t ctx("UL Context"); auto entry = build_log_entry_metadata(); - entry.fmtstring = ""; + entry.fmtstring = nullptr; fmt::memory_buffer buffer; json_formatter{}.format_ctx(ctx, std::move(entry), buffer); diff --git a/lib/test/srslog/log_channel_test.cpp b/lib/test/srslog/log_channel_test.cpp index 8d7ec523d..1ccb6f2d5 100644 --- a/lib/test/srslog/log_channel_test.cpp +++ b/lib/test/srslog/log_channel_test.cpp @@ -89,8 +89,7 @@ when_logging_in_log_channel_then_log_entry_is_pushed_into_the_backend() test_dummies::sink_dummy s; log_channel log("id", s, backend); - std::string fmtstring = "test"; - log(fmtstring, 42, "Hello"); + log("test", 42, "Hello"); ASSERT_EQ(backend.push_invocation_count(), 1); @@ -104,8 +103,7 @@ static bool when_logging_in_disabled_log_channel_then_log_entry_is_ignored() log_channel log("id", s, backend); log.set_enabled(false); - std::string fmtstring = "test"; - log(fmtstring, 42, "Hello"); + log("test", 42, "Hello"); ASSERT_EQ(backend.push_invocation_count(), 0); @@ -122,11 +120,10 @@ static bool when_logging_then_filled_in_log_entry_is_pushed_into_the_backend() log_channel log("id", s, backend, {name, tag, true}); - std::string fmtstring = "test"; uint32_t ctx = 10; log.set_context(ctx); - log(fmtstring, 42, "Hello"); + log("test", 42, "Hello"); ASSERT_EQ(backend.push_invocation_count(), 1); @@ -136,7 +133,7 @@ static bool when_logging_then_filled_in_log_entry_is_pushed_into_the_backend() ASSERT_NE(entry.metadata.tp.time_since_epoch().count(), 0); ASSERT_EQ(entry.metadata.context.value, ctx); ASSERT_EQ(entry.metadata.context.enabled, true); - ASSERT_EQ(entry.metadata.fmtstring, fmtstring); + ASSERT_EQ(entry.metadata.fmtstring, std::string("test")); ASSERT_EQ(entry.metadata.log_name, name); ASSERT_EQ(entry.metadata.log_tag, tag); ASSERT_EQ(entry.metadata.hex_dump.empty(), true); @@ -155,13 +152,12 @@ when_logging_with_hex_dump_then_filled_in_log_entry_is_pushed_into_the_backend() log_channel log("id", s, backend, {name, tag, true}); - std::string fmtstring = "test"; uint32_t ctx = 4; log.set_context(ctx); log.set_hex_dump_max_size(4); uint8_t hex[] = {0, 1, 2, 3, 4, 5, 6, 7, 8}; - log(hex, sizeof(hex), fmtstring, 42, "Hello"); + log(hex, sizeof(hex), "test", 42, "Hello"); ASSERT_EQ(backend.push_invocation_count(), 1); @@ -171,7 +167,7 @@ when_logging_with_hex_dump_then_filled_in_log_entry_is_pushed_into_the_backend() ASSERT_NE(entry.metadata.tp.time_since_epoch().count(), 0); ASSERT_EQ(entry.metadata.context.value, ctx); ASSERT_EQ(entry.metadata.context.enabled, true); - ASSERT_EQ(entry.metadata.fmtstring, fmtstring); + ASSERT_EQ(entry.metadata.fmtstring, std::string("test")); ASSERT_EQ(entry.metadata.log_name, name); ASSERT_EQ(entry.metadata.log_tag, tag); ASSERT_EQ(entry.metadata.hex_dump.size(), 4); @@ -193,11 +189,9 @@ when_hex_array_length_is_less_than_hex_log_max_size_then_array_length_is_used() log_channel log("id", s, backend); - std::string fmtstring = "test"; - log.set_hex_dump_max_size(10); uint8_t hex[] = {0, 1, 2}; - log(hex, sizeof(hex), fmtstring, 42, "Hello"); + log(hex, sizeof(hex), "test", 42, "Hello"); ASSERT_EQ(backend.push_invocation_count(), 1); @@ -264,10 +258,9 @@ when_logging_with_context_and_message_then_filled_in_log_entry_is_pushed_into_th uint32_t ctx_value = 4; log.set_context(ctx_value); - std::string fmtstring = "test"; my_ctx ctx("myctx"); - log(ctx, fmtstring, 10, 3.3); + log(ctx, "test", 10, 3.3); ASSERT_EQ(backend.push_invocation_count(), 1); @@ -277,7 +270,7 @@ when_logging_with_context_and_message_then_filled_in_log_entry_is_pushed_into_th ASSERT_NE(entry.metadata.tp.time_since_epoch().count(), 0); ASSERT_EQ(entry.metadata.context.value, ctx_value); ASSERT_EQ(entry.metadata.context.enabled, true); - ASSERT_EQ(entry.metadata.fmtstring, fmtstring); + ASSERT_EQ(entry.metadata.fmtstring, std::string("test")); ASSERT_EQ(entry.metadata.log_name, name); ASSERT_EQ(entry.metadata.log_tag, tag); ASSERT_EQ(entry.metadata.hex_dump.empty(), true); diff --git a/lib/test/srslog/text_formatter_test.cpp b/lib/test/srslog/text_formatter_test.cpp index fa20f56e1..3d0e008f5 100644 --- a/lib/test/srslog/text_formatter_test.cpp +++ b/lib/test/srslog/text_formatter_test.cpp @@ -110,41 +110,120 @@ static bool when_log_entry_with_hex_dump_is_passed_then_hex_dump_is_formatted() namespace { DECLARE_METRIC("SNR", snr_t, float, "dB"); DECLARE_METRIC("PWR", pwr_t, int, "dBm"); -DECLARE_METRIC("CenterFreq", cfreq_t, unsigned, "MHz"); -DECLARE_METRIC_SET("RF", myset1, snr_t, pwr_t, cfreq_t); +DECLARE_METRIC_SET("RF", rf_set, snr_t, pwr_t); DECLARE_METRIC("Throughput", thr_t, float, "MB/s"); DECLARE_METRIC("Address", ip_addr_t, std::string, ""); -DECLARE_METRIC_SET("Network", myset2, thr_t, ip_addr_t); +DECLARE_METRIC_LIST("Antennas", antenna_list_t, std::vector); +DECLARE_METRIC_SET("ue_container", ue_set, thr_t, ip_addr_t, antenna_list_t); -using ctx_t = srslog::build_context_type; +DECLARE_METRIC("type", entry_type_t, std::string, ""); +DECLARE_METRIC("sector_id", sector_id_t, unsigned, ""); +DECLARE_METRIC_LIST("ue_list", ue_list_t, std::vector); +DECLARE_METRIC_SET("sector_metrics", + sector_set, + entry_type_t, + sector_id_t, + ue_list_t); + +DECLARE_METRIC_LIST("sector_list", sector_list_t, std::vector); + +using complex_ctx_t = srslog::build_context_type; } // namespace +/// Builds an instance of a complex context object filled in with some random +/// data. +static complex_ctx_t build_complex_context() +{ + complex_ctx_t ctx("Complex Context"); + + ctx.get().emplace_back(); + ctx.at(0).write("event"); + ctx.at(0).write(1); + + ctx.at(0).get().emplace_back(); + ctx.at(0).at(0).write(1.2); + ctx.at(0).at(0).write("10.20.30.40"); + + ctx.at(0).get().emplace_back(); + ctx.at(0).at(1).write(10.2); + ctx.at(0).at(1).write("10.20.30.41"); + + ctx.at(0) + .at(0) + .get() + .emplace_back(); + ctx.at(0).at(0).at(0).write( + 5.1); + ctx.at(0).at(0).at(0).write( + -11.5); + + ctx.at(0) + .at(0) + .get() + .emplace_back(); + ctx.at(0).at(0).at(1).write( + 10.1); + ctx.at(0).at(0).at(1).write( + -20.5); + + ctx.at(0) + .at(1) + .get() + .emplace_back(); + ctx.at(0).at(1).at(0).write( + 20.1); + ctx.at(0).at(1).at(0).write( + -30.5); + ctx.at(0) + .at(1) + .get() + .emplace_back(); + ctx.at(0).at(1).at(1).write( + 30.1); + ctx.at(0).at(1).at(1).write( + -40.5); + + return ctx; +} + static bool when_log_entry_with_only_context_is_passed_then_context_is_formatted() { + auto ctx = build_complex_context(); auto entry = build_log_entry_metadata(); - entry.fmtstring = ""; - ctx_t ctx("UL Context"); - - ctx.get().write(-55.1); - ctx.get().write(-10); - ctx.get().write(1500); - ctx.get().write(150.01); - ctx.get().write("192.168.1.0"); + entry.fmtstring = nullptr; fmt::memory_buffer buffer; text_formatter{}.format_ctx(ctx, std::move(entry), buffer); std::string result = fmt::to_string(buffer); - std::string expected = - "00:00:00.050000 [ABC ] [Z] [ 10] Context dump for \"UL Context\"\n" - " RF\n" - " SNR: -55.1 dB\n" - " PWR: -10 dBm\n" - " CenterFreq: 1500 MHz\n" - " Network\n" - " Throughput: 150.01 MB/s\n" - " Address: 192.168.1.0\n"; + std::string expected = "00:00:00.050000 [ABC ] [Z] [ 10] Context dump for " + "\"Complex Context\"\n" + " > List: sector_list\n" + " > Set: sector_metrics\n" + " type: event\n" + " sector_id: 1\n" + " > List: ue_list\n" + " > Set: ue_container\n" + " Throughput: 1.2 MB/s\n" + " Address: 10.20.30.40\n" + " > List: Antennas\n" + " > Set: RF\n" + " SNR: 5.1 dB\n" + " PWR: -11 dBm\n" + " > Set: RF\n" + " SNR: 10.1 dB\n" + " PWR: -20 dBm\n" + " > Set: ue_container\n" + " Throughput: 10.2 MB/s\n" + " Address: 10.20.30.41\n" + " > List: Antennas\n" + " > Set: RF\n" + " SNR: 20.1 dB\n" + " PWR: -30 dBm\n" + " > Set: RF\n" + " SNR: 30.1 dB\n" + " PWR: -40 dBm\n"; ASSERT_EQ(result, expected); @@ -155,21 +234,18 @@ static bool when_log_entry_with_context_and_message_is_passed_then_context_is_formatted() { auto entry = build_log_entry_metadata(); - ctx_t ctx("UL Context"); - - ctx.get().write(-55.1); - ctx.get().write(-10); - ctx.get().write(1500); - ctx.get().write(150.01); - ctx.get().write("192.168.1.0"); + auto ctx = build_complex_context(); fmt::memory_buffer buffer; text_formatter{}.format_ctx(ctx, std::move(entry), buffer); std::string result = fmt::to_string(buffer); std::string expected = - "00:00:00.050000 [ABC ] [Z] [ 10] [[RF_SNR: -55.1 dB, RF_PWR: -10 dBm, " - "RF_CenterFreq: 1500 MHz] [Network_Throughput: 150.01 MB/s, " - "Network_Address: 192.168.1.0]]: Text 88\n"; + "00:00:00.050000 [ABC ] [Z] [ 10] [[sector_metrics_type: event, " + "sector_metrics_sector_id: 1, [ue_container_Throughput: 1.2 MB/s, " + "ue_container_Address: 10.20.30.40, [RF_SNR: 5.1 dB, RF_PWR: -11 " + "dBm][RF_SNR: 10.1 dB, RF_PWR: -20 dBm]][ue_container_Throughput: 10.2 " + "MB/s, ue_container_Address: 10.20.30.41, [RF_SNR: 20.1 dB, RF_PWR: -30 " + "dBm][RF_SNR: 30.1 dB, RF_PWR: -40 dBm]]]]: Text 88\n"; ASSERT_EQ(result, expected); diff --git a/srsenb/enb.conf.example b/srsenb/enb.conf.example index 805daa29c..90a7f07da 100644 --- a/srsenb/enb.conf.example +++ b/srsenb/enb.conf.example @@ -296,6 +296,7 @@ enable = false # metrics_csv_filename: File path to use for CSV metrics. # tracing_enable: Write source code tracing information to a file. # tracing_filename: File path to use for tracing information. +# tracing_buffcapacity: Maximum capacity in bytes the tracing framework can store. # pregenerate_signals: Pregenerate uplink signals after attach. Improves CPU performance. # tx_amplitude: Transmit amplitude factor (set 0-1 to reduce PAPR) # rrc_inactivity_timer Inactivity timeout used to remove UE context from RRC (in milliseconds). @@ -317,6 +318,7 @@ enable = false #alarms_filename = /tmp/enb_alarms.log #tracing_enable = true #tracing_filename = /tmp/enb_tracing.log +#tracing_buffcapacity = 1000000 #pregenerate_signals = false #tx_amplitude = 0.6 #rrc_inactivity_timer = 30000 diff --git a/srsenb/hdr/enb.h b/srsenb/hdr/enb.h index e6c8c020b..9a389ad5d 100644 --- a/srsenb/hdr/enb.h +++ b/srsenb/hdr/enb.h @@ -31,7 +31,6 @@ #include "srsenb/hdr/stack/enb_stack_base.h" #include "srsenb/hdr/stack/rrc/rrc_config.h" -#include "srslte/system/sys_metrics_processor.h" #include "srslte/common/bcd_helpers.h" #include "srslte/common/buffer_pool.h" #include "srslte/common/interfaces_common.h" @@ -43,6 +42,7 @@ #include "srslte/interfaces/sched_interface.h" #include "srslte/interfaces/ue_interfaces.h" #include "srslte/srslog/srslog.h" +#include "srslte/system/sys_metrics_processor.h" namespace srsenb { @@ -90,6 +90,7 @@ struct general_args_t { std::string alarms_filename; bool print_buffer_state; bool tracing_enable; + std::size_t tracing_buffcapacity; std::string tracing_filename; std::string eia_pref_list; std::string eea_pref_list; diff --git a/srsenb/src/main.cc b/srsenb/src/main.cc index 1e5072347..64b9e5291 100644 --- a/srsenb/src/main.cc +++ b/srsenb/src/main.cc @@ -210,6 +210,7 @@ void parse_args(all_args_t* args, int argc, char* argv[]) ("expert.alarms_filename", bpo::value(&args->general.alarms_filename)->default_value("/tmp/enb_alarms.log"), "Alarms filename") ("expert.tracing_enable", bpo::value(&args->general.tracing_enable)->default_value(false), "Events tracing") ("expert.tracing_filename", bpo::value(&args->general.tracing_filename)->default_value("/tmp/enb_tracing.log"), "Tracing events filename") + ("expert.tracing_buffcapacity", bpo::value(&args->general.tracing_buffcapacity)->default_value(1000000), "Tracing buffer capcity") ("expert.rrc_inactivity_timer", bpo::value(&args->general.rrc_inactivity_timer)->default_value(30000), "Inactivity timer in ms.") ("expert.print_buffer_state", bpo::value(&args->general.print_buffer_state)->default_value(false), "Prints on the console the buffer state every 10 seconds") ("expert.eea_pref_list", bpo::value(&args->general.eea_pref_list)->default_value("EEA0, EEA2, EEA1"), "Ordered preference list for the selection of encryption algorithm (EEA) (default: EEA0, EEA2, EEA1).") @@ -506,9 +507,9 @@ int main(int argc, char* argv[]) #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); + if (!srslog::event_trace_init(args.general.tracing_filename, args.general.tracing_buffcapacity)) { + return SRSLTE_ERROR; + } } #endif diff --git a/srsue/hdr/ue.h b/srsue/hdr/ue.h index 5d9e86f0a..9fde96bd4 100644 --- a/srsue/hdr/ue.h +++ b/srsue/hdr/ue.h @@ -64,6 +64,7 @@ typedef struct { std::string metrics_csv_filename; bool tracing_enable; std::string tracing_filename; + std::size_t tracing_buffcapacity; } general_args_t; typedef struct { diff --git a/srsue/src/main.cc b/srsue/src/main.cc index 99f61467a..9c44861bb 100644 --- a/srsue/src/main.cc +++ b/srsue/src/main.cc @@ -428,6 +428,10 @@ static int parse_args(all_args_t* args, int argc, char* argv[]) bpo::value(&args->general.tracing_filename)->default_value("/tmp/ue_tracing.log"), "Tracing events filename") + ("general.tracing_buffcapacity", + bpo::value(&args->general.tracing_buffcapacity)->default_value(1000000), + "Tracing buffer capcity") + ("stack.have_tti_time_stats", bpo::value(&args->stack.have_tti_time_stats)->default_value(true), "Calculate TTI execution statistics") @@ -653,9 +657,9 @@ int main(int argc, char* argv[]) #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); + if (!srslog::event_trace_init(args.general.tracing_filename, args.general.tracing_buffcapacity)) { + return SRSLTE_ERROR; + } } #endif diff --git a/srsue/src/stack/mac_nr/proc_ra_nr.cc b/srsue/src/stack/mac_nr/proc_ra_nr.cc index 6d568058f..9fdbc7a24 100644 --- a/srsue/src/stack/mac_nr/proc_ra_nr.cc +++ b/srsue/src/stack/mac_nr/proc_ra_nr.cc @@ -181,7 +181,7 @@ void proc_ra_nr::ra_response_reception(const mac_interface_phy_nr::mac_nr_grant_ logger.warning("Error unpacking RAR PDU (%d)", i); return; } - logger.info(pdu.to_string()); + logger.info("%s", pdu.to_string()); for (auto& subpdu : pdu.get_subpdus()) { if (subpdu.has_rapid() && subpdu.get_rapid() == preamble_index) { diff --git a/srsue/ue.conf.example b/srsue/ue.conf.example index 2f08a9485..9b329182d 100644 --- a/srsue/ue.conf.example +++ b/srsue/ue.conf.example @@ -381,6 +381,8 @@ enable = false # # tracing_filename: File path to use for tracing information. # +# tracing_buffcapacity: Maximum capacity in bytes the tracing framework can store. +# # have_tti_time_stats: Calculate TTI execution statistics using system clock # ##################################################################### @@ -391,3 +393,4 @@ enable = false #have_tti_time_stats = true #tracing_enable = true #tracing_filename = /tmp/ue_tracing.log +#tracing_buffcapacity = 1000000