fix(logger): reduce logging overhead on request threads#41
Open
Trojan-254 wants to merge 1 commit intoAz107:masterfrom
Open
fix(logger): reduce logging overhead on request threads#41Trojan-254 wants to merge 1 commit intoAz107:masterfrom
Trojan-254 wants to merge 1 commit intoAz107:masterfrom
Conversation
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
fix(logger): reduce logging overhead on request threads
Problem
Despite the logger running in a background thread, logging was introducing measurable latency on the request-handling path. Benchmarks showed a ~32% throughput drop and near 2x latency increase when logging was enabled:
Root Causes
SimpleTime::get_current_timestamp()was called on the request thread per log message, performing a syscall, a year-loop calendar calculation, and aformat!allocation before the message even reached the channel(*self.component).clone()was heap-allocating a newStringon every log call despitecomponentalready being anArc<String>format!()at call sites allocated unconditionally before the log level filter could discard the messagechannel()(unbounded) was used with blockingsend(), which could synchronize request threads with the logger under loadDEBUG/INFOviacfg!(debug_assertions)with no way to suppress logging at runtimeChanges
logger.rsSimpleTime::get_current_timestamp()is now called inside the consumer loop, completely off the request pathArc::cloneinstead ofString::clone-LogMessage.componentis nowArc<String>, making the clone a single atomic incrementsync_channel(4096)replaceschannel()- pre-allocated ring buffer with no growth allocationstry_send()replacessend()- drops messages under saturation rather than blocking the request threadlog_info!,log_debug!,log_warn!,log_error!- check the log level before callingformat!(), so filtered messages produce zero allocationsLogger::enabled()- exposes the level check cleanly for use by macros without makingmin_levelpublicconfig.rslog_level: Option<String>field to theConfigstruct[HTEAPOT]section inconfig.tomlNone, falling back to the existingcfg!(debug_assertions)behaviour when not setmain.rsmin_lognow resolves fromconfig.log_levelfirst, withcfg!(debug_assertions)as the fallbacklogger.xxx(format!(...))call sites replaced with the lazy macrosConfiguration
Log level can now be controlled at runtime via
config.toml:Setting
"none"suppresses all log output with zero allocation overhead on the request path.Notes
Under extreme load,
try_sendwill silently drop log entries when the channel buffer is full. This is intentional, log loss under saturation is preferable to request thread stalls. The 4096-entry buffer provides ample headroom for normal operation.