- 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.
master
faluco 4 years ago committed by Ismael Gomez
parent 60cd649b8f
commit 173dcdd421

@ -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<fmt::printf_context> store;
std::string log_name;
char log_tag;

@ -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; }
};

@ -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;
}

@ -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<std::chrono::steady_clock> start;
};

@ -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 <typename... Args>
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<fmt::printf_context> store;
(void)std::initializer_list<int>{(store.push_back(args), 0)...};
(void)std::initializer_list<int>{
(store.push_back(std::forward<Args>(args)), 0)...};
// Send the log entry to the backend.
log_formatter& formatter = log_sink.get_formatter();
@ -121,7 +122,7 @@ public:
template <typename... Args>
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<fmt::printf_context> store;
(void)std::initializer_list<int>{(store.push_back(args), 0)...};
(void)std::initializer_list<int>{
(store.push_back(std::forward<Args>(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 <typename... Ts, typename... Args>
void operator()(const context<Ts...>& ctx,
const std::string& fmtstr,
Args&&... args)
void operator()(const context<Ts...>& 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<fmt::printf_context> store;
(void)std::initializer_list<int>{(store.push_back(args), 0)...};
(void)std::initializer_list<int>{
(store.push_back(std::forward<Args>(args)), 0)...};
// Send the log entry to the backend.
log_formatter& formatter = log_sink.get_formatter();

@ -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",
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()));
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",
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()));
tx_buffer[0].size());
logger.info("%s", to_c_str(buff));
// Limit number of samples to transmit
nof_samples = tx_buffer[0].size() / ratio;

@ -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());
}
}

@ -111,6 +111,7 @@ private:
};
std::once_flag start_once_flag;
std::thread worker_thread;
fmt::memory_buffer fmt_buffer;
};
} // namespace srslog

@ -11,6 +11,7 @@
*/
#include "srslte/srslog/event_trace.h"
#include "sinks/single_write_file_sink.h"
#include "srslte/srslog/srslog.h"
#include <ctime>
@ -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<sink>(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<std::chrono::microseconds>(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,

@ -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)));

@ -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);
}

@ -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<log_formatter> 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> scope_stack;
};
} // namespace srslog

@ -28,8 +28,8 @@ public:
size_t max_size,
std::unique_ptr<log_formatter> f) :
sink(std::move(f)),
base_filename(std::move(name)),
max_size((max_size == 0) ? 0 : std::max<size_t>(max_size, 4 * 1024))
max_size((max_size == 0) ? 0 : std::max<size_t>(max_size, 4 * 1024)),
base_filename(std::move(name))
{}
file_sink(const file_sink& other) = delete;

@ -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<log_formatter> 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<char> buffer;
bool is_written = false;
};
} // namespace srslog
#endif // SRSLOG_SINGLE_WRITE_FILE_SINK_H

@ -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 ../../)

@ -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<myset1>().write<snr_t>(-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<sector_list_t>().emplace_back();
ctx.at<sector_list_t>(0).get<ue_list_t>().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);

@ -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);

@ -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<rf_set>);
DECLARE_METRIC_SET("ue_container", ue_set, thr_t, ip_addr_t, antenna_list_t);
using ctx_t = srslog::build_context_type<myset1, myset2>;
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<ue_set>);
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<sector_set>);
using complex_ctx_t = srslog::build_context_type<sector_list_t>;
} // 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<sector_list_t>().emplace_back();
ctx.at<sector_list_t>(0).write<entry_type_t>("event");
ctx.at<sector_list_t>(0).write<sector_id_t>(1);
ctx.at<sector_list_t>(0).get<ue_list_t>().emplace_back();
ctx.at<sector_list_t>(0).at<ue_list_t>(0).write<thr_t>(1.2);
ctx.at<sector_list_t>(0).at<ue_list_t>(0).write<ip_addr_t>("10.20.30.40");
ctx.at<sector_list_t>(0).get<ue_list_t>().emplace_back();
ctx.at<sector_list_t>(0).at<ue_list_t>(1).write<thr_t>(10.2);
ctx.at<sector_list_t>(0).at<ue_list_t>(1).write<ip_addr_t>("10.20.30.41");
ctx.at<sector_list_t>(0)
.at<ue_list_t>(0)
.get<antenna_list_t>()
.emplace_back();
ctx.at<sector_list_t>(0).at<ue_list_t>(0).at<antenna_list_t>(0).write<snr_t>(
5.1);
ctx.at<sector_list_t>(0).at<ue_list_t>(0).at<antenna_list_t>(0).write<pwr_t>(
-11.5);
ctx.at<sector_list_t>(0)
.at<ue_list_t>(0)
.get<antenna_list_t>()
.emplace_back();
ctx.at<sector_list_t>(0).at<ue_list_t>(0).at<antenna_list_t>(1).write<snr_t>(
10.1);
ctx.at<sector_list_t>(0).at<ue_list_t>(0).at<antenna_list_t>(1).write<pwr_t>(
-20.5);
ctx.at<sector_list_t>(0)
.at<ue_list_t>(1)
.get<antenna_list_t>()
.emplace_back();
ctx.at<sector_list_t>(0).at<ue_list_t>(1).at<antenna_list_t>(0).write<snr_t>(
20.1);
ctx.at<sector_list_t>(0).at<ue_list_t>(1).at<antenna_list_t>(0).write<pwr_t>(
-30.5);
ctx.at<sector_list_t>(0)
.at<ue_list_t>(1)
.get<antenna_list_t>()
.emplace_back();
ctx.at<sector_list_t>(0).at<ue_list_t>(1).at<antenna_list_t>(1).write<snr_t>(
30.1);
ctx.at<sector_list_t>(0).at<ue_list_t>(1).at<antenna_list_t>(1).write<pwr_t>(
-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<myset1>().write<snr_t>(-55.1);
ctx.get<myset1>().write<pwr_t>(-10);
ctx.get<myset1>().write<cfreq_t>(1500);
ctx.get<myset2>().write<thr_t>(150.01);
ctx.get<myset2>().write<ip_addr_t>("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<myset1>().write<snr_t>(-55.1);
ctx.get<myset1>().write<pwr_t>(-10);
ctx.get<myset1>().write<cfreq_t>(1500);
ctx.get<myset2>().write<thr_t>(150.01);
ctx.get<myset2>().write<ip_addr_t>("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);

@ -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

@ -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;

@ -210,6 +210,7 @@ void parse_args(all_args_t* args, int argc, char* argv[])
("expert.alarms_filename", bpo::value<string>(&args->general.alarms_filename)->default_value("/tmp/enb_alarms.log"), "Alarms filename")
("expert.tracing_enable", bpo::value<bool>(&args->general.tracing_enable)->default_value(false), "Events tracing")
("expert.tracing_filename", bpo::value<string>(&args->general.tracing_filename)->default_value("/tmp/enb_tracing.log"), "Tracing events filename")
("expert.tracing_buffcapacity", bpo::value<std::size_t>(&args->general.tracing_buffcapacity)->default_value(1000000), "Tracing buffer capcity")
("expert.rrc_inactivity_timer", bpo::value<uint32_t>(&args->general.rrc_inactivity_timer)->default_value(30000), "Inactivity timer in ms.")
("expert.print_buffer_state", bpo::value<bool>(&args->general.print_buffer_state)->default_value(false), "Prints on the console the buffer state every 10 seconds")
("expert.eea_pref_list", bpo::value<string>(&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

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

@ -428,6 +428,10 @@ static int parse_args(all_args_t* args, int argc, char* argv[])
bpo::value<string>(&args->general.tracing_filename)->default_value("/tmp/ue_tracing.log"),
"Tracing events filename")
("general.tracing_buffcapacity",
bpo::value<std::size_t>(&args->general.tracing_buffcapacity)->default_value(1000000),
"Tracing buffer capcity")
("stack.have_tti_time_stats",
bpo::value<bool>(&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

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

@ -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

Loading…
Cancel
Save