- Provide a fast path for logging pre-formatted strings that are small and fit in 64 bytes without any allocations.

- Use this new feature in the tracer.

lib/include/srslte/srslog/detail/log_entry_metadata.h

@@ -18,6 +18,9 @@
 
 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.
@@ -31,13 +34,14 @@ struct log_context {
 
 /// Metadata fields carried for each log entry.
 struct log_entry_metadata {
-  std::chrono::high_resolution_clock::time_point tp;
-  log_context context;
-  const char* fmtstring;
+  std::chrono::high_resolution_clock::time_point     tp;
+  log_context                                        context;
+  const char*                                        fmtstring;
   fmt::dynamic_format_arg_store<fmt::printf_context> store;
-  std::string log_name;
-  char log_tag;
-  std::vector<uint8_t> hex_dump;
+  std::string                                        log_name;
+  char                                               log_tag;
+  small_str_buffer                                   small_str;
+  std::vector<uint8_t>                               hex_dump;
 };
 
 } // namespace detail

lib/include/srslte/srslog/detail/support/work_queue.h

@@ -111,7 +111,7 @@ public:
     // Did we wake up on timeout?
     if (timedout && queue.empty()) {
       cond_var.unlock();
-      return {false, T{}};
+      return {false, T()};
     }
 
     // Here we have been woken up normally.

lib/include/srslte/srslog/log_channel.h

@@ -113,7 +113,34 @@ public:
          fmtstr,
          std::move(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,
+         {},
+         log_name,
+         log_tag,
+         std::move(str)}};
     backend.push(std::move(entry));
   }
 
@@ -152,6 +179,7 @@ public:
          std::move(store),
          log_name,
          log_tag,
+         small_str_buffer(),
          std::vector<uint8_t>(buffer, buffer + len)}};
     backend.push(std::move(entry));
   }
@@ -178,7 +206,8 @@ public:
          nullptr,
          {},
          log_name,
-         log_tag}};
+         log_tag,
+         small_str_buffer()}};
     backend.push(std::move(entry));
   }
 
@@ -209,7 +238,8 @@ public:
          fmtstr,
          std::move(store),
          log_name,
-         log_tag}};
+         log_tag,
+         small_str_buffer()}};
     backend.push(std::move(entry));
   }
 

lib/src/srslog/backend_worker.cpp

@@ -90,6 +90,11 @@ 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();
+  }
   entry.format_func(std::move(entry.metadata), fmt_buffer);
 
   if (auto err_str = entry.s->write({fmt_buffer.data(), fmt_buffer.size()})) {
@@ -99,8 +104,7 @@ void backend_worker::process_log_entry(detail::log_entry&& entry)
 
 void backend_worker::process_outstanding_entries()
 {
-  assert(!running_flag &&
-         "Cannot process outstanding entries while thread is running");
+  assert(!running_flag && "Cannot process outstanding entries while thread is running");
 
   while (true) {
     auto item = queue.timed_pop(1);

lib/src/srslog/event_trace.cpp

@@ -124,17 +124,18 @@ void trace_duration_end(const std::string& category, const std::string& name)
 /// Private implementation of the complete event destructor.
 srslog::detail::scoped_complete_event::~scoped_complete_event()
 {
-  if (!tracer)
+  if (!tracer) {
     return;
+  }
 
   auto end = std::chrono::steady_clock::now();
   unsigned long long diff =
       std::chrono::duration_cast<std::chrono::microseconds>(end - start)
           .count();
 
-  (*tracer)("[TID:%0u] Complete event \"%s\" (duration %lld us): %s",
-            (unsigned)::pthread_self(),
-            category,
-            diff,
-            name);
+  small_str_buffer str;
+  // Limit to 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);
+  str.push_back('\0');
+  (*tracer)(std::move(str));
 }

lib/test/srslog/json_formatter_test.cpp

@@ -27,7 +27,7 @@ static detail::log_entry_metadata build_log_entry_metadata()
   fmt::dynamic_format_arg_store<fmt::printf_context> store;
   store.push_back(88);
 
-  return {tp, {10, true}, "Text %d", std::move(store), "ABC", 'Z'};
+  return {tp, {10, true}, "Text %d", std::move(store), "ABC", 'Z', small_str_buffer()};
 }
 
 static bool when_fully_filled_log_entry_then_everything_is_formatted()

lib/test/srslog/log_backend_test.cpp

@@ -70,19 +70,6 @@ private:
 
 } // namespace
 
-static bool when_backend_is_not_started_then_pushed_log_entries_are_ignored()
-{
-  sink_spy spy;
-  log_backend_impl backend;
-
-  detail::log_entry entry = {&spy};
-  backend.push(std::move(entry));
-
-  ASSERT_EQ(spy.write_invocation_count(), 0);
-
-  return true;
-}
-
 /// Builds a basic log entry.
 static detail::log_entry build_log_entry(sink* s)
 {
@@ -95,7 +82,19 @@ static detail::log_entry build_log_entry(sink* s)
   return {
       s,
       [](detail::log_entry_metadata&& metadata, fmt::memory_buffer& buffer) {},
-      {tp, {0, false}, "Text %d", std::move(store), "", '\0'}};
+      {tp, {0, false}, "Text %d", std::move(store), "", '\0', small_str_buffer()}};
+}
+
+static bool when_backend_is_not_started_then_pushed_log_entries_are_ignored()
+{
+  sink_spy spy;
+  log_backend_impl backend;
+
+  backend.push(build_log_entry(&spy));
+
+  ASSERT_EQ(spy.write_invocation_count(), 0);
+
+  return true;
 }
 
 static bool when_backend_is_started_then_pushed_log_entries_are_sent_to_sink()

lib/test/srslog/log_channel_test.cpp

@@ -278,6 +278,30 @@ when_logging_with_context_and_message_then_filled_in_log_entry_is_pushed_into_th
   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);
+  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);
@@ -296,6 +320,8 @@ int main()
       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

@@ -27,7 +27,7 @@ static detail::log_entry_metadata build_log_entry_metadata()
   fmt::dynamic_format_arg_store<fmt::printf_context> store;
   store.push_back(88);
 
-  return {tp, {10, true}, "Text %d", std::move(store), "ABC", 'Z'};
+  return {tp, {10, true}, "Text %d", std::move(store), "ABC", 'Z', small_str_buffer()};
 }
 
 static bool when_fully_filled_log_entry_then_everything_is_formatted()