From e8f72c38f4bf74e7291043917fdd0bae1404b407 Mon Sep 17 00:00:00 2001 From: Alex Crichton Date: Thu, 24 Oct 2013 17:30:36 -0700 Subject: [PATCH] Cache and buffer stdout per-task for printing Almost all languages provide some form of buffering of the stdout stream, and this commit adds this feature for rust. A handle to stdout is lazily initialized in the Task structure as a buffered owned Writer trait object. The buffer behavior depends on where stdout is directed to. Like C, this line-buffers the stream when the output goes to a terminal (flushes on newlines), and also like C this uses a fixed-size buffer when output is not directed at a terminal. We may decide the fixed-size buffering is overkill, but it certainly does reduce write syscall counts when piping output elsewhere. This is a *huge* benefit to any code using logging macros or the printing macros. Formatting emits calls to `write` very frequently, and to have each of them backed by a write syscall was very expensive. In a local benchmark of printing 10000 lines of "what" to stdout, I got the following timings: when | terminal | redirected ---------------------------------- before | 0.575s | 0.525s after | 0.197s | 0.013s C | 0.019s | 0.004s I can also confirm that we're buffering the output appropriately in both situtations. We're still far slower than C, but I believe much of that has to do with the "homing" that all tasks due, we're still performing an order of magnitude more write syscalls than C does. --- src/libstd/rt/io/buffered.rs | 60 +++++++++++++++++++++++++++---- src/libstd/rt/io/stdio.rs | 68 +++++++++++++++++++++++++++++------- src/libstd/rt/logging.rs | 6 ++-- src/libstd/rt/task.rs | 27 +++++++++++--- src/libstd/rt/uv/uvio.rs | 2 +- src/libstd/rt/uv/uvll.rs | 5 +-- src/rt/rust_uv.cpp | 2 +- 7 files changed, 139 insertions(+), 31 deletions(-) diff --git a/src/libstd/rt/io/buffered.rs b/src/libstd/rt/io/buffered.rs index 9dcb35c806f7c..47c8dbd35c614 100644 --- a/src/libstd/rt/io/buffered.rs +++ b/src/libstd/rt/io/buffered.rs @@ -221,17 +221,48 @@ impl Writer for BufferedWriter { } impl Decorator for BufferedWriter { - fn inner(self) -> W { - self.inner - } + fn inner(self) -> W { self.inner } + fn inner_ref<'a>(&'a self) -> &'a W { &self.inner } + fn inner_mut_ref<'a>(&'a mut self) -> &'a mut W { &mut self.inner } +} - fn inner_ref<'a>(&'a self) -> &'a W { - &self.inner +/// Wraps a Writer and buffers output to it, flushing whenever a newline (0xa, +/// '\n') is detected. +/// +/// Note that this structure does NOT flush the output when dropped. +pub struct LineBufferedWriter { + priv inner: BufferedWriter, +} + +impl LineBufferedWriter { + /// Creates a new `LineBufferedWriter` + pub fn new(inner: W) -> LineBufferedWriter { + // Lines typically aren't that long, don't use a giant buffer + LineBufferedWriter { + inner: BufferedWriter::with_capacity(1024, inner) + } } +} - fn inner_mut_ref<'a>(&'a mut self) -> &'a mut W { - &mut self.inner +impl Writer for LineBufferedWriter { + fn write(&mut self, buf: &[u8]) { + match buf.iter().position(|&b| b == '\n' as u8) { + Some(i) => { + self.inner.write(buf.slice_to(i + 1)); + self.inner.flush(); + self.inner.write(buf.slice_from(i + 1)); + } + None => self.inner.write(buf), + } } + + fn flush(&mut self) { self.inner.flush() } +} + +impl Decorator for LineBufferedWriter { + fn inner(self) -> W { self.inner.inner() } + fn inner_ref<'a>(&'a self) -> &'a W { self.inner.inner_ref() } + fn inner_mut_ref<'a>(&'a mut self) -> &'a mut W { self.inner.inner_mut_ref() } } struct InternalBufferedWriter(BufferedWriter); @@ -413,4 +444,19 @@ mod test { assert_eq!(reader.read_until(8), Some(~[0])); assert_eq!(reader.read_until(9), None); } + + #[test] + fn test_line_buffer() { + let mut writer = LineBufferedWriter::new(MemWriter::new()); + writer.write([0]); + assert_eq!(*writer.inner_ref().inner_ref(), ~[]); + writer.write([1]); + assert_eq!(*writer.inner_ref().inner_ref(), ~[]); + writer.flush(); + assert_eq!(*writer.inner_ref().inner_ref(), ~[0, 1]); + writer.write([0, '\n' as u8, 1]); + assert_eq!(*writer.inner_ref().inner_ref(), ~[0, 1, 0, '\n' as u8]); + writer.flush(); + assert_eq!(*writer.inner_ref().inner_ref(), ~[0, 1, 0, '\n' as u8, 1]); + } } diff --git a/src/libstd/rt/io/stdio.rs b/src/libstd/rt/io/stdio.rs index b922e6400cc50..3f34d32b350b4 100644 --- a/src/libstd/rt/io/stdio.rs +++ b/src/libstd/rt/io/stdio.rs @@ -30,6 +30,7 @@ use fmt; use libc; use option::{Option, Some, None}; use result::{Ok, Err}; +use rt::io::buffered::{LineBufferedWriter, BufferedWriter}; use rt::rtio::{IoFactory, RtioTTY, RtioFileStream, with_local_io, CloseAsynchronously}; use super::{Reader, Writer, io_error, IoError, OtherIoError}; @@ -111,37 +112,78 @@ pub fn stderr() -> StdWriter { do src(libc::STDERR_FILENO, false) |src| { StdWriter { inner: src } } } +/// Executes a closure with the local task's handle on stdout. By default, this +/// stream is a buffering stream, so the handled yielded to the given closure +/// can be used to flush the stdout stream (if necessary). The buffering used is +/// line-buffering when stdout is attached to a terminal, and a fixed sized +/// buffer if it is not attached to a terminal. +/// +/// Note that handles generated via the `stdout()` function all output to the +/// same stream, and output among all task may be interleaved as a result of +/// this. This is provided to have access to the default stream for `print` and +/// `println` (and the related macros) for this task. +/// +/// Also note that logging macros do not use this stream. Using the logging +/// macros will emit output to stderr. +pub fn with_task_stdout(f: &fn(&mut Writer)) { + use rt::local::Local; + use rt::task::Task; + + unsafe { + // Logging may require scheduling operations, so we can't remove the + // task from TLS right now, hence the unsafe borrow. Sad. + let task: *mut Task = Local::unsafe_borrow(); + + match (*task).stdout_handle { + Some(ref mut handle) => f(*handle), + None => { + let handle = stdout(); + let mut handle = if handle.isatty() { + ~LineBufferedWriter::new(handle) as ~Writer + } else { + // The default capacity is very large, 64k, but this is just + // a stdout stream, and possibly per task, so let's not make + // this too expensive. + ~BufferedWriter::with_capacity(4096, handle) as ~Writer + }; + f(handle); + (*task).stdout_handle = Some(handle); + } + } + } +} + /// Prints a string to the stdout of the current process. No newline is emitted /// after the string is printed. pub fn print(s: &str) { - // XXX: need to see if not caching stdin() is the cause of performance - // issues, it should be possible to cache a stdout handle in each Task - // and then re-use that across calls to print/println. Note that the - // resolution of this comment will affect all of the prints below as - // well. - stdout().write(s.as_bytes()); + do with_task_stdout |io| { + io.write(s.as_bytes()); + } } /// Prints a string as a line. to the stdout of the current process. A literal /// `\n` character is printed to the console after the string. pub fn println(s: &str) { - let mut out = stdout(); - out.write(s.as_bytes()); - out.write(['\n' as u8]); + do with_task_stdout |io| { + io.write(s.as_bytes()); + io.write(['\n' as u8]); + } } /// Similar to `print`, but takes a `fmt::Arguments` structure to be compatible /// with the `format_args!` macro. pub fn print_args(fmt: &fmt::Arguments) { - let mut out = stdout(); - fmt::write(&mut out as &mut Writer, fmt); + do with_task_stdout |io| { + fmt::write(io, fmt); + } } /// Similar to `println`, but takes a `fmt::Arguments` structure to be /// compatible with the `format_args!` macro. pub fn println_args(fmt: &fmt::Arguments) { - let mut out = stdout(); - fmt::writeln(&mut out as &mut Writer, fmt); + do with_task_stdout |io| { + fmt::writeln(io, fmt); + } } /// Representation of a reader of a standard input stream diff --git a/src/libstd/rt/logging.rs b/src/libstd/rt/logging.rs index 31650ede7000d..cb66d6f6199ae 100644 --- a/src/libstd/rt/logging.rs +++ b/src/libstd/rt/logging.rs @@ -13,6 +13,8 @@ use from_str::from_str; use libc::exit; use option::{Some, None, Option}; use rt::io; +use rt::io::stdio::StdWriter; +use rt::io::buffered::LineBufferedWriter; use rt::crate_map::{ModEntry, CrateMap, iter_crate_map, get_crate_map}; use str::StrSlice; use u32; @@ -170,7 +172,7 @@ pub trait Logger { /// This logger emits output to the stderr of the process, and contains a lazily /// initialized event-loop driven handle to the stream. pub struct StdErrLogger { - priv handle: Option, + priv handle: Option>, } impl StdErrLogger { @@ -181,7 +183,7 @@ impl Logger for StdErrLogger { fn log(&mut self, args: &fmt::Arguments) { // First time logging? Get a handle to the stderr of this process. if self.handle.is_none() { - self.handle = Some(io::stderr()); + self.handle = Some(LineBufferedWriter::new(io::stderr())); } fmt::writeln(self.handle.get_mut_ref() as &mut io::Writer, args); } diff --git a/src/libstd/rt/task.rs b/src/libstd/rt/task.rs index 1ea68bb52d7e0..dc3b6293fb099 100644 --- a/src/libstd/rt/task.rs +++ b/src/libstd/rt/task.rs @@ -23,6 +23,7 @@ use option::{Option, Some, None}; use rt::borrowck; use rt::borrowck::BorrowRecord; use rt::env; +use rt::io::Writer; use rt::kill::Death; use rt::local::Local; use rt::logging::StdErrLogger; @@ -56,7 +57,8 @@ pub struct Task { sched: Option<~Scheduler>, task_type: TaskType, // Dynamic borrowck debugging info - borrow_list: Option<~[BorrowRecord]> + borrow_list: Option<~[BorrowRecord]>, + stdout_handle: Option<~Writer>, } pub enum TaskType { @@ -141,7 +143,8 @@ impl Task { name: None, sched: None, task_type: SchedTask, - borrow_list: None + borrow_list: None, + stdout_handle: None, } } @@ -175,7 +178,8 @@ impl Task { coroutine: Some(Coroutine::new(stack_pool, stack_size, start)), sched: None, task_type: GreenTask(Some(home)), - borrow_list: None + borrow_list: None, + stdout_handle: None, } } @@ -198,7 +202,8 @@ impl Task { coroutine: Some(Coroutine::new(stack_pool, stack_size, start)), sched: None, task_type: GreenTask(Some(home)), - borrow_list: None + borrow_list: None, + stdout_handle: None, } } @@ -234,6 +239,7 @@ impl Task { // Run the task main function, then do some cleanup. do f.finally { + // First, destroy task-local storage. This may run user dtors. // // FIXME #8302: Dear diary. I'm so tired and confused. @@ -257,6 +263,17 @@ impl Task { // Destroy remaining boxes. Also may run user dtors. unsafe { cleanup::annihilate(); } + + // Finally flush and destroy any output handles which the task + // owns. There are no boxes here, and no user destructors should + // run after this any more. + match self.stdout_handle.take() { + Some(handle) => { + let mut handle = handle; + handle.flush(); + } + None => {} + } } } @@ -331,7 +348,7 @@ impl Task { impl Drop for Task { fn drop(&mut self) { rtdebug!("called drop for a task: {}", borrow::to_uint(self)); - rtassert!(self.destroyed) + rtassert!(self.destroyed); } } diff --git a/src/libstd/rt/uv/uvio.rs b/src/libstd/rt/uv/uvio.rs index 29370c484eb5a..1d78a2a8f2ba8 100644 --- a/src/libstd/rt/uv/uvio.rs +++ b/src/libstd/rt/uv/uvio.rs @@ -1791,7 +1791,7 @@ impl RtioTTY for UvTTY { } fn isatty(&self) -> bool { - unsafe { uvll::guess_handle(self.fd) == uvll::UV_TTY } + unsafe { uvll::guess_handle(self.fd) == uvll::UV_TTY as c_int } } } diff --git a/src/libstd/rt/uv/uvll.rs b/src/libstd/rt/uv/uvll.rs index 75e6a0c6ca552..18e95c8966e18 100644 --- a/src/libstd/rt/uv/uvll.rs +++ b/src/libstd/rt/uv/uvll.rs @@ -977,7 +977,8 @@ pub unsafe fn tty_get_winsize(tty: *uv_tty_t, width: *c_int, #[fixed_stack_segment]; #[inline(never)]; rust_uv_tty_get_winsize(tty, width, height) } -pub unsafe fn guess_handle(fd: c_int) -> uv_handle_type { +// FIXME(#9613) this should return uv_handle_type, not a c_int +pub unsafe fn guess_handle(fd: c_int) -> c_int { #[fixed_stack_segment]; #[inline(never)]; rust_uv_guess_handle(fd) } @@ -1148,7 +1149,7 @@ extern { fn rust_uv_tty_set_mode(tty: *uv_tty_t, mode: c_int) -> c_int; fn rust_uv_tty_get_winsize(tty: *uv_tty_t, width: *c_int, height: *c_int) -> c_int; - fn rust_uv_guess_handle(fd: c_int) -> uv_handle_type; + fn rust_uv_guess_handle(fd: c_int) -> c_int; // XXX: see comments in addrinfo.rs // These should all really be constants... diff --git a/src/rt/rust_uv.cpp b/src/rt/rust_uv.cpp index 0cbbb58d02c66..c59dacab88990 100644 --- a/src/rt/rust_uv.cpp +++ b/src/rt/rust_uv.cpp @@ -659,7 +659,7 @@ rust_uv_tty_get_winsize(uv_tty_t *tty, int *width, int *height) { return uv_tty_get_winsize(tty, width, height); } -extern "C" uv_handle_type +extern "C" int rust_uv_guess_handle(int fd) { return uv_guess_handle(fd); }