backend logging thread improvements (#207)

backend logging thread performance improvements

CHANGELOG.md

@@ -1,3 +1,4 @@
+- [v2.5.0](#v2.5.0)
 - [v2.4.2](#v2.4.2)
 - [v2.4.1](#v2.4.1)
 - [v2.4.0](#v2.4.0)
@@ -35,6 +36,12 @@
 - [v1.1.0](#v1.1.0)
 - [v1.0.0](#v1.0.0)
 
+## v2.5.0
+
+**Improvements**
+
+- Performance improvements for the backend logging thread
+
 ## v2.4.2
 
 **Fixes**

examples/example_custom_handler.cpp

@@ -15,7 +15,7 @@ class CustomHandler : public quill::Handler
    * @param formatted_log_message input message to write
    * @param log_message_timestamp log timestamp
    */
-  void write(fmt::memory_buffer const& formatted_log_message, quill::TransitEvent const& log_event) override
+  void write(quill::fmt_buffer_t const& formatted_log_message, quill::TransitEvent const& log_event) override
   {
     // write a formatted log
     std::string log{formatted_log_message.data(), formatted_log_message.size()};

examples/example_filters.cpp

@@ -16,7 +16,7 @@ class FileFilter : public quill::FilterBase
 
   QUILL_NODISCARD bool filter(char const* thread_id, std::chrono::nanoseconds log_message_timestamp,
                               quill::MacroMetadata const& metadata,
-                              fmt::memory_buffer const& formatted_record) noexcept override
+                              quill::fmt_buffer_t const& formatted_record) noexcept override
   {
     // log only messages that are INFO or above in the file
     return metadata.level() < quill::LogLevel::Warning;
@@ -33,7 +33,7 @@ class StdoutFilter : public quill::FilterBase
 
   QUILL_NODISCARD bool filter(char const* thread_id, std::chrono::nanoseconds log_message_timestamp,
                               quill::MacroMetadata const& metadata,
-                              fmt::memory_buffer const& formatted_record) noexcept override
+                              quill::fmt_buffer_t const& formatted_record) noexcept override
   {
     // log only WARNINGS or higher to stdout
     return metadata.level() >= quill::LogLevel::Warning;

examples/example_multiple_handlers.cpp

@@ -12,7 +12,7 @@ class VectorHandler final : public quill::Handler
   VectorHandler() = default;
 
   /***/
-  void write(fmt::memory_buffer const& formatted_log_message, quill::TransitEvent const& log_event) override
+  void write(quill::fmt_buffer_t const& formatted_log_message, quill::TransitEvent const& log_event) override
   {
     // Called by the logger backend worker thread for each LOG_* macro
     // formatted_log_message.size() - 1 to exclude '/n'

quill/include/quill/PatternFormatter.h

@@ -98,15 +98,15 @@ class PatternFormatter
   QUILL_ATTRIBUTE_HOT void format(std::chrono::nanoseconds timestamp, std::string_view thread_id,
                                   std::string_view thread_name, std::string_view process_id,
                                   std::string_view logger_name, MacroMetadata const& macro_metadata,
-                                  fmt::memory_buffer const& log_msg);
+                                  fmt_buffer_t const& log_msg);
 
   QUILL_ATTRIBUTE_HOT std::string_view format_timestamp(std::chrono::nanoseconds timestamp);
 
   /**
    * Returns the stored formatted record, to be called after format(...) is called
    * @return Returns the stored formatted record
    */
-  QUILL_NODISCARD QUILL_ATTRIBUTE_HOT fmt::memory_buffer const& formatted_log_message() const noexcept
+  QUILL_NODISCARD QUILL_ATTRIBUTE_HOT fmt_buffer_t const& formatted_log_message() const noexcept
   {
     return _formatted_log_message;
   }
@@ -163,6 +163,6 @@ class PatternFormatter
 
   /** The buffer where we store each formatted string, also stored as class member to avoid
    * re-allocations. This is mutable so we can have a format() const function **/
-  fmt::memory_buffer _formatted_log_message;
+  fmt_buffer_t _formatted_log_message;
 };
 } // namespace quill

quill/include/quill/Quill.h

@@ -28,8 +28,8 @@ namespace quill
 
 /** Version Info **/
 constexpr uint32_t VersionMajor{2};
-constexpr uint32_t VersionMinor{4};
-constexpr uint32_t VersionPatch{2};
+constexpr uint32_t VersionMinor{5};
+constexpr uint32_t VersionPatch{0};
 constexpr uint32_t Version{VersionMajor * 10000 + VersionMinor * 100 + VersionPatch};
 
 /** forward declarations **/

quill/include/quill/TransitEvent.h

@@ -7,7 +7,6 @@
 
 #include "quill/Fmt.h"
 #include "quill/detail/Serialize.h"
-#include "quill/detail/ThreadContext.h"
 
 namespace quill
 {
@@ -17,45 +16,8 @@ struct TransitEvent
   TransitEvent() = default;
   ~TransitEvent() = default;
 
-  TransitEvent(detail::ThreadContext* thread_context, detail::Header header,
-               fmt::memory_buffer formatted_msg, std::atomic<bool>* flush_flag)
-    : thread_id(thread_context->thread_id()),
-      thread_name(thread_context->thread_name()),
-      header(header),
-      formatted_msg(std::move(formatted_msg)),
-      flush_flag(flush_flag)
-  {
-  }
-
-  TransitEvent(TransitEvent const& other)
-    : structured_keys(other.structured_keys),
-      structured_values(other.structured_values),
-      thread_id(other.thread_id),
-      thread_name(other.thread_name),
-      header(other.header),
-      flush_flag(other.flush_flag)
-
-  {
-    formatted_msg.clear();
-    formatted_msg.append(other.formatted_msg.begin(), other.formatted_msg.end());
-  }
-
-  TransitEvent& operator=(TransitEvent const& other)
-  {
-    if (this != &other)
-    {
-      structured_keys = other.structured_keys;
-      structured_values = other.structured_values;
-      thread_id = other.thread_id;
-      thread_name = other.thread_name;
-      header = other.header;
-      formatted_msg.clear();
-      formatted_msg.append(other.formatted_msg.begin(), other.formatted_msg.end());
-      flush_flag = other.flush_flag;
-    }
-
-    return *this;
-  }
+  TransitEvent(TransitEvent const& other) = delete;
+  TransitEvent& operator=(TransitEvent const& other) = delete;
 
   TransitEvent(TransitEvent&& other) noexcept
     : structured_keys(std::move(other.structured_keys)),
@@ -93,16 +55,16 @@ struct TransitEvent
   std::string thread_id;
   std::string thread_name;
   detail::Header header;
-  fmt::memory_buffer formatted_msg;       /** buffer for message **/
+  fmt_buffer_t formatted_msg;             /** buffer for message **/
   std::atomic<bool>* flush_flag{nullptr}; /** This is only used in the case of Event::Flush **/
 };
 
 class TransitEventComparator
 {
 public:
-  bool operator()(TransitEvent const* lhs, TransitEvent const* rhs)
+  bool operator()(std::pair<uint64_t, TransitEvent*> const& lhs, std::pair<uint64_t, TransitEvent*> const& rhs)
   {
-    return lhs->header.timestamp > rhs->header.timestamp;
+    return lhs.first > rhs.first;
   }
 };
 } // namespace quill

quill/include/quill/bundled/fmt/format.h

@@ -802,7 +802,7 @@ enum { inline_buffer_size = 500 };
 
   **Example**::
 
-     auto out = fmt::memory_buffer();
+     auto out = fmt_buffer_t();
      format_to(std::back_inserter(out), "The answer is {}.", 42);
 
   This will append the following output to the ``out`` object:

quill/include/quill/detail/Serialize.h

@@ -289,12 +289,12 @@ QUILL_NODISCARD QUILL_ATTRIBUTE_HOT constexpr std::byte* encode_args(size_t* c_s
 /**
  * Format function
  */
-using FormatToFn = std::byte* (*)(std::string_view format, std::byte* data, fmt::memory_buffer& out,
+using FormatToFn = std::byte* (*)(std::string_view format, std::byte* data, fmt_buffer_t& out,
                                   std::vector<fmt::basic_format_arg<fmt::format_context>>& args);
 
 template <typename... Args>
 QUILL_NODISCARD QUILL_ATTRIBUTE_HOT std::byte* format_to(std::string_view format, std::byte* data,
-                                                         fmt::memory_buffer& out,
+                                                         fmt_buffer_t& out,
                                                          std::vector<fmt::basic_format_arg<fmt::format_context>>& args)
 {
   constexpr size_t num_dtors = fmt::detail::count<need_call_dtor_for<Args>()...>();

quill/include/quill/detail/backend/BackendWorker.h

@@ -156,7 +156,7 @@ class BackendWorker
   std::chrono::nanoseconds _backend_thread_sleep_duration; /** backend_thread_sleep_duration from config **/
   size_t _max_transit_events; /** limit of transit events before start flushing, value from config */
 
-  std::priority_queue<TransitEvent*, std::vector<TransitEvent*>, TransitEventComparator> _transit_events;
+  std::priority_queue<std::pair<uint64_t, TransitEvent*>, std::vector<std::pair<uint64_t, TransitEvent*>>, TransitEventComparator> _transit_events;
 
   std::vector<fmt::basic_format_arg<fmt::format_context>> _args; /** Format args tmp storage as member to avoid reallocation */
 
@@ -471,7 +471,7 @@ bool BackendWorker::_read_queue_messages_and_decode(ThreadContext* thread_contex
     queue.finish_read(read_size);
     bytes_available -= read_size;
 
-    _transit_events.emplace(transit_event);
+    _transit_events.emplace(std::make_pair(transit_event->header.timestamp, transit_event));
   }
 
   // read everything
@@ -481,7 +481,7 @@ bool BackendWorker::_read_queue_messages_and_decode(ThreadContext* thread_contex
 /***/
 void BackendWorker::_process_transit_event()
 {
-  TransitEvent const* transit_event = _transit_events.top();
+  TransitEvent* transit_event = _transit_events.top().second;
 
   // If backend_process(...) throws we want to skip this event and move to the next so we catch the
   // error here instead of catching it in the parent try/catch block of main_loop
@@ -509,7 +509,7 @@ void BackendWorker::_process_transit_event()
       else
       {
         // this is a backtrace log and we will store it
-        _backtrace_log_message_storage.store(*transit_event);
+        _backtrace_log_message_storage.store(std::move(*transit_event));
       }
     }
     else if (transit_event->header.metadata->macro_metadata.event() == MacroMetadata::Event::InitBacktrace)

quill/include/quill/detail/misc/Common.h

@@ -146,6 +146,8 @@ constexpr bool detect_structured_log_template(std::wstring_view)
 }
 } // namespace detail
 
+using fmt_buffer_t = fmt::basic_memory_buffer<char, 64>;
+
 /**
  * Enum to select a timezone
  */

quill/include/quill/filters/FilterBase.h

@@ -39,7 +39,7 @@ class FilterBase
    */
   QUILL_NODISCARD virtual bool filter(char const* thread_id, std::chrono::nanoseconds log_message_timestamp,
                                       MacroMetadata const& metadata,
-                                      fmt::memory_buffer const& formatted_record) noexcept = 0;
+                                      fmt_buffer_t const& formatted_record) noexcept = 0;
 
   /**
    * Gets the name of the filter. Only useful if an existing filter is needed to be looked up

quill/include/quill/handlers/ConsoleHandler.h

@@ -196,7 +196,7 @@ class ConsoleHandler : public StreamHandler
    * @param formatted_log_message input log message to write
    * @param transit_Event transit_Event
    */
-  QUILL_ATTRIBUTE_HOT void write(fmt::memory_buffer const& formatted_log_message,
+  QUILL_ATTRIBUTE_HOT void write(fmt_buffer_t const& formatted_log_message,
                                  TransitEvent const& transit_Event) override;
 
   /**

quill/include/quill/handlers/Handler.h

@@ -73,7 +73,7 @@ class Handler
    * @param formatted_log_message input log message to write
    * @param log_event transit event
    */
-  QUILL_ATTRIBUTE_HOT virtual void write(fmt::memory_buffer const& formatted_log_message,
+  QUILL_ATTRIBUTE_HOT virtual void write(fmt_buffer_t const& formatted_log_message,
                                          quill::TransitEvent const& log_event) = 0;
 
   /**
@@ -114,7 +114,7 @@ class Handler
    * @return result of all filters
    */
   QUILL_NODISCARD bool apply_filters(char const* thread_id, std::chrono::nanoseconds log_message_timestamp,
-                                     MacroMetadata const& metadata, fmt::memory_buffer const& formatted_record);
+                                     MacroMetadata const& metadata, fmt_buffer_t const& formatted_record);
 
 protected:
   /**< Owned formatter for this handler, we have to use a pointer here since the PatterFormatter

quill/include/quill/handlers/JsonFileHandler.h

@@ -27,10 +27,10 @@ class JsonFileHandler : public FileHandler
    * @param formatted_log_message input log message to write
    * @param log_event log_event
    */
-  QUILL_ATTRIBUTE_HOT void write(fmt::memory_buffer const& formatted_log_message,
+  QUILL_ATTRIBUTE_HOT void write(fmt_buffer_t const& formatted_log_message,
                                  quill::TransitEvent const& log_event) override;
 
 private:
-  fmt::memory_buffer _json_message;
+  fmt_buffer_t _json_message;
 };
 } // namespace quill

quill/include/quill/handlers/RotatingFileHandler.h

@@ -46,7 +46,7 @@ class RotatingFileHandler final : public FileHandler
    * @param formatted_log_message input log message to write
    * @param log_event transit_event
    */
-  QUILL_ATTRIBUTE_HOT void write(fmt::memory_buffer const& formatted_log_message,
+  QUILL_ATTRIBUTE_HOT void write(fmt_buffer_t const& formatted_log_message,
                                  quill::TransitEvent const& log_event) override;
 
 private:

quill/include/quill/handlers/StreamHandler.h

@@ -38,7 +38,7 @@ class StreamHandler : public Handler
    * @param formatted_log_message input log message to write
    * @param log_event log_event
    */
-  QUILL_ATTRIBUTE_HOT void write(fmt::memory_buffer const& formatted_log_message,
+  QUILL_ATTRIBUTE_HOT void write(fmt_buffer_t const& formatted_log_message,
                                  quill::TransitEvent const& log_event) override;
 
   /**

quill/include/quill/handlers/TimeRotatingFileHandler.h

@@ -30,9 +30,9 @@ class TimeRotatingFileHandler final : public FileHandler
    * @param timezone if true gmt time then UTC times are used instead
    * @param at_time used when 'daily' is specified
    */
-  TimeRotatingFileHandler(fs::path const& base_filename, std::string const& mode,
-                          std::string when, uint32_t interval, uint32_t backup_count,
-                          Timezone timezone, std::string const& at_time);
+  TimeRotatingFileHandler(fs::path const& base_filename, std::string const& mode, std::string when,
+                          uint32_t interval, uint32_t backup_count, Timezone timezone,
+                          std::string const& at_time);
 
   ~TimeRotatingFileHandler() override = default;
 
@@ -41,7 +41,7 @@ class TimeRotatingFileHandler final : public FileHandler
    * @param formatted_log_message input log message to write
    * @param log_event log_event
    */
-  QUILL_ATTRIBUTE_HOT void write(fmt::memory_buffer const& formatted_log_message,
+  QUILL_ATTRIBUTE_HOT void write(fmt_buffer_t const& formatted_log_message,
                                  quill::TransitEvent const& log_event) override;
 
 private:

quill/src/PatternFormatter.cpp

@@ -179,7 +179,7 @@ void PatternFormatter::_set_pattern(std::string const& format_pattern)
 /***/
 void PatternFormatter::format(std::chrono::nanoseconds timestamp, std::string_view thread_id,
                               std::string_view thread_name, std::string_view process_id, std::string_view logger_name,
-                              MacroMetadata const& macro_metadata, fmt::memory_buffer const& log_msg)
+                              MacroMetadata const& macro_metadata, fmt_buffer_t const& log_msg)
 {
   if (_format.empty())
   {

quill/src/detail/backend/BacktraceStorage.cpp

@@ -30,7 +30,7 @@ void BacktraceStorage::store(TransitEvent transit_event)
   else
   {
     // Store the object in the vector
-    stored_object_info.stored_records_collection[stored_object_info.index] = transit_event;
+    stored_object_info.stored_records_collection[stored_object_info.index] = std::move(transit_event);
 
     // Update the index wrapping around the vector capacity
     if (stored_object_info.index < stored_object_info.capacity - 1)

quill/src/handlers/ConsoleHandler.cpp

@@ -172,7 +172,7 @@ ConsoleHandler::ConsoleHandler(std::string stream, FILE* file, ConsoleColours co
 }
 
 /***/
-void ConsoleHandler::write(fmt::memory_buffer const& formatted_log_message, quill::TransitEvent const& log_event)
+void ConsoleHandler::write(fmt_buffer_t const& formatted_log_message, quill::TransitEvent const& log_event)
 {
 #if defined(_WIN32)
   if (_console_colours.using_colours())

quill/src/handlers/Handler.cpp

@@ -31,7 +31,7 @@ void Handler::add_filter(std::unique_ptr<FilterBase> filter)
 
 /***/
 QUILL_NODISCARD bool Handler::apply_filters(char const* thread_id, std::chrono::nanoseconds log_message_timestamp,
-                                            MacroMetadata const& metadata, fmt::memory_buffer const& formatted_record)
+                                            MacroMetadata const& metadata, fmt_buffer_t const& formatted_record)
 {
   if (metadata.level() < _log_level.load(std::memory_order_relaxed))
   {

quill/src/handlers/JsonFileHandler.cpp

@@ -4,7 +4,7 @@
 namespace quill
 {
 /***/
-void JsonFileHandler::write(fmt::memory_buffer const& formatted_log_message, quill::TransitEvent const& log_event)
+void JsonFileHandler::write(fmt_buffer_t const& formatted_log_message, quill::TransitEvent const& log_event)
 {
   _json_message.clear();
 

quill/src/handlers/RotatingFileHandler.cpp

@@ -72,7 +72,7 @@ RotatingFileHandler::RotatingFileHandler(fs::path const& base_filename,
 }
 
 /***/
-void RotatingFileHandler::write(fmt::memory_buffer const& formatted_log_message, quill::TransitEvent const& log_event)
+void RotatingFileHandler::write(fmt_buffer_t const& formatted_log_message, quill::TransitEvent const& log_event)
 {
   _current_size += formatted_log_message.size();
 

quill/src/handlers/StreamHandler.cpp

@@ -21,7 +21,7 @@ StreamHandler::StreamHandler(fs::path stream, FILE* file /* = nullptr */)
 }
 
 /***/
-void StreamHandler::write(fmt::memory_buffer const& formatted_log_message, quill::TransitEvent const& log_event)
+void StreamHandler::write(fmt_buffer_t const& formatted_log_message, quill::TransitEvent const& log_event)
 {
   detail::fwrite_fully(formatted_log_message.data(), sizeof(char), formatted_log_message.size(), _file);
 }

quill/src/handlers/TimeRotatingFileHandler.cpp

@@ -79,8 +79,7 @@ TimeRotatingFileHandler::TimeRotatingFileHandler(fs::path const& base_filename,
 }
 
 /***/
-void TimeRotatingFileHandler::write(fmt::memory_buffer const& formatted_log_message,
-                                    quill::TransitEvent const& log_event)
+void TimeRotatingFileHandler::write(fmt_buffer_t const& formatted_log_message, quill::TransitEvent const& log_event)
 {
   bool const should_rotate =
     (std::chrono::nanoseconds{log_event.header.timestamp} >= _next_rotation_time.time_since_epoch());