From d2d9426366463f826a62f3b2a855303b37155d08 Mon Sep 17 00:00:00 2001 From: Odysseas Georgoudis Date: Sat, 21 Sep 2024 14:00:32 +0100 Subject: [PATCH 1/4] Use a separate function overload for when dynamic log level is used (cherry picked from commit 3c977bc8f77eb4e20976bfc0208515bc9584e545) --- include/quill/CsvWriter.h | 8 +- include/quill/LogMacros.h | 8 +- include/quill/Logger.h | 173 +++++++++++++++++++++----- include/quill/backend/SignalHandler.h | 6 +- 4 files changed, 152 insertions(+), 43 deletions(-) diff --git a/include/quill/CsvWriter.h b/include/quill/CsvWriter.h index 647cc116..eb7238ae 100644 --- a/include/quill/CsvWriter.h +++ b/include/quill/CsvWriter.h @@ -63,7 +63,7 @@ class CsvWriter }()), quill::PatternFormatterOptions{"%(message)", "", Timezone::GmtTime}); - _logger->template log_statement(quill::LogLevel::None, &header_metadata, TCsvSchema::header); + _logger->template log_statement(&header_metadata, TCsvSchema::header); } /** @@ -78,7 +78,7 @@ class CsvWriter Frontend::create_or_get_logger(unique_name + "_csv", std::move(sink), quill::PatternFormatterOptions{"%(message)", "", Timezone::GmtTime}); - _logger->template log_statement(quill::LogLevel::None, &header_metadata, TCsvSchema::header); + _logger->template log_statement(&header_metadata, TCsvSchema::header); } /** @@ -92,7 +92,7 @@ class CsvWriter _logger = Frontend::create_or_get_logger( unique_name + "_csv", sinks, quill::PatternFormatterOptions{"%(message)", "", Timezone::GmtTime}); - _logger->template log_statement(quill::LogLevel::None, &header_metadata, TCsvSchema::header); + _logger->template log_statement(&header_metadata, TCsvSchema::header); } /** @@ -112,7 +112,7 @@ class CsvWriter template void append_row(Args&&... fields) { - _logger->template log_statement(quill::LogLevel::None, &line_metadata, fields...); + _logger->template log_statement(&line_metadata, fields...); } /** diff --git a/include/quill/LogMacros.h b/include/quill/LogMacros.h index 5f7cfe63..9001bee5 100644 --- a/include/quill/LogMacros.h +++ b/include/quill/LogMacros.h @@ -307,8 +307,8 @@ { \ if (likelyhood(logger->template should_log_statement())) \ { \ - QUILL_DEFINE_MACRO_METADATA(__FUNCTION__, fmt, tags, log_level); \ - logger->template log_statement(quill::LogLevel::None, ¯o_metadata, ##__VA_ARGS__); \ + QUILL_DEFINE_MACRO_METADATA(__FUNCTION__, fmt, tags, log_level); \ + logger->template log_statement(¯o_metadata, ##__VA_ARGS__); \ } \ } while (0) @@ -335,8 +335,8 @@ { \ if (QUILL_LIKELY(logger->template should_log_statement())) \ { \ - QUILL_DEFINE_MACRO_METADATA(__FUNCTION__, fmt, tags, quill::LogLevel::Backtrace); \ - logger->template log_statement(quill::LogLevel::None, ¯o_metadata, ##__VA_ARGS__); \ + QUILL_DEFINE_MACRO_METADATA(__FUNCTION__, fmt, tags, quill::LogLevel::Backtrace); \ + logger->template log_statement(¯o_metadata, ##__VA_ARGS__); \ } \ } while (0) diff --git a/include/quill/Logger.h b/include/quill/Logger.h index 995cc209..bf28c44b 100644 --- a/include/quill/Logger.h +++ b/include/quill/Logger.h @@ -90,40 +90,137 @@ class LoggerImpl : public detail::LoggerBase // Store the timestamp of the log statement at the start of the call. This gives more accurate // timestamp especially if the queue is full // This is very rare but might lead to out of order timestamp in the log file if we block on push for too long + uint64_t const current_timestamp = _get_current_timestamp(); - uint64_t current_timestamp; + if (QUILL_UNLIKELY(thread_context == nullptr)) + { + // This caches the ThreadContext pointer to avoid repeatedly calling get_local_thread_context() + thread_context = detail::get_local_thread_context(); + } - if (clock_source == ClockSourceType::Tsc) + // For the dynamic log level we want to add to the total size to store the dynamic log level + constexpr size_t header_size{sizeof(current_timestamp) + (sizeof(uintptr_t) * 3) + sizeof(dynamic_log_level)}; + + // Need to know how much size we need from the queue + size_t const total_size = header_size + + detail::compute_encoded_size_and_cache_string_lengths( + thread_context->get_conditional_arg_size_cache(), fmt_args...); + + std::byte* write_buffer = _prepare_write_buffer(total_size); + + if constexpr (frontend_options_t::queue_type == QueueType::UnboundedUnlimited) { - current_timestamp = detail::rdtsc(); + assert(write_buffer && + "Unbounded unlimited queue will always allocate and have enough capacity"); } - else if (clock_source == ClockSourceType::System) + else if constexpr ((frontend_options_t::queue_type == QueueType::BoundedDropping) || + (frontend_options_t::queue_type == QueueType::UnboundedDropping)) { - current_timestamp = static_cast(std::chrono::duration_cast( - std::chrono::system_clock::now().time_since_epoch()) - .count()); + if (QUILL_UNLIKELY(write_buffer == nullptr)) + { + // not enough space to push to queue message is dropped + if (macro_metadata->event() == MacroMetadata::Event::Log) + { + thread_context->increment_failure_counter(); + } + return false; + } } - else + else if constexpr ((frontend_options_t::queue_type == QueueType::BoundedBlocking) || + (frontend_options_t::queue_type == QueueType::UnboundedBlocking)) + { + if (QUILL_UNLIKELY(write_buffer == nullptr)) + { + if (macro_metadata->event() == MacroMetadata::Event::Log) + { + thread_context->increment_failure_counter(); + } + + do + { + if constexpr (frontend_options_t::blocking_queue_retry_interval_ns > 0) + { + std::this_thread::sleep_for(std::chrono::nanoseconds{frontend_options_t::blocking_queue_retry_interval_ns}); + } + + // not enough space to push to queue, keep trying + write_buffer = _prepare_write_buffer(total_size); + } while (write_buffer == nullptr); + } + } + + // we have enough space in this buffer, and we will write to the buffer + +#ifndef NDEBUG + std::byte const* const write_begin = write_buffer; + assert(write_begin); +#endif + + // first encode a header + write_buffer = _encode_header(write_buffer, current_timestamp, macro_metadata, this, + detail::decode_and_store_args...>); + + // encode remaining arguments + detail::encode(write_buffer, thread_context->get_conditional_arg_size_cache(), fmt_args...); + + // write the dynamic log level + // The reason we write it last is that is less likely to break the alignment in the buffer + std::memcpy(write_buffer, &dynamic_log_level, sizeof(dynamic_log_level)); + write_buffer += sizeof(dynamic_log_level); + +#ifndef NDEBUG + assert((write_buffer > write_begin) && "write_buffer must be greater than write_begin"); + assert(total_size == (static_cast(write_buffer - write_begin)) && + "The committed write bytes must be equal to the total_size requested bytes"); +#endif + + thread_context->get_spsc_queue().finish_write(total_size); + thread_context->get_spsc_queue().commit_write(); + + if constexpr (immediate_flush) { - current_timestamp = user_clock->now(); + this->flush_log(); } + return true; + } + + /** + * Push a log message to the spsc queue to be logged by the backend thread. + * One spsc queue per caller thread. This function is enabled only when all arguments are + * fundamental types. + * This is the fastest way possible to log + * @note This function is thread-safe. + * @param macro_metadata metadata of the log message + * @param fmt_args arguments + * + * @return true if the message is written to the queue, false if it is dropped (when a dropping queue is used) + */ + template + QUILL_ATTRIBUTE_HOT bool log_statement(MacroMetadata const* macro_metadata, Args&&... fmt_args) + { +#ifndef NDEBUG + assert(valid.load(std::memory_order_acquire) && "Invalidated loggers can not log"); +#endif + + // Store the timestamp of the log statement at the start of the call. This gives more accurate + // timestamp especially if the queue is full + // This is very rare but might lead to out of order timestamp in the log file if we block on push for too long + uint64_t const current_timestamp = _get_current_timestamp(); + if (QUILL_UNLIKELY(thread_context == nullptr)) { // This caches the ThreadContext pointer to avoid repeatedly calling get_local_thread_context() thread_context = detail::get_local_thread_context(); } + // Size of header + constexpr size_t header_size{sizeof(current_timestamp) + (sizeof(uintptr_t) * 3)}; + // Need to know how much size we need from the queue - size_t total_size = sizeof(current_timestamp) + (sizeof(uintptr_t) * 3) + + size_t const total_size = header_size + detail::compute_encoded_size_and_cache_string_lengths( - thread_context->get_conditional_arg_size_cache(), fmt_args...); - - if (dynamic_log_level != LogLevel::None) - { - // For the dynamic log level we want to add to the total size to store the dynamic log level - total_size += sizeof(dynamic_log_level); - } + thread_context->get_conditional_arg_size_cache(), fmt_args...); std::byte* write_buffer = _prepare_write_buffer(total_size); @@ -182,14 +279,6 @@ class LoggerImpl : public detail::LoggerBase // encode remaining arguments detail::encode(write_buffer, thread_context->get_conditional_arg_size_cache(), fmt_args...); - if (dynamic_log_level != LogLevel::None) - { - // write the dynamic log level - // The reason we write it last is that is less likely to break the alignment in the buffer - std::memcpy(write_buffer, &dynamic_log_level, sizeof(dynamic_log_level)); - write_buffer += sizeof(dynamic_log_level); - } - #ifndef NDEBUG assert((write_buffer > write_begin) && "write_buffer must be greater than write_begin"); assert(total_size == (static_cast(write_buffer - write_begin)) && @@ -222,7 +311,7 @@ class LoggerImpl : public detail::LoggerBase // we pass this message to the queue and also pass capacity as arg // We do not want to drop the message if a dropping queue is used - while (!this->log_statement(LogLevel::None, ¯o_metadata, max_capacity)) + while (!this->log_statement(¯o_metadata, max_capacity)) { std::this_thread::sleep_for(std::chrono::nanoseconds{100}); } @@ -241,7 +330,7 @@ class LoggerImpl : public detail::LoggerBase "", "", "", nullptr, LogLevel::Critical, MacroMetadata::Event::FlushBacktrace}; // We do not want to drop the message if a dropping queue is used - while (!this->log_statement(LogLevel::None, ¯o_metadata)) + while (!this->log_statement(¯o_metadata)) { std::this_thread::sleep_for(std::chrono::nanoseconds{100}); } @@ -272,8 +361,7 @@ class LoggerImpl : public detail::LoggerBase std::atomic* backend_thread_flushed_ptr = &backend_thread_flushed; // We do not want to drop the message if a dropping queue is used - while (!this->log_statement(LogLevel::None, ¯o_metadata, - reinterpret_cast(backend_thread_flushed_ptr))) + while (!this->log_statement(¯o_metadata, reinterpret_cast(backend_thread_flushed_ptr))) { if (sleep_duration_ns > 0) { @@ -307,8 +395,8 @@ class LoggerImpl : public detail::LoggerBase LoggerImpl(std::string logger_name, std::vector> sinks, PatternFormatterOptions pattern_formatter_options, ClockSourceType clock_source, UserClockSource* user_clock) - : detail::LoggerBase(static_cast(logger_name), - static_cast>&&>(sinks), + : detail::LoggerBase( + static_cast(logger_name), static_cast>&&>(sinks), static_cast(pattern_formatter_options), clock_source, user_clock) { @@ -318,7 +406,7 @@ class LoggerImpl : public detail::LoggerBase this->clock_source = ClockSourceType::User; } } - + /** * Encodes header information into the write buffer * @@ -347,6 +435,27 @@ class LoggerImpl : public detail::LoggerBase return write_buffer; } + /** + * Prepares a write buffer for the given context and size. + */ + QUILL_NODISCARD QUILL_ATTRIBUTE_HOT uint64_t _get_current_timestamp() const noexcept + { + if (clock_source == ClockSourceType::Tsc) + { + return detail::rdtsc(); + } + else if (clock_source == ClockSourceType::System) + { + return static_cast(std::chrono::duration_cast( + std::chrono::system_clock::now().time_since_epoch()) + .count()); + } + else + { + return user_clock->now(); + } + } + /** * Prepares a write buffer for the given context and size. */ diff --git a/include/quill/backend/SignalHandler.h b/include/quill/backend/SignalHandler.h index d6e06d62..8fed4f6a 100644 --- a/include/quill/backend/SignalHandler.h +++ b/include/quill/backend/SignalHandler.h @@ -75,9 +75,9 @@ class SignalHandlerContext if (logger->template should_log_statement()) \ { \ static constexpr quill::MacroMetadata macro_metadata{ \ - "SignalHandler:~", "", fmt, nullptr, log_level, quill::MacroMetadata::Event::Log}; \ - \ - logger->template log_statement(quill::LogLevel::None, ¯o_metadata, ##__VA_ARGS__); \ + "SignalHandler:~", "", fmt, nullptr, log_level, quill::MacroMetadata::Event::Log}; \ + \ + logger->template log_statement(¯o_metadata, ##__VA_ARGS__); \ } \ } while (0) From 87fb638761045d9555fcc17956d124098f511e05 Mon Sep 17 00:00:00 2001 From: odygrd Date: Sat, 21 Sep 2024 14:40:55 +0100 Subject: [PATCH 2/4] optimise total size calculation for when only arithmetic types are logged --- include/quill/Logger.h | 38 +++++++++++++++++++++++++++++--------- include/quill/core/Codec.h | 11 +++++++++++ 2 files changed, 40 insertions(+), 9 deletions(-) diff --git a/include/quill/Logger.h b/include/quill/Logger.h index bf28c44b..d1599642 100644 --- a/include/quill/Logger.h +++ b/include/quill/Logger.h @@ -98,13 +98,23 @@ class LoggerImpl : public detail::LoggerBase thread_context = detail::get_local_thread_context(); } - // For the dynamic log level we want to add to the total size to store the dynamic log level + // Size of header constexpr size_t header_size{sizeof(current_timestamp) + (sizeof(uintptr_t) * 3) + sizeof(dynamic_log_level)}; + size_t total_size{header_size}; - // Need to know how much size we need from the queue - size_t const total_size = header_size + - detail::compute_encoded_size_and_cache_string_lengths( - thread_context->get_conditional_arg_size_cache(), fmt_args...); + if constexpr (std::conjunction_v>, std::is_enum>, + std::is_same, void const*>>...>) + { + // optimisation when only arithmetic types + constexpr size_t total_args_size = + detail::compute_encoded_size_for_numeric_types...>(); + total_size += total_args_size; + } + else + { + total_size += detail::compute_encoded_size_and_cache_string_lengths( + thread_context->get_conditional_arg_size_cache(), fmt_args...); + } std::byte* write_buffer = _prepare_write_buffer(total_size); @@ -216,11 +226,21 @@ class LoggerImpl : public detail::LoggerBase // Size of header constexpr size_t header_size{sizeof(current_timestamp) + (sizeof(uintptr_t) * 3)}; + size_t total_size{header_size}; - // Need to know how much size we need from the queue - size_t const total_size = header_size + - detail::compute_encoded_size_and_cache_string_lengths( - thread_context->get_conditional_arg_size_cache(), fmt_args...); + if constexpr (std::conjunction_v>, std::is_enum>, + std::is_same, void const*>>...>) + { + // optimisation when only arithmetic types + constexpr size_t total_args_size = + detail::compute_encoded_size_for_numeric_types...>(); + total_size += total_args_size; + } + else + { + total_size += detail::compute_encoded_size_and_cache_string_lengths( + thread_context->get_conditional_arg_size_cache(), fmt_args...); + } std::byte* write_buffer = _prepare_write_buffer(total_size); diff --git a/include/quill/core/Codec.h b/include/quill/core/Codec.h index 88ea00de..03b0e0fc 100644 --- a/include/quill/core/Codec.h +++ b/include/quill/core/Codec.h @@ -277,6 +277,17 @@ QUILL_NODISCARD QUILL_ATTRIBUTE_HOT size_t compute_encoded_size_and_cache_string return total_sum; } +/** + * @brief Calculates the total size required to encode the provided arguments + * This is used only for arithmetic types + */ +template +QUILL_NODISCARD QUILL_ATTRIBUTE_HOT constexpr size_t compute_encoded_size_for_numeric_types() noexcept +{ + constexpr size_t total_sum = (0 + ... + sizeof(Args)); + return total_sum; +} + /** * @brief Encodes multiple arguments into a buffer. * @param buffer Pointer to the buffer for encoding. From a8ac73e87de6bb2abe26ba73f4b8541cd039a82d Mon Sep 17 00:00:00 2001 From: odygrd Date: Sat, 21 Sep 2024 21:08:51 +0100 Subject: [PATCH 3/4] optimise total size calculation for when only arithmetic types are logged --- include/quill/Logger.h | 333 ++++++++++++++++++++++++----------------- 1 file changed, 198 insertions(+), 135 deletions(-) diff --git a/include/quill/Logger.h b/include/quill/Logger.h index d1599642..e219bb32 100644 --- a/include/quill/Logger.h +++ b/include/quill/Logger.h @@ -29,6 +29,66 @@ QUILL_BEGIN_NAMESPACE +#define QUILL_PREPARE_QUEUE_WRITE_BUFFER \ + std::byte* write_buffer = _prepare_write_buffer(total_size); \ + \ + if constexpr (frontend_options_t::queue_type == QueueType::UnboundedUnlimited) \ + { \ + assert(write_buffer && \ + "Unbounded unlimited queue will always allocate and have enough capacity"); \ + } \ + else if constexpr ((frontend_options_t::queue_type == QueueType::BoundedDropping) || \ + (frontend_options_t::queue_type == QueueType::UnboundedDropping)) \ + { \ + if (QUILL_UNLIKELY(write_buffer == nullptr)) \ + { \ + if (macro_metadata->event() == MacroMetadata::Event::Log) \ + { \ + thread_context->increment_failure_counter(); \ + } \ + return false; \ + } \ + } \ + else if constexpr ((frontend_options_t::queue_type == QueueType::BoundedBlocking) || \ + (frontend_options_t::queue_type == QueueType::UnboundedBlocking)) \ + { \ + if (QUILL_UNLIKELY(write_buffer == nullptr)) \ + { \ + if (macro_metadata->event() == MacroMetadata::Event::Log) \ + { \ + thread_context->increment_failure_counter(); \ + } \ + \ + do \ + { \ + if constexpr (frontend_options_t::blocking_queue_retry_interval_ns > 0) \ + { \ + std::this_thread::sleep_for(std::chrono::nanoseconds{frontend_options_t::blocking_queue_retry_interval_ns}); \ + } \ + \ + /** not enough space to push to queue, keep trying **/ \ + write_buffer = _prepare_write_buffer(total_size); \ + } while (write_buffer == nullptr); \ + } \ + } + +#define QUILL_FINALIZE_QUEUE_WRITE \ + thread_context->get_spsc_queue().finish_write(total_size); \ + thread_context->get_spsc_queue().commit_write(); \ + \ + if constexpr (immediate_flush) \ + { \ + this->flush_log(); \ + } + +#define QUILL_ENCODE_DATA \ + /** first encode a header **/ \ + write_buffer = _encode_header(write_buffer, current_timestamp, macro_metadata, this, \ + detail::decode_and_store_args...>); \ + \ + /** encode remaining arguments **/ \ + detail::encode(write_buffer, thread_context->get_conditional_arg_size_cache(), fmt_args...); + /** Forward Declarations **/ class Sink; @@ -68,8 +128,11 @@ class LoggerImpl : public detail::LoggerBase * @return true if the message is written to the queue, false if it is dropped (when a dropping queue is used) */ template - QUILL_ATTRIBUTE_HOT bool log_statement(LogLevel dynamic_log_level, - MacroMetadata const* macro_metadata, Args&&... fmt_args) + QUILL_ATTRIBUTE_HOT std::enable_if_t< + std::conjunction_v>, std::is_enum>, + std::is_same, void const*>>...>, + bool> + log_statement(LogLevel dynamic_log_level, MacroMetadata const* macro_metadata, Args&&... fmt_args) { #ifndef NDEBUG if (dynamic_log_level != quill::LogLevel::None) @@ -98,67 +161,77 @@ class LoggerImpl : public detail::LoggerBase thread_context = detail::get_local_thread_context(); } - // Size of header - constexpr size_t header_size{sizeof(current_timestamp) + (sizeof(uintptr_t) * 3) + sizeof(dynamic_log_level)}; - size_t total_size{header_size}; + constexpr size_t total_size{ + sizeof(current_timestamp) + (sizeof(uintptr_t) * 3) + sizeof(dynamic_log_level) + + detail::compute_encoded_size_for_numeric_types...>()}; - if constexpr (std::conjunction_v>, std::is_enum>, - std::is_same, void const*>>...>) - { - // optimisation when only arithmetic types - constexpr size_t total_args_size = - detail::compute_encoded_size_for_numeric_types...>(); - total_size += total_args_size; - } - else - { - total_size += detail::compute_encoded_size_and_cache_string_lengths( - thread_context->get_conditional_arg_size_cache(), fmt_args...); - } + QUILL_PREPARE_QUEUE_WRITE_BUFFER + + // we have enough space in this buffer, and we will write to the buffer + +#ifndef NDEBUG + std::byte const* const write_begin = write_buffer; + assert(write_begin); +#endif + + QUILL_ENCODE_DATA + + // write the dynamic log level + // The reason we write it last is that is less likely to break the alignment in the buffer + std::memcpy(write_buffer, &dynamic_log_level, sizeof(dynamic_log_level)); + write_buffer += sizeof(dynamic_log_level); + +#ifndef NDEBUG + assert((write_buffer > write_begin) && "write_buffer must be greater than write_begin"); + assert(total_size == (static_cast(write_buffer - write_begin)) && + "The committed write bytes must be equal to the total_size requested bytes"); +#endif + + QUILL_FINALIZE_QUEUE_WRITE - std::byte* write_buffer = _prepare_write_buffer(total_size); + return true; + } - if constexpr (frontend_options_t::queue_type == QueueType::UnboundedUnlimited) + template + QUILL_ATTRIBUTE_HOT std::enable_if_t< + !std::conjunction_v>, std::is_enum>, + std::is_same, void const*>>...>, + bool> + log_statement(LogLevel dynamic_log_level, MacroMetadata const* macro_metadata, Args&&... fmt_args) + { +#ifndef NDEBUG + if (dynamic_log_level != quill::LogLevel::None) { - assert(write_buffer && - "Unbounded unlimited queue will always allocate and have enough capacity"); + assert((macro_metadata->log_level() == quill::LogLevel::Dynamic) && + "MacroMetadata LogLevel must be Dynamic when using a dynamic_log_level"); } - else if constexpr ((frontend_options_t::queue_type == QueueType::BoundedDropping) || - (frontend_options_t::queue_type == QueueType::UnboundedDropping)) + + if (macro_metadata->log_level() != quill::LogLevel::Dynamic) { - if (QUILL_UNLIKELY(write_buffer == nullptr)) - { - // not enough space to push to queue message is dropped - if (macro_metadata->event() == MacroMetadata::Event::Log) - { - thread_context->increment_failure_counter(); - } - return false; - } + assert((dynamic_log_level == quill::LogLevel::None) && + "No dynamic_log_level should be set when MacroMetadata LogLevel is not Dynamic"); } - else if constexpr ((frontend_options_t::queue_type == QueueType::BoundedBlocking) || - (frontend_options_t::queue_type == QueueType::UnboundedBlocking)) + + assert(valid.load(std::memory_order_acquire) && "Invalidated loggers can not log"); +#endif + + // Store the timestamp of the log statement at the start of the call. This gives more accurate + // timestamp especially if the queue is full + // This is very rare but might lead to out of order timestamp in the log file if we block on push for too long + uint64_t const current_timestamp = _get_current_timestamp(); + + if (QUILL_UNLIKELY(thread_context == nullptr)) { - if (QUILL_UNLIKELY(write_buffer == nullptr)) - { - if (macro_metadata->event() == MacroMetadata::Event::Log) - { - thread_context->increment_failure_counter(); - } - - do - { - if constexpr (frontend_options_t::blocking_queue_retry_interval_ns > 0) - { - std::this_thread::sleep_for(std::chrono::nanoseconds{frontend_options_t::blocking_queue_retry_interval_ns}); - } - - // not enough space to push to queue, keep trying - write_buffer = _prepare_write_buffer(total_size); - } while (write_buffer == nullptr); - } + // This caches the ThreadContext pointer to avoid repeatedly calling get_local_thread_context() + thread_context = detail::get_local_thread_context(); } + size_t const total_size{sizeof(current_timestamp) + (sizeof(uintptr_t) * 3) + sizeof(dynamic_log_level) + + detail::compute_encoded_size_and_cache_string_lengths( + thread_context->get_conditional_arg_size_cache(), fmt_args...)}; + + QUILL_PREPARE_QUEUE_WRITE_BUFFER + // we have enough space in this buffer, and we will write to the buffer #ifndef NDEBUG @@ -166,12 +239,7 @@ class LoggerImpl : public detail::LoggerBase assert(write_begin); #endif - // first encode a header - write_buffer = _encode_header(write_buffer, current_timestamp, macro_metadata, this, - detail::decode_and_store_args...>); - - // encode remaining arguments - detail::encode(write_buffer, thread_context->get_conditional_arg_size_cache(), fmt_args...); + QUILL_ENCODE_DATA // write the dynamic log level // The reason we write it last is that is less likely to break the alignment in the buffer @@ -184,13 +252,7 @@ class LoggerImpl : public detail::LoggerBase "The committed write bytes must be equal to the total_size requested bytes"); #endif - thread_context->get_spsc_queue().finish_write(total_size); - thread_context->get_spsc_queue().commit_write(); - - if constexpr (immediate_flush) - { - this->flush_log(); - } + QUILL_FINALIZE_QUEUE_WRITE return true; } @@ -207,7 +269,11 @@ class LoggerImpl : public detail::LoggerBase * @return true if the message is written to the queue, false if it is dropped (when a dropping queue is used) */ template - QUILL_ATTRIBUTE_HOT bool log_statement(MacroMetadata const* macro_metadata, Args&&... fmt_args) + QUILL_ATTRIBUTE_HOT std::enable_if_t< + std::conjunction_v>, std::is_enum>, + std::is_same, void const*>>...>, + bool> + log_statement(MacroMetadata const* macro_metadata, Args&&... fmt_args) { #ifndef NDEBUG assert(valid.load(std::memory_order_acquire) && "Invalidated loggers can not log"); @@ -224,67 +290,71 @@ class LoggerImpl : public detail::LoggerBase thread_context = detail::get_local_thread_context(); } - // Size of header - constexpr size_t header_size{sizeof(current_timestamp) + (sizeof(uintptr_t) * 3)}; - size_t total_size{header_size}; + constexpr size_t total_size{ + sizeof(current_timestamp) + (sizeof(uintptr_t) * 3) + + detail::compute_encoded_size_for_numeric_types...>()}; - if constexpr (std::conjunction_v>, std::is_enum>, - std::is_same, void const*>>...>) - { - // optimisation when only arithmetic types - constexpr size_t total_args_size = - detail::compute_encoded_size_for_numeric_types...>(); - total_size += total_args_size; - } - else - { - total_size += detail::compute_encoded_size_and_cache_string_lengths( - thread_context->get_conditional_arg_size_cache(), fmt_args...); - } + QUILL_PREPARE_QUEUE_WRITE_BUFFER - std::byte* write_buffer = _prepare_write_buffer(total_size); + // we have enough space in this buffer, and we will write to the buffer - if constexpr (frontend_options_t::queue_type == QueueType::UnboundedUnlimited) - { - assert(write_buffer && - "Unbounded unlimited queue will always allocate and have enough capacity"); - } - else if constexpr ((frontend_options_t::queue_type == QueueType::BoundedDropping) || - (frontend_options_t::queue_type == QueueType::UnboundedDropping)) - { - if (QUILL_UNLIKELY(write_buffer == nullptr)) - { - // not enough space to push to queue message is dropped - if (macro_metadata->event() == MacroMetadata::Event::Log) - { - thread_context->increment_failure_counter(); - } - return false; - } - } - else if constexpr ((frontend_options_t::queue_type == QueueType::BoundedBlocking) || - (frontend_options_t::queue_type == QueueType::UnboundedBlocking)) +#ifndef NDEBUG + std::byte const* const write_begin = write_buffer; + assert(write_begin); +#endif + + QUILL_ENCODE_DATA + +#ifndef NDEBUG + assert((write_buffer > write_begin) && "write_buffer must be greater than write_begin"); + assert(total_size == (static_cast(write_buffer - write_begin)) && + "The committed write bytes must be equal to the total_size requested bytes"); +#endif + + QUILL_FINALIZE_QUEUE_WRITE + + return true; + } + + /** + * Push a log message to the spsc queue to be logged by the backend thread. + * One spsc queue per caller thread. This function is enabled only when all arguments are + * fundamental types. + * This is the fastest way possible to log + * @note This function is thread-safe. + * @param macro_metadata metadata of the log message + * @param fmt_args arguments + * + * @return true if the message is written to the queue, false if it is dropped (when a dropping queue is used) + */ + template + QUILL_ATTRIBUTE_HOT std::enable_if_t< + !std::conjunction_v>, std::is_enum>, + std::is_same, void const*>>...>, + bool> + log_statement(MacroMetadata const* macro_metadata, Args&&... fmt_args) + { +#ifndef NDEBUG + assert(valid.load(std::memory_order_acquire) && "Invalidated loggers can not log"); +#endif + + // Store the timestamp of the log statement at the start of the call. This gives more accurate + // timestamp especially if the queue is full + // This is very rare but might lead to out of order timestamp in the log file if we block on push for too long + uint64_t const current_timestamp = _get_current_timestamp(); + + if (QUILL_UNLIKELY(thread_context == nullptr)) { - if (QUILL_UNLIKELY(write_buffer == nullptr)) - { - if (macro_metadata->event() == MacroMetadata::Event::Log) - { - thread_context->increment_failure_counter(); - } - - do - { - if constexpr (frontend_options_t::blocking_queue_retry_interval_ns > 0) - { - std::this_thread::sleep_for(std::chrono::nanoseconds{frontend_options_t::blocking_queue_retry_interval_ns}); - } - - // not enough space to push to queue, keep trying - write_buffer = _prepare_write_buffer(total_size); - } while (write_buffer == nullptr); - } + // This caches the ThreadContext pointer to avoid repeatedly calling get_local_thread_context() + thread_context = detail::get_local_thread_context(); } + size_t const total_size{sizeof(current_timestamp) + (sizeof(uintptr_t) * 3) + + detail::compute_encoded_size_and_cache_string_lengths( + thread_context->get_conditional_arg_size_cache(), fmt_args...)}; + + QUILL_PREPARE_QUEUE_WRITE_BUFFER + // we have enough space in this buffer, and we will write to the buffer #ifndef NDEBUG @@ -292,12 +362,7 @@ class LoggerImpl : public detail::LoggerBase assert(write_begin); #endif - // first encode a header - write_buffer = _encode_header(write_buffer, current_timestamp, macro_metadata, this, - detail::decode_and_store_args...>); - - // encode remaining arguments - detail::encode(write_buffer, thread_context->get_conditional_arg_size_cache(), fmt_args...); + QUILL_ENCODE_DATA #ifndef NDEBUG assert((write_buffer > write_begin) && "write_buffer must be greater than write_begin"); @@ -305,13 +370,7 @@ class LoggerImpl : public detail::LoggerBase "The committed write bytes must be equal to the total_size requested bytes"); #endif - thread_context->get_spsc_queue().finish_write(total_size); - thread_context->get_spsc_queue().commit_write(); - - if constexpr (immediate_flush) - { - this->flush_log(); - } + QUILL_FINALIZE_QUEUE_WRITE return true; } @@ -505,4 +564,8 @@ class LoggerImpl : public detail::LoggerBase using Logger = LoggerImpl; +#undef QUILL_PREPARE_QUEUE_WRITE_BUFFER +#undef QUILL_ENCODE_DATA +#undef QUILL_FINALIZE_QUEUE_WRITE + QUILL_END_NAMESPACE From a46c553804a2b0e2a0b2b8b2874bd744cc5b41fc Mon Sep 17 00:00:00 2001 From: Odysseas Georgoudis Date: Sun, 22 Sep 2024 01:30:18 +0100 Subject: [PATCH 4/4] zz --- include/quill/Logger.h | 107 +++++++++++++++-------------------------- 1 file changed, 40 insertions(+), 67 deletions(-) diff --git a/include/quill/Logger.h b/include/quill/Logger.h index e219bb32..57357b69 100644 --- a/include/quill/Logger.h +++ b/include/quill/Logger.h @@ -25,11 +25,38 @@ #include #include #include +#include #include QUILL_BEGIN_NAMESPACE -#define QUILL_PREPARE_QUEUE_WRITE_BUFFER \ +#define INITIALISE_TIMESTAMP_AND_THREAD_CONTEXT \ + /** Store the timestamp of the log statement at the start of the call. This gives more accurate \ + * timestamp especially if the queue is full This is very rare but might lead to out of order \ + * timestamp in the log file if we block on push for too long */ \ + uint64_t current_timestamp; \ + if (clock_source == ClockSourceType::Tsc) \ + { \ + current_timestamp = detail::rdtsc(); \ + } \ + else if (clock_source == ClockSourceType::System) \ + { \ + current_timestamp = static_cast(std::chrono::duration_cast( \ + std::chrono::system_clock::now().time_since_epoch()) \ + .count()); \ + } \ + else \ + { \ + current_timestamp = user_clock->now(); \ + } \ + \ + if (QUILL_UNLIKELY(thread_context == nullptr)) \ + { \ + /** This caches the ThreadContext pointer to avoid calling get_local_thread_context() */ \ + thread_context = detail::get_local_thread_context(); \ + } + +#define QUILL_PREPARE_QUEUE_WRITE \ std::byte* write_buffer = _prepare_write_buffer(total_size); \ \ if constexpr (frontend_options_t::queue_type == QueueType::UnboundedUnlimited) \ @@ -150,22 +177,14 @@ class LoggerImpl : public detail::LoggerBase assert(valid.load(std::memory_order_acquire) && "Invalidated loggers can not log"); #endif - // Store the timestamp of the log statement at the start of the call. This gives more accurate - // timestamp especially if the queue is full - // This is very rare but might lead to out of order timestamp in the log file if we block on push for too long - uint64_t const current_timestamp = _get_current_timestamp(); - - if (QUILL_UNLIKELY(thread_context == nullptr)) - { - // This caches the ThreadContext pointer to avoid repeatedly calling get_local_thread_context() - thread_context = detail::get_local_thread_context(); - } + INITIALISE_TIMESTAMP_AND_THREAD_CONTEXT + // Include dynamic_log_level in the total size constexpr size_t total_size{ sizeof(current_timestamp) + (sizeof(uintptr_t) * 3) + sizeof(dynamic_log_level) + detail::compute_encoded_size_for_numeric_types...>()}; - QUILL_PREPARE_QUEUE_WRITE_BUFFER + QUILL_PREPARE_QUEUE_WRITE // we have enough space in this buffer, and we will write to the buffer @@ -215,22 +234,14 @@ class LoggerImpl : public detail::LoggerBase assert(valid.load(std::memory_order_acquire) && "Invalidated loggers can not log"); #endif - // Store the timestamp of the log statement at the start of the call. This gives more accurate - // timestamp especially if the queue is full - // This is very rare but might lead to out of order timestamp in the log file if we block on push for too long - uint64_t const current_timestamp = _get_current_timestamp(); - - if (QUILL_UNLIKELY(thread_context == nullptr)) - { - // This caches the ThreadContext pointer to avoid repeatedly calling get_local_thread_context() - thread_context = detail::get_local_thread_context(); - } + INITIALISE_TIMESTAMP_AND_THREAD_CONTEXT + // Include dynamic_log_level in the total size size_t const total_size{sizeof(current_timestamp) + (sizeof(uintptr_t) * 3) + sizeof(dynamic_log_level) + detail::compute_encoded_size_and_cache_string_lengths( thread_context->get_conditional_arg_size_cache(), fmt_args...)}; - QUILL_PREPARE_QUEUE_WRITE_BUFFER + QUILL_PREPARE_QUEUE_WRITE // we have enough space in this buffer, and we will write to the buffer @@ -279,22 +290,13 @@ class LoggerImpl : public detail::LoggerBase assert(valid.load(std::memory_order_acquire) && "Invalidated loggers can not log"); #endif - // Store the timestamp of the log statement at the start of the call. This gives more accurate - // timestamp especially if the queue is full - // This is very rare but might lead to out of order timestamp in the log file if we block on push for too long - uint64_t const current_timestamp = _get_current_timestamp(); - - if (QUILL_UNLIKELY(thread_context == nullptr)) - { - // This caches the ThreadContext pointer to avoid repeatedly calling get_local_thread_context() - thread_context = detail::get_local_thread_context(); - } + INITIALISE_TIMESTAMP_AND_THREAD_CONTEXT constexpr size_t total_size{ sizeof(current_timestamp) + (sizeof(uintptr_t) * 3) + detail::compute_encoded_size_for_numeric_types...>()}; - QUILL_PREPARE_QUEUE_WRITE_BUFFER + QUILL_PREPARE_QUEUE_WRITE // we have enough space in this buffer, and we will write to the buffer @@ -338,22 +340,13 @@ class LoggerImpl : public detail::LoggerBase assert(valid.load(std::memory_order_acquire) && "Invalidated loggers can not log"); #endif - // Store the timestamp of the log statement at the start of the call. This gives more accurate - // timestamp especially if the queue is full - // This is very rare but might lead to out of order timestamp in the log file if we block on push for too long - uint64_t const current_timestamp = _get_current_timestamp(); - - if (QUILL_UNLIKELY(thread_context == nullptr)) - { - // This caches the ThreadContext pointer to avoid repeatedly calling get_local_thread_context() - thread_context = detail::get_local_thread_context(); - } + INITIALISE_TIMESTAMP_AND_THREAD_CONTEXT size_t const total_size{sizeof(current_timestamp) + (sizeof(uintptr_t) * 3) + detail::compute_encoded_size_and_cache_string_lengths( thread_context->get_conditional_arg_size_cache(), fmt_args...)}; - QUILL_PREPARE_QUEUE_WRITE_BUFFER + QUILL_PREPARE_QUEUE_WRITE // we have enough space in this buffer, and we will write to the buffer @@ -514,27 +507,6 @@ class LoggerImpl : public detail::LoggerBase return write_buffer; } - /** - * Prepares a write buffer for the given context and size. - */ - QUILL_NODISCARD QUILL_ATTRIBUTE_HOT uint64_t _get_current_timestamp() const noexcept - { - if (clock_source == ClockSourceType::Tsc) - { - return detail::rdtsc(); - } - else if (clock_source == ClockSourceType::System) - { - return static_cast(std::chrono::duration_cast( - std::chrono::system_clock::now().time_since_epoch()) - .count()); - } - else - { - return user_clock->now(); - } - } - /** * Prepares a write buffer for the given context and size. */ @@ -564,8 +536,9 @@ class LoggerImpl : public detail::LoggerBase using Logger = LoggerImpl; -#undef QUILL_PREPARE_QUEUE_WRITE_BUFFER +#undef QUILL_PREPARE_QUEUE_WRITE #undef QUILL_ENCODE_DATA #undef QUILL_FINALIZE_QUEUE_WRITE +#undef INITIALISE_TIMESTAMP_AND_THREAD_CONTEXT QUILL_END_NAMESPACE