Skip to content

What makes slog fast

Dawid Ciężarkiewicz edited this page Oct 9, 2016 · 17 revisions

Static dispatch

Handling logging records in slog is based on Drain trait. By using a trait, it's possible to parametrize structs implementing Drain, with other Drains. Eg. LevelFilter implements Drain by wrapping different Drain and filtering-out all the logging records of insufficient logging level. Thanks to the Rust static dispatch, it's a cost-free abstraction. The resulting code is as efficient as hand-written one, while Drains can be nicely combined like LEGO blocks.

Avoiding allocations

Slog rigorously avoids allocation. In fact the only place in the core slog library that uses allocation, are values associated with loggers, that are placed on heap with Box and then reference counted with Arc.

When particular Drain needs a buffer for serialization, a thread_local reusable vectors are employed and Vec::clear() is used to keep them empty, without reallocating memory. This pattern is easy to use, saving allocation time, keeping the same buffer memory in CPU cache, without need for synchronization of concurrent calls.

Using lifetimes for temporary data

Every logging statement forms a Record structure that encapsulates all the logging information.

pub struct Record<'a> {
    meta: &'a RecordStatic<'a>,
    msg: fmt::Arguments<'a>,
    values: &'a [BorrowedKeyValue<'a>],
}

Notice the lifetimes and that a part of Record is moved to RecordStatic it is:

pub struct RecordStatic<'a> {
    /// Logging level
    pub level: Level,
    /// File
    pub file: &'static str,
    /// Line
    pub line: u32,
    /// Column (currently not implemented)
    pub column: u32,
    /// Function (currently not implemented)
    pub function: &'static str,
    /// Module
    pub module: &'static str,
    /// Target - for backward compatibility with `log`
    pub target: &'a str,
}

This makes it possible to create RecordStatic as a static variable and thus put the data that is constant for a given logging statement in the read-only section of the binary, instead of re-creating it every time.

It's a big improvement, taking microbenchmark from 6ns to 2ns. Without it, every field of RecordStatic would have to be initialized on stack every time Record is created. With it - Record is created on stack with only three fields.

Avoid doing anything until it's necessary

Most of the time, most of the logging statements will be ignored due to their low logging levels. That's why it's important to avoid any work when handling them.

Taking current system time is slow. That's why Record does not contain any timestamp. If any Drain wants to print it - it will have to take it manually. This also avoids slog core crate mandate a time library to use by it's users and custom Drain implementation.

Formatting logging message takes time, so Record<'a> contains `Arguments<'a> and defers it's formatting until some drain eg. prints it.

All key-values associated with logging records are taken as a static array of references. All key-values associated with loggers are Arc-chained vectors of Boxed values to avoid having to copy them. Serialize trait makes it possible to defer actual serialization of any key-value pairs to the time when it's actually required.

Compile time logging filtering

Most logging application won't ever print debug or trace level logging messages in production (release builds). That is why by default slog removes trace! and debug! logging statements at compile time. This can be overridden using cargo's "feature flags", and makes both trace! and debug! practically free both performance and code-size wise. Hopefully that will encourage liberal usage, even in performance sensitive code.

For a bit different reasons, trace! messages are by default not compiled in, even in debug builds: most of the time they just blow up the log, hidding what's important. When they are really needed, they can be re-enabled with "feature flags".