Skip to content

Cache and buffer stdout per-task for printing #10060

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 1 commit into from
Oct 25, 2013

Conversation

alexcrichton
Copy link
Member

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.

@brson
Copy link
Contributor

brson commented Oct 25, 2013

Super-nice work. 🍭

bors added a commit that referenced this pull request Oct 25, 2013
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.
@jdm
Copy link
Contributor

jdm commented Oct 25, 2013

Is there a way to force a buffer flush? I could imagine being confused by debug output not appearing before a task failure.

@alexcrichton
Copy link
Member Author

The with_task_stdout function is public, and writers expose a flush function, so that's how I figured that you would flush the task's stdout. For us it doesn't quite make sense to write stdio::flush() because that doesn't mean much when you're not using println and friends, so I figured that explicitly flagging it as the task's stdout then it would be clear what you're flushing.

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.
bors added a commit that referenced this pull request Oct 25, 2013
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.
@bors bors closed this Oct 25, 2013
@bors bors merged commit e8f72c3 into rust-lang:master Oct 25, 2013
flip1995 pushed a commit to flip1995/rust that referenced this pull request Dec 29, 2022
…x, r=llogiq

 Fix [match_single_binding] suggestion introduced an extra semicolon

Fix rust-lang#9725

---

changelog: [`match_single_binding`]: suggestion no longer introduces unneeded semicolons
[rust-lang#10060](rust-lang/rust-clippy#10060)
<!-- changelog_checked -->
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants