slog-rs
`term::TermDecorator` should do line buffering
term::TermDecorator could be faster on Linux by line-buffering its output instead of outputting many parts of the line with their own syscall.
Diff I applied to the term crate (not slog-term!):
diff --git a/src/lib.rs b/src/lib.rs
index fd02172..e217055 100644
--- a/src/lib.rs
+++ b/src/lib.rs
@@ -69,7 +69,7 @@ pub use terminfo::TerminfoTerminal;
#[cfg(windows)]
pub use win::WinConsole;
-use std::io::{self, Stdout, Stderr};
+use std::io::{self, LineWriter, Stdout, Stderr};
pub mod terminfo;
@@ -77,15 +77,15 @@ pub mod terminfo;
mod win;
/// Alias for stdout terminals.
-pub type StdoutTerminal = Terminal<Output = Stdout> + Send;
+pub type StdoutTerminal = Terminal<Output = LineWriter<Stdout>> + Send;
/// Alias for stderr terminals.
-pub type StderrTerminal = Terminal<Output = Stderr> + Send;
+pub type StderrTerminal = Terminal<Output = LineWriter<Stderr>> + Send;
#[cfg(not(windows))]
/// Return a Terminal wrapping stdout, or None if a terminal couldn't be
/// opened.
pub fn stdout() -> Option<Box<StdoutTerminal>> {
- TerminfoTerminal::new(io::stdout()).map(|t| Box::new(t) as Box<StdoutTerminal>)
+ TerminfoTerminal::new(LineWriter::new(io::stdout())).map(|t| Box::new(t) as Box<StdoutTerminal>)
}
#[cfg(windows)]
@@ -101,7 +101,7 @@ pub fn stdout() -> Option<Box<StdoutTerminal>> {
/// Return a Terminal wrapping stderr, or None if a terminal couldn't be
/// opened.
pub fn stderr() -> Option<Box<StderrTerminal>> {
- TerminfoTerminal::new(io::stderr()).map(|t| Box::new(t) as Box<StderrTerminal>)
+ TerminfoTerminal::new(LineWriter::new(io::stderr())).map(|t| Box::new(t) as Box<StderrTerminal>)
}
#[cfg(windows)]
I used the following program to check how fast a logging statement is:
#[macro_use]
extern crate slog;
extern crate slog_term;
use slog::BorrowedKV;
use slog::Drain;
use slog::Logger;
use slog_term::*;
use std::sync::Mutex;
fn main() {
let compact = FullFormat::new(TermDecorator::new().build()).build().fuse();
let log: Logger = Logger::root(Mutex::new(compact).fuse(), o!("version" => "1.0", "foobar" => "barfoo"));
for _ in 0..10_000 {
trace!(log, "logging a trace message");
debug!(log.new(o!("foo" => "bar")), "debug values"; "x" => 1, "y" => -1);
info!(log, "some interesting info"; "where" => "right here");
warn!(log, "be cautious!"; "why" => "you never know...");
error!(log, "wrong {}", "foobar"; "type" => "unknown");
crit!(log, "abandoning test");
}
}
[dependencies]
slog = "2.0.0-3.1"
slog-term = "2.0.0-3.0"
strace without optimization:
[...]
rite(2, "0", 1) = 1
write(2, "7", 1) = 1
write(2, " ", 1) = 1
write(2, "16", 2) = 2
write(2, ":", 1) = 1
write(2, "42", 2) = 2
write(2, ":", 1) = 1
write(2, "28", 2) = 2
write(2, ".", 1) = 1
write(2, "904", 3) = 3
write(2, "\33(B\33[m", 6) = 6
write(2, " ", 1) = 1
write(2, "\33[33m", 5) = 5
write(2, "WARN", 4) = 4
write(2, "\33(B\33[m", 6) = 6
write(2, " ", 1) = 1
write(2, "\33[1m", 4) = 4
write(2, "be cautious!", 12) = 12
write(2, "\33(B\33[m", 6) = 6
write(2, ", ", 2) = 2
write(2, "\33[1m", 4) = 4
write(2, "why", 3) = 3
write(2, "\33(B\33[m", 6) = 6
write(2, ":", 1) = 1
write(2, "\33(B\33[m", 6) = 6
write(2, " ", 1) = 1
write(2, "\33(B\33[m", 6) = 6
write(2, "you never know...", 17) = 17
write(2, "\33(B\33[m", 6) = 6
write(2, ", ", 2) = 2
write(2, "\33[1m", 4) = 4
write(2, "foobar", 6) = 6
write(2, "\33(B\33[m", 6) = 6
write(2, ":", 1) = 1
write(2, "\33(B\33[m", 6) = 6
write(2, " ", 1) = 1
write(2, "\33(B\33[m", 6) = 6
write(2, "barfoo", 6) = 6
write(2, "\33(B\33[m", 6) = 6
write(2, ", ", 2) = 2
write(2, "\33[1m", 4) = 4
write(2, "version", 7) = 7
write(2, "\33(B\33[m", 6) = 6
[...]
strace with optimization:
write(2, "\33(B\33[mApr 07 16:33:00.256\33(B\33[m "..., 168) = 168
write(2, "\33(B\33[mApr 07 16:33:00.257\33(B\33[m "..., 264) = 264
write(2, "\33(B\33[mApr 07 16:33:00.257\33(B\33[m "..., 213) = 213
write(2, "\33(B\33[mApr 07 16:33:00.257\33(B\33[m "..., 209) = 209
write(2, "\33(B\33[mApr 07 16:33:00.257\33(B\33[m "..., 200) = 200
write(2, "\33(B\33[mApr 07 16:33:00.257\33(B\33[m "..., 160) = 160
Without the optimization, it ran in 11.6 seconds, with the optimization, it ran it 4.5 seconds.
Agreed. Though I was wondering if this should be decorator's job, or the IO given to decorator should do it. One can just wrap the io in https://doc.rust-lang.org/std/io/struct.BufWriter.html.
Please not however that on Windows colors and other decoration are separate calls and the data is not being sent in-line as escape codes, so it can't be buffered, AFAIK.
It should be possible to buffer the evaluation of the format string on Windows though, removing this kind of call:
write(2, "16", 2) = 2
write(2, ":", 1) = 1
write(2, "42", 2) = 2
write(2, ":", 1) = 1
write(2, "28", 2) = 2
write(2, ".", 1) = 1
write(2, "904", 3) = 3
(prints the current time).
Oh dear. This is https://github.com/slog-rs/term/blob/12f4e905af008a666c5e0dda1cd1b362ae7061e9/src/lib.rs#L773 . Very inefficient.
Do you think you can come up with a PR? Since you have all the instrumentation there, maybe you can come up with best layer to stuff buffering there.
Another argument for line buffering is that when interleaved with other logging systems (GStreamer with lots of threads in my case) I often see line-buffered output of those interleaved with parts of slog output. Makes it really hard to work with when it happens.
I absolutely agree that slog-term should do line buffering.
However, I would like to note that any buffering beyond that should be configurable and off by default. I use slog-term for debugging crates that use unsafe code. It's important that I see each line as soon as it happens in case my app crashes.
I remember being bitten by a nasty bug because I buffered over multiple lines when logging to a file. Flushing after every newline fixed it. I just want to make sure that doesn't happen to new users 😉
EDIT: Just realized this issue is old. Is this still a problem?
Seems like it's open, so no one produced a PR. At this point I'm only merging things that other people are willing to put an effort into. :)