TIL: Writing to stdout is only as fast as your terminal

Consider this barebones HTTP server:

use anyhow::Result;
use std::{
  io::{Read, Write},
  net::TcpListener,
};

fn main() -> Result<()> {
  let listener = TcpListener::bind("0.0.0.0:7096")?;
  let mut buf = [0u8; 4096];

  for stream in listener.incoming() {
    let mut stream = stream?;
    loop {
      if let Ok(n) = stream.read(&mut buf) {
        if n == 0 {
          break;
        }

        _ = stream.write_all(
          b"HTTP/1.1 200 OK\r\nContent-Length: 12\r\n\r\nHello World!",
        );
      }
    }
  }

  Ok(())
}

The language isn’t relevant for this post, so don’t focus too much on it. For people unfamiliar with Rust, this server is just returning a Hello World! response to any HTTP requests that come its way.

It is single-threaded, and can only work with one connection at a time, so it’s pretty bad, but let’s see what kind of performance we can get:

$ wrk -t1 -c1 -d10s http://127.0.0.1:7096

I’m using wrk here, which is an HTTP benchmarking tool. I’ve told it to use one thread (-t1) and one connection (-c1), and to run the benchmark for ten seconds (-d10s). Here are the results:

Running 10s test @ http://127.0.0.1:7096
  1 threads and 1 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency    16.51us    2.17us 170.00us   90.68%
    Req/Sec    57.17k     0.91k   57.77k    98.02%
  573678 requests in 10.10s, 27.90MB read
Requests/sec:  56801.42
Transfer/sec:      2.76MB

I”m running this on my measly M2 MacBook Air, but we’re still able to handle about 56000 requests per second.

Let’s now place a single log line in our server to tell us when we receive a request, keeping everything else exactly the same:

// ..snip
fn main() -> Result<()> {
  // ..snip

  println!("Incoming request!"); // <- Our log line

  _ = stream.write_all(
    b"HTTP/1.1 200 OK\r\nContent-Length: 12\r\n\r\nHello World!",
  );
  // ..snip
}

And run our benchmark again:

$ wrk -t1 -c1 -d10s http://127.0.0.1:7096
Running 10s test @ http://127.0.0.1:7096
  1 threads and 1 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency    39.37ms   81.52ms 418.46ms   85.34%
    Req/Sec    18.43k    14.01k   55.23k    63.89%
Requests/sec:  15062.45
Transfer/sec:    750.18KB

Oh boy, our performance took a nosedive. We’re only able to do 15000 requests a second now?! Normally you’d profile to figure out what your bottleneck is, but in this case it is pretty obviously our println!.

stdout is a blocking, buffered stream whose “write-end” is attached to your process, while the “read-end” attaches to your terminal. When you write to this stream, your bytes go to a buffer, and stay there until you write a newline character (\n), at which point all your bytes are sent to your terminal to display (in other words, stdout is “flushed”).

What this means is that you can only really write to stdout as fast as your terminal can consume it. If you write too quickly, your process’s write will block till stdout is flushed, meaning your process (or one of it’s threads) will stop making progress. In our case, wrk sends multiple HTTP requests on the same connection, and we attempt to write the static string Incoming request! to stdout. I ran my server (cargo run --release) in VSCode’s terminal, which isn’t the fastest, so it slowed down our entire program. What’s slow here is the VSCode terminal’s flush.

I’ll repeat this exact same experiment, except I’ll run my server on iTerm2 and Alacritty this time (remember what matters is where I’m printing from, not where I run wrk from):

# Server on iTerm2
$ wrk -t1 -c1 -d10s http://127.0.0.1:7096
Running 10s test @ http://127.0.0.1:7096
  1 threads and 1 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency    22.83us    8.80us   1.20ms   96.70%
    Req/Sec    42.06k   743.20    43.55k    93.07%
  422480 requests in 10.10s, 20.55MB read
Requests/sec:  41829.62
Transfer/sec:      2.03MB

# Server on Alacritty
$ wrk -t1 -c1 -d10s http://127.0.0.1:7096
Running 10s test @ http://127.0.0.1:7096
  1 threads and 1 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency    18.58us    3.56us 240.00us   92.80%
    Req/Sec    51.27k     1.11k   53.01k    97.03%
  515471 requests in 10.10s, 25.07MB read
Requests/sec:  51039.99
Transfer/sec:      2.48MB

Alacritty can almost keep up!

This post is mostly a PSA for myself. I’m yet to figure out how to have my cake and eat it too — how to log but not tank my RPS.