Skip to content

fix(logger): reduce logging overhead on request threads #41

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
Trojan-254 wants to merge 1 commit into
base: master
Choose a base branch
from
Open

fix(logger): reduce logging overhead on request threads #41

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
6 changes: 5 additions & 1 deletion src/config.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -159,6 +159,7 @@ pub struct Config {
pub cache_ttl: u16,
pub threads: u16,
pub log_file: Option<String>,
pub log_level: Option<String>,
pub index: String, // Index file to serve by default
// pub error: String, // Error file to serve when a file is not found
pub proxy_rules: HashMap<String, String>,
Expand All @@ -185,6 +186,7 @@ impl Config {
index: "index.html".to_string(),
log_file: None,
//error: "error.html".to_string(),
log_level: None,
threads: 1,
cache: false,
cache_ttl: 0,
Expand Down Expand Up @@ -213,7 +215,7 @@ impl Config {
root: root_dir,
index: file_name.to_string(),
log_file: None,

log_level: None,
threads: 1,
cache: false,
cache_ttl: 0,
Expand Down Expand Up @@ -278,6 +280,7 @@ impl Config {
index: map.get2("index").unwrap_or("index.html".to_string()),
log_file: map.get2("log_file"),
//error: map.get2("error").unwrap_or("error.html".to_string()),
log_level: map.get2("log_level"),
proxy_rules,
}
}
Expand All @@ -293,6 +296,7 @@ impl Config {
cache_ttl: 0,
threads: 2,
log_file: None,
log_level: None,
index: "index.html".to_string(),
proxy_rules,
}
Expand Down
87 changes: 58 additions & 29 deletions src/logger.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,7 +1,7 @@
use std::fmt;
use std::io::Write;
use std::sync::Arc;
use std::sync::mpsc::{Sender, channel};
use std::sync::mpsc::{SyncSender, sync_channel};
use std::thread::{self, JoinHandle};
use std::time::{Duration, Instant, SystemTime, UNIX_EPOCH};

Expand Down Expand Up @@ -114,15 +114,14 @@ impl SimpleTime {

/// Internal message structure containing log metadata.
struct LogMessage {
timestamp: String,
level: LogLevel,
component: String,
component: Arc<String>,
content: String,
}

/// Core logger implementation running in a background thread.
struct LoggerCore {
tx: Sender<LogMessage>,
tx: SyncSender<LogMessage>,
_thread: JoinHandle<()>,
}

Expand All @@ -143,41 +142,37 @@ impl Logger {
min_level: LogLevel,
component: &str,
) -> Logger {
let (tx, rx) = channel::<LogMessage>();
let (tx, rx) = sync_channel::<LogMessage>(4096);
let thread = thread::spawn(move || {
let mut last_flush = Instant::now();
let mut buff = Vec::new();
let mut max_size = 100;
let mut buff = String::with_capacity(8196);
let mut max_size = 100usize;
let timeout = Duration::from_secs(1);

loop {
let msg = rx.recv_timeout(timeout);
match msg {
Ok(msg) => {
let formatted = format!(
let ts = SimpleTime::get_current_timestamp();
buff.push_str(&format!(
"{} [{}] [{}] {}\n",
msg.timestamp, msg.level, msg.component, msg.content
);
buff.push(formatted);
ts, msg.level, msg.component, msg.content
));
}
Err(std::sync::mpsc::RecvTimeoutError::Timeout) => {}
Err(_) => break,
}

// Flush if timeout or buffer threshold reached
if last_flush.elapsed() >= timeout || buff.len() >= max_size {
if last_flush.elapsed() >= timeout || buff.len() >= max_size * 80 {
if !buff.is_empty() {
if buff.len() >= max_size {
max_size = (max_size * 10).min(1_000_000);
max_size = if buff.len() >= max_size * 80 {
(max_size * 10).min(1_000_000)
} else {
max_size = (max_size / 10).max(100);
}
let wr = writer.write_all(buff.join("").as_bytes());
if wr.is_err() {
println!("Failed to write to log: {:?}", wr);
}
(max_size / 10).max(100)
};
let _ = writer.write_all(buff.as_bytes());
let _ = writer.flush();

buff.clear();
}
last_flush = Instant::now();
Expand All @@ -204,21 +199,22 @@ impl Logger {
}
}

#[inline]
pub fn enabled(&self, level:LogLevel) -> bool {
level >= self.min_level
}

/// Sends a log message with the given level and content.
pub fn log(&self, level: LogLevel, content: String) {
if level < self.min_level {
if !self.enabled(level) {
return;
}

let log_msg = LogMessage {
timestamp: SimpleTime::get_current_timestamp(),
let _ = self.core.tx.try_send(LogMessage {
level,
component: (*self.component).clone(),
component: Arc::clone(&self.component),
content,
};

// Send the log message to the channel
let _ = self.core.tx.send(log_msg);
});
}

/// Logs a DEBUG-level message.
Expand Down Expand Up @@ -263,6 +259,39 @@ impl Clone for Logger {
}
}

#[macro_export]
macro_rules! log_debug {
($l:expr, $($a:tt)*) => {
if $l.enabled($crate::logger::LogLevel::DEBUG) {
$l.log($crate::logger::LogLevel::DEBUG, format!($($a)*));
}
};
}
#[macro_export]
macro_rules! log_info {
($l:expr, $($a:tt)*) => {
if $l.enabled($crate::logger::LogLevel::INFO) {
$l.log($crate::logger::LogLevel::INFO, format!($($a)*));
}
};
}
#[macro_export]
macro_rules! log_warn {
($l:expr, $($a:tt)*) => {
if $l.enabled($crate::logger::LogLevel::WARN) {
$l.log($crate::logger::LogLevel::WARN, format!($($a)*));
}
};
}
#[macro_export]
macro_rules! log_error {
($l:expr, $($a:tt)*) => {
if $l.enabled($crate::logger::LogLevel::ERROR) {
$l.log($crate::logger::LogLevel::ERROR, format!($($a)*));
}
};
}

#[cfg(test)]
mod tests {
use super::*;
Expand Down
54 changes: 22 additions & 32 deletions src/main.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -119,10 +119,13 @@ fn main() {
// Determine if the server should proxy all requests
let proxy_only = config.proxy_rules.get("/").is_some();

let min_log = if cfg!(debug_assertions) {
LogLevel::DEBUG
} else {
LogLevel::INFO
let min_log = match config.log_level.as_deref() {
Some("debug") => LogLevel::DEBUG,
Some("info") => LogLevel::INFO,
Some("warn") => LogLevel::WARN,
Some("error") => LogLevel::ERROR,
Some("none") => LogLevel::FATAL,
_ => if cfg!(debug_assertions) { LogLevel::DEBUG } else { LogLevel::INFO },
};
// Initialize the logger based on the config or default to stdout if the log file can't be created
let logger = match config.log_file.clone() {
Expand Down Expand Up @@ -152,20 +155,16 @@ fn main() {
//Configure graceful shutdown from ctrl+c
shutdown::setup_graceful_shutdown(&mut server, logger.clone());

logger.info(format!(
"Server started at http://{}:{}",
config.host, config.port
)); // Log that the server has started
log_info!(logger, "Server started at http:/{}:{}", config.host, config.port); // Log that the server has started

// Log whether the cache is enabled based on the config setting
if config.cache {
logger.info("Cache Enabled".to_string());
log_info!(logger, "Cache enabled");
}

// If proxy-only mode is enabled, issue a warning that local paths won't be used
if proxy_only {
logger
.warn("WARNING: All requests are proxied to /. Local paths won't be used.".to_string());
log_warn!(logger, "WARNING: All requests are proxied to /. Local paths won't be used.");
}

// Create separate loggers for each component (proxy, cache, and HTTP)
Expand All @@ -182,27 +181,21 @@ fn main() {
let req_method = req.method.to_str(); // Get the HTTP method (e.g., GET, POST)

// Log the incoming request method and path
http_logger.info(format!("Request {} {}", req_method, req.path));
log_info!(http_logger, "Request {} {}", req_method, req.path);

if config.cache {
let cache_start = Instant::now(); // Track cache operation time
let cache_start = Instant::now();
let mut cache_lock = cache.lock().expect("Error locking cache");
if let Some(response) = cache_lock.get(&req) {
cache_logger.debug(format!("cache hit for {}", &req.path));
let elapsed = start_time.elapsed();
http_logger.debug(format!(
"Request processed in {:.6}ms",
elapsed.as_secs_f64() * 1000.0 // Log the time taken in milliseconds
));
log_debug!(cache_logger, "cache hit for {}", req.path);
log_debug!(http_logger, "Request processed in {:.6}ms",
start_time.elapsed().as_secs_f64() * 1000.0);
return Box::new(response);
} else {
cache_logger.debug(format!("cache miss for {}", &req.path));
log_debug!(cache_logger, "cache miss for {}", req.path);
}
let cache_elapsed = cache_start.elapsed();
cache_logger.debug(format!(
"Cache operation completed in {:.6}µs",
cache_elapsed.as_micros()
));
log_debug!(cache_logger, "Cache operation completed in {:.6}µs",
cache_start.elapsed().as_micros());
}

let mut ctx = Context {
Expand All @@ -218,17 +211,14 @@ fn main() {

let response = handlers.get_handler(&ctx);
if response.is_none() {
logger.error("No handler found for request".to_string());
log_error!(logger, "No handler found for request");
return HttpResponse::new(HttpStatus::InternalServerError, "content", None);
}
let response = response.unwrap().run(&mut ctx);

// Log how long the request took to process
let elapsed = start_time.elapsed();
http_logger.debug(format!(
"Request processed in {:.6}ms",
elapsed.as_secs_f64() * 1000.0 // Log the time taken in milliseconds
));
log_debug!(http_logger, "Request processed in {:.6}ms",
start_time.elapsed().as_secs_f64() * 1000.0);

response
// If content was found, return it with the appropriate headers, otherwise return a 404
});
Expand Down
Loading