Skip to content

Commit

Permalink
Revert "Use a separate function overload for when dynamic log level i…
Browse files Browse the repository at this point in the history 
…s used"

This reverts commit 3c977bc.
  • Loading branch information
@odygrd
odygrd committed Sep 21, 2024
1 parent 3c977bc commit 4ec51bd
Show file tree
Hide file tree
Showing 4 changed files with 43 additions and 152 deletions.
8 changes: 4 additions & 4 deletions include/quill/CsvWriter.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -63,7 +63,7 @@ class CsvWriter
}()),
quill::PatternFormatterOptions{"%(message)", "", Timezone::GmtTime});

_logger->template log_statement<false>(&header_metadata, TCsvSchema::header);
_logger->template log_statement<false>(quill::LogLevel::None, &header_metadata, TCsvSchema::header);
}

/**
Expand All @@ -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<false>(&header_metadata, TCsvSchema::header);
_logger->template log_statement<false>(quill::LogLevel::None, &header_metadata, TCsvSchema::header);
}

/**
Expand All @@ -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<false>(&header_metadata, TCsvSchema::header);
_logger->template log_statement<false>(quill::LogLevel::None, &header_metadata, TCsvSchema::header);
}

/**
Expand All @@ -112,7 +112,7 @@ class CsvWriter
template <typename... Args>
void append_row(Args&&... fields)
{
_logger->template log_statement<false>(&line_metadata, fields...);
_logger->template log_statement<false>(quill::LogLevel::None, &line_metadata, fields...);
}

/**
Expand Down
8 changes: 4 additions & 4 deletions include/quill/LogMacros.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -307,8 +307,8 @@
{ \
if (likelyhood(logger->template should_log_statement<log_level>())) \
{ \
QUILL_DEFINE_MACRO_METADATA(__FUNCTION__, fmt, tags, log_level); \
logger->template log_statement<QUILL_IMMEDIATE_FLUSH>(&macro_metadata, ##__VA_ARGS__); \
QUILL_DEFINE_MACRO_METADATA(__FUNCTION__, fmt, tags, log_level); \
logger->template log_statement<QUILL_IMMEDIATE_FLUSH>(quill::LogLevel::None, &macro_metadata, ##__VA_ARGS__); \
} \
} while (0)

Expand All @@ -335,8 +335,8 @@
{ \
if (QUILL_LIKELY(logger->template should_log_statement<quill::LogLevel::Backtrace>())) \
{ \
QUILL_DEFINE_MACRO_METADATA(__FUNCTION__, fmt, tags, quill::LogLevel::Backtrace); \
logger->template log_statement<QUILL_IMMEDIATE_FLUSH>(&macro_metadata, ##__VA_ARGS__); \
QUILL_DEFINE_MACRO_METADATA(__FUNCTION__, fmt, tags, quill::LogLevel::Backtrace); \
logger->template log_statement<QUILL_IMMEDIATE_FLUSH>(quill::LogLevel::None, &macro_metadata, ##__VA_ARGS__); \
} \
} while (0)

Expand Down
173 changes: 32 additions & 141 deletions include/quill/Logger.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -90,137 +90,40 @@ 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();

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

// 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);
uint64_t current_timestamp;

if constexpr (frontend_options_t::queue_type == QueueType::UnboundedUnlimited)
if (clock_source == ClockSourceType::Tsc)
{
assert(write_buffer &&
"Unbounded unlimited queue will always allocate and have enough capacity");
current_timestamp = detail::rdtsc();
}
else if constexpr ((frontend_options_t::queue_type == QueueType::BoundedDropping) ||
(frontend_options_t::queue_type == QueueType::UnboundedDropping))
else if (clock_source == ClockSourceType::System)
{
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;
}
current_timestamp = static_cast<uint64_t>(std::chrono::duration_cast<std::chrono::nanoseconds>(
std::chrono::system_clock::now().time_since_epoch())
.count());
}
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<detail::remove_cvref_t<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<size_t>(write_buffer - write_begin)) &&
"The committed write bytes must be equal to the total_size requested bytes");
#endif

thread_context->get_spsc_queue<frontend_options_t::queue_type>().finish_write(total_size);
thread_context->get_spsc_queue<frontend_options_t::queue_type>().commit_write();

if constexpr (immediate_flush)
else
{
this->flush_log();
current_timestamp = user_clock->now();
}

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 <bool immediate_flush, typename... Args>
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<frontend_options_t>();
}

// 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 const total_size = header_size +
size_t 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...);
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);
}

std::byte* write_buffer = _prepare_write_buffer(total_size);

Expand Down Expand Up @@ -279,6 +182,14 @@ 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<size_t>(write_buffer - write_begin)) &&
Expand Down Expand Up @@ -311,7 +222,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<false>(&macro_metadata, max_capacity))
while (!this->log_statement<false>(LogLevel::None, &macro_metadata, max_capacity))
{
std::this_thread::sleep_for(std::chrono::nanoseconds{100});
}
Expand All @@ -330,7 +241,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<false>(&macro_metadata))
while (!this->log_statement<false>(LogLevel::None, &macro_metadata))
{
std::this_thread::sleep_for(std::chrono::nanoseconds{100});
}
Expand Down Expand Up @@ -361,7 +272,8 @@ class LoggerImpl : public detail::LoggerBase
std::atomic<bool>* 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<false>(&macro_metadata, reinterpret_cast<uintptr_t>(backend_thread_flushed_ptr)))
while (!this->log_statement<false>(LogLevel::None, &macro_metadata,
reinterpret_cast<uintptr_t>(backend_thread_flushed_ptr)))
{
if (sleep_duration_ns > 0)
{
Expand Down Expand Up @@ -395,8 +307,8 @@ class LoggerImpl : public detail::LoggerBase
LoggerImpl(std::string logger_name, std::vector<std::shared_ptr<Sink>> sinks,
PatternFormatterOptions pattern_formatter_options, ClockSourceType clock_source,
UserClockSource* user_clock)
: detail::LoggerBase(
static_cast<std::string&&>(logger_name), static_cast<std::vector<std::shared_ptr<Sink>>&&>(sinks),
: detail::LoggerBase(static_cast<std::string&&>(logger_name),
static_cast<std::vector<std::shared_ptr<Sink>>&&>(sinks),
static_cast<PatternFormatterOptions&&>(pattern_formatter_options), clock_source, user_clock)

{
Expand All @@ -406,7 +318,7 @@ class LoggerImpl : public detail::LoggerBase
this->clock_source = ClockSourceType::User;
}
}

/**
* Encodes header information into the write buffer
*
Expand Down Expand Up @@ -435,27 +347,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<uint64_t>(std::chrono::duration_cast<std::chrono::nanoseconds>(
std::chrono::system_clock::now().time_since_epoch())
.count());
}
else
{
return user_clock->now();
}
}

/**
* Prepares a write buffer for the given context and size.
*/
Expand Down
6 changes: 3 additions & 3 deletions include/quill/backend/SignalHandler.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -75,9 +75,9 @@ class SignalHandlerContext
if (logger->template should_log_statement<log_level>()) \
{ \
static constexpr quill::MacroMetadata macro_metadata{ \
"SignalHandler:~", "", fmt, nullptr, log_level, quill::MacroMetadata::Event::Log}; \
\
logger->template log_statement<false>(&macro_metadata, ##__VA_ARGS__); \
"SignalHandler:~", "", fmt, nullptr, log_level, quill::MacroMetadata::Event::Log}; \
\
logger->template log_statement<false>(quill::LogLevel::None, &macro_metadata, ##__VA_ARGS__); \
} \
} while (0)

Expand Down

0 comments on commit 4ec51bd

Please sign in to comment.