In high-performance computing fields, such as high-frequency trading (HFT), every nanosecond is crucial. A slight delay can lead to significant opportunity costs.
Therefore, developers must scrutinize every aspect of their code to eliminate unnecessary performance overhead. Logging is essential for debugging and monitoring, but if implemented poorly, it can itself become a major performance bottleneck.
This article will explore how to evolve from a simple logging implementation to an efficient logging system in Rust that has almost no performance impact.
1. The Root of the Problem: The Cost of Naive Logging
Let’s start with the most basic logging method, using the <span>println!</span> macro directly.
// Simple logging implementation
let date = Local::now();
println!(
"ts: {} volume: {} price: {} flag: {}",
date.format("%Y-%m-%d %H:%M:%S"),
100.02,
20000.0,
true);
The drawbacks of this method are very obvious:
- Blocking I/O
<span>println!</span>writes data directly to standard output, which is a slow I/O operation. During execution, it blocks the current thread (our precious strategy thread) until the operation is complete. - Expensive FormattingFormatting strings, especially operations like the timestamp
<span>date.format(...)</span>, require computation and memory allocation, which should be avoided in performance-sensitive hot paths.
At this point, the average time taken to print logs is about 1769 nanoseconds.
In high-frequency scenarios, the message rate is often positively correlated with market opportunities. When the market is most active and requires the system to respond quickly, the volume of logs can surge, leading to spikes in latency, which is exactly what we want to avoid.
2. The First Evolution: Asynchronous Logging
To address the I/O blocking issue, a common improvement is to adopt asynchronous logging. The core idea is to separate logging operations from the critical strategy thread and delegate them to a dedicated logging thread.
The strategy thread sends the formatted log string to a thread-safe queue (such as a lock-free queue like RingBuffer) and then immediately returns to continue executing its core tasks. The logging thread retrieves the string from the queue and performs the actual I/O write operations.
// Asynchronous logging: sending formatted strings
use lockfree::channel::spsc;
use std::thread;
// 1. Create a single producer, single consumer lock-free channel
let (mut sx, mut rx) = spsc::create::();
// 2. Start a dedicated logging thread
thread::spawn(move || {
// Loop to receive and print log messages
while let Ok(msg) = rx.recv() {
println!("{}", msg);
}});
// 3. In the strategy thread
let date = Local::now();
// Still formatting the string in the strategy thread
let log_msg = format!(
"ts: {} volume: {} price: {} flag: {}",
date.format("%Y-%m-%d %H:%M:%S"),
100.02,
20000.0,
true);
// Send the formatted string to the logging thread
sx.send(log_msg).unwrap();
This solution significantly improves latency and latency stability by moving slow I/O operations out of the hot path.
According to benchmarks, the average latency of this asynchronous logging is around 1189 nanoseconds. Although better than direct printing, there is still substantial room for optimization.
However, it still does not address another performance killer: string formatting. The dynamic memory allocation and data conversion involved in the <span>format!</span> macro still occur on the strategy thread, introducing unnecessary overhead.
3. The Second Evolution: Serializing Closures
Since string formatting is expensive, can we also move it to the logging thread?
Typically, timestamps are formatted into date strings, and creating strings involves dynamic memory allocation, which should be avoided. If we can delegate both I/O operations and string construction to separate threads, that would be even better. Circumventing this overhead with alternative implementations is quite challenging in most programming languages.
This implementation can accept a variable number of parameters, and these parameters can be of any type. In strongly typed languages like Rust and C++, this becomes complex. A feasible solution is to use some binary serialization method, such as bincode, protobuf, or BSON, to serialize the parameters to be logged along with the formatting string. However, I believe this is not the most efficient approach. From a performance perspective, it would be more efficient to complete most of the work at compile time, avoiding unnecessary memory operations.
A powerful feature of Rust provides us with an elegant solution: closures. In Rust, closures can not only be code but can also be captured, serialized, and sent across threads like data.
The idea is:
- In the strategy thread, create a closure that contains the complete logging logic (including formatting and printing).
- This closure will capture all the variables that need to be logged (such as price, volume, etc.).
- The strategy thread does not execute this closure but sends the closure itself to the logging thread.
- Upon receiving the closure, the logging thread invokes it, thus completing all formatting and I/O work on the logging thread.
In this way, the workload for the strategy thread is minimized: it only needs to create the closure and send its pointer and captured parameters to the queue.
// Asynchronous logging: sending closures
use lockfree::channel::spsc;
use std::thread;
// A simple struct to wrap sendable closures
struct LogClosure {
func: Box,
}
impl LogClosure {
fn new(func: F) -> Self
where
F: FnOnce() + Send + 'static,
{
Self { func: Box::new(func) }
}
fn invoke(self) {
(self.func)();
}
}
// 1. Create a channel to receive closures
let (mut sx, mut rx) = spsc::create::();
// 2. Start the logging thread
thread::spawn(move || {
while let Ok(log_closure) = rx.recv() {
// Execute the closure in the logging thread
log_closure.invoke();
}});
// 3. In the strategy thread
let date = Local::now();
let volume = 100.02;
let price = 20000.0;
let flag = true;
// Create and send a closure that captures all needed variables
sx.send(LogClosure::new(move || {
println!(
"ts: {} volume: {} price: {} flag: {}",
date.format("%Y-%m-%d %H:%M:%S"),
volume,
price,
flag
);
})).unwrap();
Awesome! The performance improvement of this method is astonishing. Because it performs almost no string or memory operations on the strategy thread, the average latency can drop to around 170 nanoseconds. More importantly, it greatly improves tail latency, making the system’s performance more stable and predictable.
Of course, implementing a similar mechanism in other languages is also possible. C++ has lambdas, which I believe can be serialized. In Rust, most of the complexity is handled by the compiler, and it incurs almost no performance overhead. Meanwhile, you don’t have to worry about concurrency issues, as the compiler ensures that ownership is correctly transferred to the logging thread.
4. The Final Evolution: Using Enums for Extreme Performance
The closure solution is already excellent, but can we go further? The answer is yes. A careful analysis of the closure solution reveals several areas for optimization:
- Heap Allocation To handle closures of uncertain size at runtime,
<span>Box</span>incurs heap memory allocation. Heap allocation is slower than stack allocation. - Unknown Size The compiler does not know the specific size of the closure at compile time, which may hinder certain optimizations.
- Redundant Information Each time a closure is sent, it implicitly includes information about the formatting string itself.
The final optimization scheme is to use Rust’s powerful type system, particularly enums, to predefine all possible log message types.
The idea is:
- Define a specific
<span>struct</span>for each log message that contains only pure data. - Define an
<span>enum</span>where each variant corresponds to a log message<span>struct</span>. - The strategy thread is only responsible for creating and populating this small, fixed-size
<span>struct</span>and<span>enum</span>, then pushing it into the queue. This process only involves stack operations, which are extremely fast. - The logging thread receives the
<span>enum</span>and uses pattern matching (<span>match</span>) to invoke the specific formatting logic associated with that data type.
// Final solution: using Enum to send structured data
use lockfree::channel::spsc;
use std::fmt;
use std::thread;
use chrono::{Local, DateTime};
// Define log data structure holding the data fields from previous examples
struct SimpleLog {
date: DateTime,
volume: f64,
price: f64,
flag: bool,
}
// Define log message enum
enum LogMessage {
Simple(SimpleLog),
// todo more log message enums
}
// Implement Display trait for the enum, binding formatting logic to data
impl fmt::Display for LogMessage {
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
match self {
LogMessage::Simple(msg) => write!(
f,
"ts: {} volume: {} price: {} flag: {}",
msg.date.format("%Y-%m-%d %H:%M:%S"),
msg.volume,
msg.price,
msg.flag
),
}
}
}
// 1. Create a channel to receive LogMessage enum
let (mut sx, mut rx) = spsc::create::();
// 2. Start the logging thread
thread::spawn(move || {
while let Ok(msg) = rx.recv() {
// Directly print, will automatically call formatting logic in Display trait
println!("{}", msg);
}});
// 3. In the strategy thread, create and send structured data
let date = Local::now();
sx.send(LogMessage::Simple(SimpleLog {
date,
volume: 100.02,
price: 20000.0,
flag: true,
})).unwrap();
This enum-based approach is the most efficient so far. It avoids heap allocation, the size of the data being sent is known at compile time, and it only transmits pure data, leaving all formatting work to the logging thread. According to the latest benchmarks, the latency of this method can be further reduced to around 128 nanoseconds, faster than the closure method.
Conclusion
Through three iterations, we have optimized a simple logging solution to its extreme:
- Direct Printing Simple but poor performance, blocking the hot path.
- Asynchronous Sending of Strings Moves I/O out of the hot path, but formatting overhead remains.
- Asynchronous Sending of Closures Moves both I/O and formatting out of the hot path, significantly improving performance.
- Asynchronous Sending of Enums Ultimate optimization, avoiding heap allocation, transmitting fixed-size pure data, achieving optimal performance.
This optimization process perfectly demonstrates the advantages of the Rust language: through its powerful type system (enums, Traits), ownership, and concurrency model, developers can write performance-optimized and logically clear code without sacrificing safety. For any system pursuing low latency, minimizing the workload on critical paths is an eternal optimization principle. This is precisely the charm of Rust.
If you have better ideas, feel free to reach out to me.