The Speed Limit in Your Logs

In our .NET 10 lab, an ASP.NET Core API handled 59,830 requests a second with its output piped to another process that read it as fast as it could. The same build handled 2,524 requests a second in Windows Terminal, using 6.4% of the machine's CPU. In a classic console window, it managed 854.

We made no code changes between runs. All we changed was what read the process's standard output.

The API used the logging levels set by the ASP.NET Core template and the console logger that WebApplication.CreateBuilder adds by default. The logger writes on a background thread, so requests can carry on while it handles the output. But that only works while there's room in the queue. Once it fills up, every request that logs has to wait for the console.

We ran each scenario three times. Here are the measurements, what explains the slowdown, and which fixes work.

Five messages per request

Our endpoint calls an inventory service over HTTP through IHttpClientFactory (in the lab, an endpoint in the same process), then writes a log message of its own. We use the template's logging configuration in appsettings.json:

{
  "Logging": {
    "LogLevel": {
      "Default": "Information",
      "Microsoft.AspNetCore": "Warning"
    }
  }
}

Setting Microsoft.AspNetCore to Warning suppresses the per-request logs from Kestrel and hosting, so the console looks quiet during development. But the HttpClient logs use categories under System.Net.Http, so they inherit the Default level. Each outgoing call produces four Information messages. Here's what we saw for one request to our endpoint:

info: System.Net.Http.HttpClient.inventory.LogicalHandler[100]
      Start processing HTTP request GET http://127.0.0.1:5871/inventory/0
info: System.Net.Http.HttpClient.inventory.ClientHandler[100]
      Sending HTTP request GET http://127.0.0.1:5871/inventory/0
info: System.Net.Http.HttpClient.inventory.ClientHandler[101]
      Received HTTP response headers after 25.1541ms - 200
info: System.Net.Http.HttpClient.inventory.LogicalHandler[101]
      End processing HTTP request after 31.1372ms - 200
info: QuoteEndpoint[0]
      Quote 0 priced at 10

That adds up to five messages and about 570 bytes per request. At 59,830 requests a second, the API was writing almost 33 MiB of log text every second. Our fast pipe kept up.

Asynchronous until the queue is full

Microsoft's logging guidance says logging "should be so fast that it isn't worth the performance cost of asynchronous code." The console logger uses a queue to keep calls fast. The calling thread formats each message and adds it to an in-memory queue. A single background thread pulls messages from the queue and writes them to the console.

Two settings control what happens when the writer can't keep up:

Both settings arrived in .NET 7. In .NET 6, the queue held a fixed 1,024 messages and always blocked when full.

For our API, a queue of 2,500 messages leaves room for about 500 requests before logging starts to block. Once it fills, throughput depends on how fast the reader can drain it: log bytes per second divided by log bytes per request.

To test this, we replaced the window with a pipe and had our harness read it at exactly 1 MiB a second. At 570 bytes per request, we'd expect about 1,840 requests a second. We measured 1,844. Across every run of every variant that kept those five messages, throughput stayed between 1,842 and 1,845 requests a second.

The server used 2.1% of the CPU, but 99th-percentile latency rose from 2.8 ms to 159 ms. Our own LogInformation call averaged 1.7 ms and took up to 238 ms. With the fast reader, it averaged 0.009 ms.

The server averaged half a core out of 24. The requests were waiting for the console.

What helps, and what doesn't

We kept the 1 MiB/s pipe and changed one thing at a time:

Neither of the obvious fixes improved throughput. A bigger queue can absorb a burst, but under steady load it fills in a fraction of a second. It also pushed the server's peak working set from 124 MiB to 201 MiB. Source-generated logging avoids boxing and template parsing on the calling thread, but still writes the same bytes. The reader remains the bottleneck.

What worked was writing fewer bytes. Raising the HttpClient categories to Warning left one 55-byte message per request and increased throughput tenfold. Raising Default to Warning removed all five messages, letting the API run at full speed.

DropWrite removed the reader as the limit by throwing logs away. It reached 64,448 requests a second in the table's run and 42,247 in our first round: without the reader as the limit, the result depends on the CPU. Of 6.9 million messages in that run, 203,030 reached the pipe, about 3 in 100. It drops new messages whatever their level, so warnings and errors are lost too. The logger reports the losses in batches, with a line on standard error once the queue accepts messages again:

31 message(s) dropped because of queue size limit. Increase the queue size or decrease logging verbosity to avoid this. You may change `ConsoleLoggerQueueFullMode` to stop dropping messages.

It wrote 160,832 of those lines during the run, and our harness read them at full speed. In your deployment, they go wherever standard error goes, possibly to the same slow reader.

When the reader stops

A slow reader limits throughput. If it stops reading altogether, the API stalls. We ran the API at full speed, then paused the pipe reader for five seconds.

With the default Wait setting, no request completed for at least 4.75 seconds (19 empty quarter-second intervals) in each of the three runs. The slowest request took 5,001 ms. Once the reader resumed, the API recovered within a quarter of a second. With DropWrite, the API kept serving requests throughout the pause. Its slowest request took 31 ms, but it dropped 2,332,784 messages over the run.

Docker uses blocking log delivery by default. Its documentation explains why it offers an alternative: "Applications are likely to fail in unexpected ways when STDERR or STDOUT streams block."

Where does your stdout go?

The console logger writes to the process's standard output. How fast it can write depends on what's reading it:

• A terminal window. In our lab, Windows Terminal capped the API at 2,524 requests a second and a classic console window at 854. When you load-test an API started with dotnet run in a terminal, you're measuring the terminal too.
• A pipe to a parent process. This might be a service wrapper, a supervisor or a log shipper. Output moves as fast as the reader can consume it, provided the reader keeps reading.
• A container log driver. Docker blocks by default, as quoted above.
• IIS. With stdoutLogEnabled, the ASP.NET Core Module redirects standard output to a file. Its documentation says: "Using the stdout log is only recommended for troubleshooting app startup issues".

For each environment, ask how fast the reader can keep up and what happens when it stalls.

Check your own services

1. Check where standard output goes in each environment: a terminal, a service wrapper, a container log driver, or a file.
2. Check the log levels production actually uses, including settings in appsettings.Production.json and environment variables such as Logging__LogLevel__Default.
3. Send one request to a hot endpoint using the production log levels, then count the log messages it writes (two lines each in the default format). Count every Information message from HttpClient, too.
4. Set categories nobody reads to Warning. Changing "System.Net.Http.HttpClient": "Warning" alone took our endpoint from five messages to one.
5. Decide what should happen when the queue fills up. With "Logging": { "Console": { "QueueFullMode": "DropWrite" } }, the API keeps serving but loses logs of every level. Watch standard error for "message(s) dropped".
6. Load-test twice: once with console output going somewhere fast, to measure the API, and once with production logging and its real destination, to measure what production will do.

What we measured

• Our API handled 2,524 requests a second in a terminal window and 854 in a classic console window. With a fast pipe, it reached 59,830.
• With a reader limited to 1 MiB/s, throughput matched the reader's speed divided by the 570 bytes logged per request. The CPU stayed nearly idle.
• Increasing the queue size and switching to source-generated logging did not change throughput. Logging fewer bytes per request raised it. DropWrite restored throughput but lost 97 of every 100 messages.
• Pausing the reader for five seconds meant no request completed for at least 4.75 seconds.

The console logger works well when someone is watching the console. In production, you need to decide where the output goes and what the API should do if that destination slows down.

How we ran this

We used .NET 10.0.14 (SDK 10.0.403) and the ASP.NET Core shared framework, with no NuGet packages, on Windows 11 build 26300 with 24 logical processors.

A harness process started the API as a child process, redirecting standard output and standard error to pipes. It read standard output at a controlled rate and standard error at full speed. It generated load through 64 concurrent connections, with each connection sending its next request as soon as the previous one finished. Each run had a 3-second warm-up followed by a 20-second measurement. The throughput and latency figures describe those 64 request loops on one machine; they are a comparison between configurations.

The API used the template's logging configuration and the default console formatter. For the terminal runs, we used Windows Terminal 1.24 as the default terminal application and conhost.exe for the classic console window. In those runs, only the window read the output.

We ran every scenario three times. With the 1 MiB/s reader, throughput varied by 3 requests a second across runs, and the 4.75-second gap appeared in every run. Windows Terminal results ranged from 2,302 to 2,996 requests a second; the classic console window ranged from 771 to 1,132.

CPU-limited runs varied more. In most of our second round, they reached about a third of their first-round throughput, while the reader-limited runs stayed unchanged. We could not identify the cause and kept those runs on file. The figures in this article come from the third round, when we also recorded how much CPU the rest of the machine used.