Do writing via io::stdout (again)

Cargo.toml

@@ -26,7 +26,6 @@ timestamp = ["chrono"]
 
 [dependencies]
 chrono     = { version = "0.4", optional = true }
-libc       = { version = "0.2.58" }
 log        = { version = "0.4.8", features = ["std", "kv_unstable"] }
 log-panics = { version = "2", optional = true, features = ["with-backtrace"] }
 
@@ -37,3 +36,7 @@ lazy_static = "1.0"
 [[bench]]
 name = "time_format"
 harness = false
+
+[[bench]]
+name = "standard_out"
+harness = false

benches/standard_out.rs

@@ -0,0 +1,34 @@
+use std::io::{self, stdout, Write};
+
+use criterion::{criterion_group, criterion_main, Criterion};
+
+const MSG: &[u8] = b"2020-01-06T12:00:09.514249Z [REQUEST] simple: url = `/not_found`, method = `/not_found`, status_code = 404, body_size = 9";
+
+fn via_std_lib(c: &mut Criterion) {
+    c.bench_function("via_std_lib", |b| {
+        b.iter(|| {
+            stdout().write(MSG).expect("write error");
+        })
+    });
+}
+
+fn via_libc_fd(c: &mut Criterion) {
+    c.bench_function("via_libc_fd", |b| {
+        b.iter(|| {
+            match unsafe {
+                libc::write(
+                    libc::STDOUT_FILENO,
+                    MSG.as_ptr() as *const libc::c_void,
+                    MSG.len(),
+                )
+            } {
+                n if n < 0 => Err(io::Error::last_os_error()),
+                n => Ok(n as usize),
+            }
+            .expect("write error");
+        })
+    });
+}
+
+criterion_group!(standard_out, via_std_lib, via_libc_fd);
+criterion_main!(standard_out);

src/format.rs

@@ -0,0 +1,87 @@
+use std::fmt;
+use std::io::Write;
+
+#[cfg(feature = "timestamp")]
+use chrono::{Datelike, Timelike};
+use log::{kv, Record};
+
+use crate::REQUEST_TARGET;
+
+/// Formats `record`, writing into `buf`.
+#[inline(always)]
+pub(crate) fn record(buf: &mut Vec<u8>, record: &Record) {
+    #[cfg(feature = "timestamp")]
+    format_timestamp(buf);
+
+    match record.target() {
+        REQUEST_TARGET => {
+            writeln!(
+                buf,
+                "[REQUEST] {}: {}{}",
+                record.module_path().unwrap_or(""),
+                record.args(),
+                KeyValuePrinter(record.key_values())
+            )
+            .unwrap_or_else(|_| unreachable!());
+        }
+        target => {
+            writeln!(
+                buf,
+                "[{}] {}: {}{}",
+                record.level(),
+                target,
+                record.args(),
+                KeyValuePrinter(record.key_values())
+            )
+            .unwrap_or_else(|_| unreachable!());
+        }
+    }
+}
+
+#[cfg(feature = "timestamp")]
+#[inline(always)]
+fn format_timestamp(buf: &mut Vec<u8>) {
+    let timestamp = chrono::Utc::now();
+
+    write!(
+        buf,
+        "{:004}-{:02}-{:02}T{:02}:{:02}:{:02}.{:06}Z ",
+        timestamp.year(),
+        timestamp.month(),
+        timestamp.day(),
+        timestamp.hour(),
+        timestamp.minute(),
+        timestamp.second(),
+        timestamp.nanosecond() / 1000,
+    )
+    .unwrap_or_else(|_| unreachable!());
+}
+
+/// Prints key values in ": key1=value1, key2=value2" format.
+///
+/// # Notes
+///
+/// Prints ": " itself, only when there is at least one key value pair.
+struct KeyValuePrinter<'a>(&'a dyn kv::Source);
+
+impl<'a> fmt::Display for KeyValuePrinter<'a> {
+    fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
+        self.0
+            .visit(&mut KeyValueVisitor(true, f))
+            .map_err(|_| fmt::Error)
+    }
+}
+
+struct KeyValueVisitor<'a, 'b>(bool, &'a mut fmt::Formatter<'b>);
+
+impl<'a, 'b, 'kvs> kv::Visitor<'kvs> for KeyValueVisitor<'a, 'b> {
+    fn visit_pair(&mut self, key: kv::Key<'kvs>, value: kv::Value<'kvs>) -> Result<(), kv::Error> {
+        self.1
+            .write_str(if self.0 { ": " } else { ", " })
+            .and_then(|()| {
+                self.0 = false;
+                write!(self.1, "{}={}", key, value)
+            })
+            .map_err(Into::into)
+    }
+}

src/lib.rs

@@ -210,13 +210,12 @@
 #![warn(missing_debug_implementations, missing_docs, unused_results)]
 
 use std::cell::RefCell;
+use std::env;
 use std::io::{self, Write};
-use std::{env, fmt};
 
-use log::{kv, LevelFilter, Log, Metadata, Record, SetLoggerError};
+use log::{LevelFilter, Log, Metadata, Record, SetLoggerError};
 
-#[cfg(feature = "timestamp")]
-use chrono::{Datelike, Timelike};
+mod format;
 
 #[cfg(test)]
 mod tests;
@@ -354,35 +353,11 @@ impl Log for Logger {
         }
     }
 
-    fn flush(&self) {}
-}
-
-/// Prints key values in ": key1=value1, key2=value2" format.
-///
-/// # Notes
-///
-/// Prints ": " itself, only when there is at least one key value pair.
-struct KeyValuePrinter<'a>(&'a dyn kv::Source);
-
-impl<'a> fmt::Display for KeyValuePrinter<'a> {
-    fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
-        self.0
-            .visit(&mut KeyValueVisitor(true, f))
-            .map_err(|_| fmt::Error)
-    }
-}
-
-struct KeyValueVisitor<'a, 'b>(bool, &'a mut fmt::Formatter<'b>);
-
-impl<'a, 'b, 'kvs> kv::Visitor<'kvs> for KeyValueVisitor<'a, 'b> {
-    fn visit_pair(&mut self, key: kv::Key<'kvs>, value: kv::Value<'kvs>) -> Result<(), kv::Error> {
-        self.1
-            .write_str(if self.0 { ": " } else { ", " })
-            .and_then(|()| {
-                self.0 = false;
-                write!(self.1, "{}={}", key, value)
-            })
-            .map_err(Into::into)
+    fn flush(&self) {
+        // Can't handle the errors here and we likely can't log them either
+        // because that also goes through std out/err, so we can't do much here.
+        let _ = stdout().flush();
+        let _ = stderr().flush();
     }
 }
 
@@ -391,57 +366,20 @@ fn log(record: &Record) {
     // Thread local buffer for logging. This way we only lock standard out/error
     // for a single write call and don't create half written logs.
     thread_local! {
-        static BUFFER: RefCell<Vec<u8>> = RefCell::new(Vec::with_capacity(1024));
+        static BUF: RefCell<Vec<u8>> = RefCell::new(Vec::with_capacity(1024));
     }
 
-    #[cfg(feature = "timestamp")]
-    let timestamp = chrono::Utc::now();
-
-    BUFFER.with(|buffer| {
-        let mut buffer = buffer.borrow_mut();
-        buffer.clear();
-
-        #[cfg(feature = "timestamp")]
-        write!(
-            &mut buffer,
-            "{:004}-{:02}-{:02}T{:02}:{:02}:{:02}.{:06}Z ",
-            timestamp.year(),
-            timestamp.month(),
-            timestamp.day(),
-            timestamp.hour(),
-            timestamp.minute(),
-            timestamp.second(),
-            timestamp.nanosecond() / 1000,
-        )
-        .unwrap_or_else(log_failure);
+    BUF.with(|buf| {
+        let mut buf = buf.borrow_mut();
+        buf.clear();
+
+        format::record(&mut buf, record);
 
         match record.target() {
-            REQUEST_TARGET => {
-                writeln!(
-                    &mut buffer,
-                    "[REQUEST] {}: {}{}",
-                    record.module_path().unwrap_or(""),
-                    record.args(),
-                    KeyValuePrinter(record.key_values())
-                )
-                .unwrap_or_else(log_failure);
-
-                write_once(stdout(), &buffer).unwrap_or_else(log_failure);
-            }
-            target => {
-                writeln!(
-                    &mut buffer,
-                    "[{}] {}: {}{}",
-                    record.level(),
-                    target,
-                    record.args(),
-                    KeyValuePrinter(record.key_values())
-                )
-                .unwrap_or_else(log_failure);
-
-                write_once(stderr(), &buffer).unwrap_or_else(log_failure);
-            }
+            REQUEST_TARGET => write_once(stdout(), &buf),
+            _ => write_once(stderr(), &buf),
         }
+        .unwrap_or_else(log_failure);
     });
 }
 
@@ -473,65 +411,10 @@ fn log_failure(err: io::Error) {
 // though the return type of the functions are different we only need them both
 // to implement `io::Write`.
 
+#[cfg(test)]
+use self::test_instruments::{stderr, stdout, LOG_OUTPUT, LOG_OUTPUT_INDEX};
 #[cfg(not(test))]
-struct Stdout;
-
-#[cfg(not(test))]
-impl Write for Stdout {
-    fn write(&mut self, buf: &[u8]) -> io::Result<usize> {
-        match unsafe {
-            libc::write(
-                libc::STDOUT_FILENO,
-                buf.as_ptr() as *const libc::c_void,
-                buf.len(),
-            )
-        } {
-            n if n < 0 => Err(io::Error::last_os_error()),
-            n => Ok(n as usize),
-        }
-    }
-
-    fn flush(&mut self) -> io::Result<()> {
-        // Don't have to flush standard out.
-        Ok(())
-    }
-}
-
-#[cfg(not(test))]
-#[inline(always)]
-fn stdout() -> Stdout {
-    Stdout
-}
-
-#[cfg(not(test))]
-struct Stderr;
-
-#[cfg(not(test))]
-impl Write for Stderr {
-    fn write(&mut self, buf: &[u8]) -> io::Result<usize> {
-        match unsafe {
-            libc::write(
-                libc::STDERR_FILENO,
-                buf.as_ptr() as *const libc::c_void,
-                buf.len(),
-            )
-        } {
-            n if n < 0 => Err(io::Error::last_os_error()),
-            n => Ok(n as usize),
-        }
-    }
-
-    fn flush(&mut self) -> io::Result<()> {
-        // Don't have to flush standard error.
-        Ok(())
-    }
-}
-
-#[cfg(not(test))]
-#[inline(always)]
-fn stderr() -> Stderr {
-    Stderr
-}
+use std::io::{stderr, stdout};
 
 // The testing variant of the functions.
 
@@ -603,6 +486,3 @@ mod test_instruments {
         }
     }
 }
-
-#[cfg(test)]
-use self::test_instruments::{stderr, stdout, LOG_OUTPUT, LOG_OUTPUT_INDEX};