Skip to content

Commit

Permalink
Add sink_min_flush_interval option in BackendOptions to control m…
Browse files Browse the repository at this point in the history
…inimum flush interval for all sinks
  • Loading branch information
odygrd committed Jan 12, 2025
1 parent 25a4572 commit f3012f9
Show file tree
Hide file tree
Showing 3 changed files with 52 additions and 14 deletions.
5 changes: 5 additions & 0 deletions CHANGELOG.md
Original file line number Diff line number Diff line change
Expand Up @@ -97,6 +97,11 @@
`quill::ConsoleSink::ColourMode`.
- Changed class member visibility in `FileSink`, `JsonSink`, and `RotatingSink` from private to protected, enabling
easier customization through inheritance for user-defined implementations.
- Added a new `sink_min_flush_interval` option in `BackendOptions`, which specifies the minimum time interval (in
milliseconds) before the backend thread flushes the output buffers calling `flush_sink()` for all sinks, with a
default value of 200ms; The backend thread ensures sinks aren't flushed more frequently than this interval, while
explicit calls to `logger->flush_log()` trigger an immediate flush, and flushing may occur less frequently if the
backend thread is busy, with this setting applying globally to all sinks.
- Added a `StopWatch` utility for easy logging of elapsed time. It can log the time elapsed since construction in
various formats. You can use either `quill::StopWatchTsc` for high-resolution TSC-based timing or
`quill::StopWatchChrono` for standard std::chrono-based timing. ([#640](https://github.com/odygrd/quill/issues/640))
Expand Down
14 changes: 14 additions & 0 deletions include/quill/backend/BackendOptions.h
Original file line number Diff line number Diff line change
Expand Up @@ -183,6 +183,20 @@ struct BackendOptions
*/
std::chrono::milliseconds rdtsc_resync_interval = std::chrono::milliseconds{500};

/**
* This option specifies the minimum time interval (in milliseconds) before the backend thread
* flushes the output buffers (flush_sink()) for all sinks in the application.
*
* The backend thread will ensure that no sink is flushed more frequently than this interval.
* Explicit calls to `logger->flush_log()` override this interval and trigger an immediate flush.
*
* However, if the backend thread is actively processing messages, flushing may occur less
* frequently than the specified interval.
*
* This setting applies globally and affects all sinks in the application.
*/
std::chrono::milliseconds sink_min_flush_interval = std::chrono::milliseconds{200};

/**
* This option enables a check that verifies the log message contains only printable characters
* before forwarding it to the sinks. This adds an extra layer of safety by filtering out
Expand Down
47 changes: 33 additions & 14 deletions include/quill/backend/BackendWorker.h
Original file line number Diff line number Diff line change
Expand Up @@ -296,7 +296,7 @@ class BackendWorker
// No cached transit events to process, minimal thread workload.

// force flush all remaining messages
_flush_and_run_active_sinks(true);
_flush_and_run_active_sinks(true, _options.sink_min_flush_interval);

// check for any dropped messages / blocked threads
_check_failure_counter(_options.error_notifier);
Expand Down Expand Up @@ -391,7 +391,7 @@ class BackendWorker
{
// we are done, all queues are now empty
_check_failure_counter(_options.error_notifier);
_flush_and_run_active_sinks(false);
_flush_and_run_active_sinks(false, std::chrono::milliseconds{0});
break;
}

Expand Down Expand Up @@ -536,7 +536,7 @@ class BackendWorker
// Lazy initialization of rdtsc clock on the backend thread only if the user decides to use
// it. The clock requires a few seconds to init as it is taking samples first.
_rdtsc_clock.store(new RdtscClock{_options.rdtsc_resync_interval}, std::memory_order_release);
_last_rdtsc_resync_time = std::chrono::system_clock::now();
_last_rdtsc_resync_time = std::chrono::steady_clock::now();
}

// Convert the rdtsc value to nanoseconds since epoch.
Expand Down Expand Up @@ -834,7 +834,7 @@ class BackendWorker
}
else if (transit_event.macro_metadata->event() == MacroMetadata::Event::Flush)
{
_flush_and_run_active_sinks(false);
_flush_and_run_active_sinks(false, std::chrono::milliseconds{0});

// This is a flush event, so we capture the flush flag to notify the caller after processing.
flush_flag = transit_event.flush_flag;
Expand Down Expand Up @@ -886,11 +886,11 @@ class BackendWorker
// proceed after ensuring a pattern formatter exists
std::string_view const log_level_description =
log_level_to_string(transit_event.log_level(), _options.log_level_descriptions.data(),
_options.log_level_descriptions.size());
_options.log_level_descriptions.size());

std::string_view const log_level_short_code =
log_level_to_string(transit_event.log_level(), _options.log_level_short_codes.data(),
_options.log_level_short_codes.size());
_options.log_level_short_codes.size());

if (transit_event.logger_base->pattern_formatter->get_options().add_metadata_to_multi_line_logs &&
(!transit_event.named_args || transit_event.named_args->empty()))
Expand Down Expand Up @@ -1165,8 +1165,7 @@ class BackendWorker
if (_rdtsc_clock.load(std::memory_order_relaxed))
{
// resync in rdtsc if we are not logging so that time_since_epoch() still works

if (auto const now = std::chrono::system_clock::now();
if (auto const now = std::chrono::steady_clock::now();
(now - _last_rdtsc_resync_time) > _options.rdtsc_resync_interval)
{
if (_rdtsc_clock.load(std::memory_order_relaxed)->resync(2500))
Expand All @@ -1178,7 +1177,7 @@ class BackendWorker
}

/***/
QUILL_ATTRIBUTE_HOT void _flush_and_run_active_sinks(bool run_periodic_tasks)
QUILL_ATTRIBUTE_HOT void _flush_and_run_active_sinks(bool run_periodic_tasks, std::chrono::milliseconds sink_min_flush_interval)
{
// Populate the active sinks cache with unique sinks, consider only the valid loggers
_logger_manager.for_each_logger(
Expand Down Expand Up @@ -1208,14 +1207,33 @@ class BackendWorker
return false;
});

bool should_flush_sinks{false};
if (sink_min_flush_interval.count())
{
// conditional flush sinks
if (auto const now = std::chrono::steady_clock::now(); (now - _last_sink_flush_time) > sink_min_flush_interval)
{
should_flush_sinks = true;
_last_sink_flush_time = now;
}
}
else
{
// sink_min_flush_interval == 0 - always flush sinks
should_flush_sinks = true;
}

for (auto const& sink : _active_sinks_cache)
{
QUILL_TRY
{
// If an exception is thrown, catch it here to prevent it from propagating
// to the outer function. This prevents potential infinite loops caused by failing
// flush operations.
sink->flush_sink();
if (should_flush_sinks)
{
// If an exception is thrown, catch it here to prevent it from propagating
// to the outer function. This prevents potential infinite loops caused by failing
// flush operations.
sink->flush_sink();
}
}
#if !defined(QUILL_NO_EXCEPTIONS)
QUILL_CATCH(std::exception const& e) { _options.error_notifier(e.what()); }
Expand Down Expand Up @@ -1542,7 +1560,8 @@ class BackendWorker

std::string _named_args_format_template; /** to avoid allocation each time **/
std::string _process_id; /** Id of the current running process **/
std::chrono::system_clock::time_point _last_rdtsc_resync_time;
std::chrono::steady_clock::time_point _last_rdtsc_resync_time;
std::chrono::steady_clock::time_point _last_sink_flush_time;
std::atomic<uint32_t> _worker_thread_id{0}; /** cached backend worker thread id */
std::atomic<bool> _is_worker_running{false}; /** The spawned backend thread status */

Expand Down

0 comments on commit f3012f9

Please sign in to comment.