term::TermDecorator should do line buffering

[tbu-]

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.

[dpc]

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.

[dpc]

Oh, you are already doing it but though it's tricky with term...

[dpc]

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.

[tbu-]

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).

[dpc]

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.

[tbu-]

I made an issue in the term repository, see above.

[nazar-pc]

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.

[Techcable]

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?

[dpc]

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. :)