From 6fb81c7619eb3f13a98bc5787c3082aa5d57f9e7 Mon Sep 17 00:00:00 2001 From: faluco Date: Mon, 10 May 2021 16:33:40 +0200 Subject: [PATCH] - Add a mutex with priority inheritance for srslog internal structures. - Replace shared_variable members in log_channel class in favor of atomics. - Remove the small string optimization in srslog now that we dont allocate anymore. - Trim some critical sections in srslog. --- .../srsran/srslog/detail/log_entry_metadata.h | 4 -- .../detail/support/dyn_arg_store_pool.h | 2 +- .../srslog/detail/support/thread_utils.h | 9 ++- lib/include/srsran/srslog/log_channel.h | 57 +++++-------------- lib/src/srslog/backend_worker.cpp | 5 -- lib/src/srslog/bundled/fmt/format.cc | 44 +++++++++++++- lib/src/srslog/event_trace.cpp | 6 +- lib/test/srslog/json_formatter_test.cpp | 2 +- lib/test/srslog/log_backend_test.cpp | 2 +- lib/test/srslog/log_channel_test.cpp | 25 -------- lib/test/srslog/text_formatter_test.cpp | 2 +- 11 files changed, 69 insertions(+), 89 deletions(-) diff --git a/lib/include/srsran/srslog/detail/log_entry_metadata.h b/lib/include/srsran/srslog/detail/log_entry_metadata.h index 1f838beec..10caf4a8b 100644 --- a/lib/include/srsran/srslog/detail/log_entry_metadata.h +++ b/lib/include/srsran/srslog/detail/log_entry_metadata.h @@ -18,9 +18,6 @@ namespace srslog { -/// This type is used to store small strings without doing any memory allocation. -using small_str_buffer = fmt::basic_memory_buffer; - namespace detail { /// This structure gives the user a way to log generic information as a context. @@ -40,7 +37,6 @@ struct log_entry_metadata { fmt::dynamic_format_arg_store* store; std::string log_name; char log_tag; - small_str_buffer small_str; std::vector hex_dump; }; diff --git a/lib/include/srsran/srslog/detail/support/dyn_arg_store_pool.h b/lib/include/srsran/srslog/detail/support/dyn_arg_store_pool.h index 595181988..85f4e33f3 100644 --- a/lib/include/srsran/srslog/detail/support/dyn_arg_store_pool.h +++ b/lib/include/srsran/srslog/detail/support/dyn_arg_store_pool.h @@ -60,8 +60,8 @@ public: return; } - scoped_lock lock(m); p->clear(); + scoped_lock lock(m); free_list.push_back(p); } diff --git a/lib/include/srsran/srslog/detail/support/thread_utils.h b/lib/include/srsran/srslog/detail/support/thread_utils.h index f10e89386..c2b36d87e 100644 --- a/lib/include/srsran/srslog/detail/support/thread_utils.h +++ b/lib/include/srsran/srslog/detail/support/thread_utils.h @@ -28,7 +28,14 @@ public: mutex(const mutex&) = delete; mutex& operator=(const mutex&) = delete; - mutex() { ::pthread_mutex_init(&m, nullptr); } + mutex() + { + ::pthread_mutexattr_t mutex_attr; + ::pthread_mutexattr_init(&mutex_attr); + ::pthread_mutexattr_setprotocol(&mutex_attr, PTHREAD_PRIO_INHERIT); + ::pthread_mutex_init(&m, &mutex_attr); + } + ~mutex() { ::pthread_mutex_destroy(&m); } /// Mutex lock. diff --git a/lib/include/srsran/srslog/log_channel.h b/lib/include/srsran/srslog/log_channel.h index 273debf67..691ef19dc 100644 --- a/lib/include/srsran/srslog/log_channel.h +++ b/lib/include/srsran/srslog/log_channel.h @@ -16,6 +16,7 @@ #include "srsran/srslog/detail/log_backend.h" #include "srsran/srslog/detail/log_entry.h" #include "srsran/srslog/sink.h" +#include namespace srslog { @@ -65,11 +66,11 @@ public: log_channel& operator=(const log_channel& other) = delete; /// Controls when the channel accepts incoming log entries. - void set_enabled(bool enabled) { is_enabled = enabled; } + void set_enabled(bool enabled) { is_enabled.store(enabled, std::memory_order_relaxed); } /// Returns true if the channel is accepting incoming log entries, otherwise /// false. - bool enabled() const { return is_enabled; } + bool enabled() const { return is_enabled.load(std::memory_order_relaxed); } /// Returns the id string of the channel. const std::string& id() const { return log_id; } @@ -108,32 +109,7 @@ public: fmtstr, store, log_name, - log_tag, - small_str_buffer()}}; - backend.push(std::move(entry)); - } - - /// Builds the provided log entry and passes it to the backend. When the - /// channel is disabled the log entry will be discarded. - void operator()(small_str_buffer&& str) - { - if (!enabled()) { - return; - } - - // Send the log entry to the backend. - log_formatter& formatter = log_sink.get_formatter(); - detail::log_entry entry = {&log_sink, - [&formatter](detail::log_entry_metadata&& metadata, fmt::memory_buffer& buffer) { - formatter.format(std::move(metadata), buffer); - }, - {std::chrono::high_resolution_clock::now(), - {ctx_value, should_print_context}, - nullptr, - nullptr, - log_name, - log_tag, - std::move(str)}}; + log_tag}}; backend.push(std::move(entry)); } @@ -170,7 +146,6 @@ public: store, log_name, log_tag, - small_str_buffer(), std::vector(buffer, buffer + len)}}; backend.push(std::move(entry)); } @@ -195,8 +170,7 @@ public: nullptr, nullptr, log_name, - log_tag, - small_str_buffer()}}; + log_tag}}; backend.push(std::move(entry)); } @@ -227,21 +201,20 @@ public: fmtstr, store, log_name, - log_tag, - small_str_buffer()}}; + log_tag}}; backend.push(std::move(entry)); } private: - const std::string log_id; - sink& log_sink; - detail::log_backend& backend; - const std::string log_name; - const char log_tag; - const bool should_print_context; - detail::shared_variable ctx_value; - detail::shared_variable hex_max_size; - detail::shared_variable is_enabled; + const std::string log_id; + sink& log_sink; + detail::log_backend& backend; + const std::string log_name; + const char log_tag; + const bool should_print_context; + std::atomic ctx_value; + std::atomic hex_max_size; + std::atomic is_enabled; }; } // namespace srslog diff --git a/lib/src/srslog/backend_worker.cpp b/lib/src/srslog/backend_worker.cpp index 31bbc6e59..8c1040599 100644 --- a/lib/src/srslog/backend_worker.cpp +++ b/lib/src/srslog/backend_worker.cpp @@ -132,11 +132,6 @@ void backend_worker::process_log_entry(detail::log_entry&& entry) assert(entry.format_func && "Invalid format function"); fmt_buffer.clear(); - // Already formatted strings in the foreground are passed to the formatter as the fmtstring. - if (entry.metadata.small_str.size()) { - entry.metadata.fmtstring = entry.metadata.small_str.data(); - } - // Save the pointer before moving the entry. auto* arg_store = entry.metadata.store; diff --git a/lib/src/srslog/bundled/fmt/format.cc b/lib/src/srslog/bundled/fmt/format.cc index 4864ac26e..d1fc4f39b 100644 --- a/lib/src/srslog/bundled/fmt/format.cc +++ b/lib/src/srslog/bundled/fmt/format.cc @@ -25,6 +25,44 @@ int format_float(char* buf, std::size_t size, const char* format, int precision, : snprintf_ptr(buf, size, format, precision, value); } +namespace { + +/// This special mutex has priority inheritance to improve latency. +class pi_mutex +{ +public: + pi_mutex(const pi_mutex&) = delete; + pi_mutex& operator=(const pi_mutex&) = delete; + + pi_mutex() + { + ::pthread_mutexattr_t mutex_attr; + ::pthread_mutexattr_init(&mutex_attr); + ::pthread_mutexattr_setprotocol(&mutex_attr, PTHREAD_PRIO_INHERIT); + ::pthread_mutex_init(&m, &mutex_attr); + } + + ~pi_mutex() { ::pthread_mutex_destroy(&m); } + + /// Mutex lock. + void lock() { ::pthread_mutex_lock(&m); } + + /// Mutex unlock. + void unlock() { ::pthread_mutex_unlock(&m); } + + /// Mutex try lock. Returns true if the lock was obtained, false otherwise. + bool try_lock() { return (::pthread_mutex_trylock(&m) == 0); } + + /// Accessor to the raw mutex structure. + pthread_mutex_t* raw() { return &m; } + const pthread_mutex_t* raw() const { return &m; } + +private: + pthread_mutex_t m; +}; + +} + #define NODE_POOL_SIZE (10000u) static constexpr uint8_t memory_heap_tag = 0xAA; class dyn_node_pool @@ -49,7 +87,7 @@ public: void* alloc(std::size_t sz) { assert(sz <= dynamic_arg_list::max_pool_node_size && "Object is too large to fit in the pool"); - std::lock_guard lock(m); + std::lock_guard lock(m); if (free_list.empty()) { // Tag that this allocation was performed by the heap. auto *p = new type; @@ -70,7 +108,6 @@ public: return; } - std::lock_guard lock(m); uint8_t* base_ptr = reinterpret_cast(p) - 1; if (*base_ptr == memory_heap_tag) { // This pointer was allocated using the heap. @@ -78,13 +115,14 @@ public: return; } + std::lock_guard lock(m); free_list.push_back(base_ptr); } private: std::vector pool; std::vector free_list; - mutable std::mutex m; + mutable pi_mutex m; }; static dyn_node_pool node_pool; diff --git a/lib/src/srslog/event_trace.cpp b/lib/src/srslog/event_trace.cpp index d43cdcac1..4763085e7 100644 --- a/lib/src/srslog/event_trace.cpp +++ b/lib/src/srslog/event_trace.cpp @@ -125,9 +125,5 @@ srslog::detail::scoped_complete_event::~scoped_complete_event() return; } - small_str_buffer str; - // Limit the category and name strings to a predefined length so everything fits in a small string. - fmt::format_to(str, "{:.32} {:.16}, {}", category, name, diff.count()); - str.push_back('\0'); - (*tracer)(std::move(str)); + (*tracer)("%s %s, %u", category, name, (unsigned)diff.count()); } diff --git a/lib/test/srslog/json_formatter_test.cpp b/lib/test/srslog/json_formatter_test.cpp index 76d9fc0c5..f2a263af8 100644 --- a/lib/test/srslog/json_formatter_test.cpp +++ b/lib/test/srslog/json_formatter_test.cpp @@ -28,7 +28,7 @@ static detail::log_entry_metadata build_log_entry_metadata(fmt::dynamic_format_a store->push_back(88); } - return {tp, {10, true}, "Text %d", store, "ABC", 'Z', small_str_buffer()}; + return {tp, {10, true}, "Text %d", store, "ABC", 'Z'}; } static bool when_fully_filled_log_entry_then_everything_is_formatted() diff --git a/lib/test/srslog/log_backend_test.cpp b/lib/test/srslog/log_backend_test.cpp index 39a395a0c..16ec6d630 100644 --- a/lib/test/srslog/log_backend_test.cpp +++ b/lib/test/srslog/log_backend_test.cpp @@ -80,7 +80,7 @@ static detail::log_entry build_log_entry(sink* s, fmt::dynamic_format_arg_store< return {s, [](detail::log_entry_metadata&& metadata, fmt::memory_buffer& buffer) {}, - {tp, {0, false}, "Text %d", store, "", '\0', small_str_buffer()}}; + {tp, {0, false}, "Text %d", store, "", '\0'}}; } static bool when_backend_is_not_started_then_pushed_log_entries_are_ignored() diff --git a/lib/test/srslog/log_channel_test.cpp b/lib/test/srslog/log_channel_test.cpp index c5674b4e8..52b53c1f8 100644 --- a/lib/test/srslog/log_channel_test.cpp +++ b/lib/test/srslog/log_channel_test.cpp @@ -270,30 +270,6 @@ static bool when_logging_with_context_and_message_then_filled_in_log_entry_is_pu return true; } -static bool when_logging_with_small_string_then_filled_in_log_entry_is_pushed_into_the_backend() -{ - backend_spy backend; - test_dummies::sink_dummy s; - - log_channel log("id", s, backend); - - small_str_buffer buf; - fmt::format_to(buf, "A {} {} {}", 1, 2, 3); - buf.push_back('\0'); - log(std::move(buf)); - - ASSERT_EQ(backend.push_invocation_count(), 1); - - const detail::log_entry& entry = backend.last_entry(); - ASSERT_EQ(&s, entry.s); - ASSERT_NE(entry.format_func, nullptr); - ASSERT_NE(entry.metadata.tp.time_since_epoch().count(), 0); - ASSERT_EQ(entry.metadata.hex_dump.empty(), true); - ASSERT_EQ(std::string(entry.metadata.small_str.data()), "A 1 2 3"); - - return true; -} - int main() { TEST_FUNCTION(when_log_channel_is_created_then_id_matches_expected_value); @@ -306,7 +282,6 @@ int main() TEST_FUNCTION(when_hex_array_length_is_less_than_hex_log_max_size_then_array_length_is_used); TEST_FUNCTION(when_logging_with_context_then_filled_in_log_entry_is_pushed_into_the_backend); TEST_FUNCTION(when_logging_with_context_and_message_then_filled_in_log_entry_is_pushed_into_the_backend); - TEST_FUNCTION(when_logging_with_small_string_then_filled_in_log_entry_is_pushed_into_the_backend); return 0; } diff --git a/lib/test/srslog/text_formatter_test.cpp b/lib/test/srslog/text_formatter_test.cpp index a9cafcf40..15c9036c4 100644 --- a/lib/test/srslog/text_formatter_test.cpp +++ b/lib/test/srslog/text_formatter_test.cpp @@ -28,7 +28,7 @@ static detail::log_entry_metadata build_log_entry_metadata(fmt::dynamic_format_a store->push_back(88); } - return {tp, {10, true}, "Text %d", store, "ABC", 'Z', small_str_buffer()}; + return {tp, {10, true}, "Text %d", store, "ABC", 'Z'}; } static bool when_fully_filled_log_entry_then_everything_is_formatted()