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

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<char, 64>;
-
 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<fmt::printf_context>* store;
   std::string                                         log_name;
   char                                                log_tag;
-  small_str_buffer                                    small_str;
   std::vector<uint8_t>                                hex_dump;
 };
 

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

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.

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 <atomic>
 
 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,
+                                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)}};
     backend.push(std::move(entry));
   }
 
@@ -170,7 +146,6 @@ public:
                                 store,
                                 log_name,
                                 log_tag,
-                                small_str_buffer(),
                                 std::vector<uint8_t>(buffer, buffer + len)}};
     backend.push(std::move(entry));
   }
@@ -195,8 +170,7 @@ public:
                                 nullptr,
                                 nullptr,
                                 log_name,
-                                log_tag,
+                                log_tag}};
-                                small_str_buffer()}};
     backend.push(std::move(entry));
   }
 
@@ -227,8 +201,7 @@ public:
                                 fmtstr,
                                 store,
                                 log_name,
-                                log_tag,
+                                log_tag}};
-                                small_str_buffer()}};
     backend.push(std::move(entry));
   }
 
@@ -239,9 +212,9 @@ private:
   const std::string     log_name;
   const char            log_tag;
   const bool            should_print_context;
-  detail::shared_variable<uint32_t> ctx_value;
+  std::atomic<uint32_t> ctx_value;
-  detail::shared_variable<int>      hex_max_size;
+  std::atomic<int>      hex_max_size;
-  detail::shared_variable<bool>     is_enabled;
+  std::atomic<bool>     is_enabled;
 };
 
 } // namespace srslog

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;
 

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<std::mutex> lock(m);
+    std::lock_guard<pi_mutex> 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<std::mutex> lock(m);
     uint8_t* base_ptr = reinterpret_cast<uint8_t *>(p) - 1;
     if (*base_ptr == memory_heap_tag) {
       // This pointer was allocated using the heap.
@@ -78,13 +115,14 @@ public:
       return;
     }
 
+    std::lock_guard<pi_mutex> lock(m);
     free_list.push_back(base_ptr);
   }
 
 private:
   std::vector<type> pool;
   std::vector<uint8_t *> free_list;
-  mutable std::mutex m;
+  mutable pi_mutex m;
 };
 
 static dyn_node_pool node_pool;

lib/src/srslog/event_trace.cpp

@@ -125,9 +125,5 @@ srslog::detail::scoped_complete_event::~scoped_complete_event()
     return;
   }
 
-  small_str_buffer str;
+  (*tracer)("%s %s, %u", category, name, (unsigned)diff.count());
-  // 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));
 }

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()

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()

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

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()