Your Log Level Is a Performance Setting

This is the fourth post in the Campfire series. The fix that shipped is Jose Luis Chavez del Cid’s (@jlchavez), from his pull request #253. We found the same problem in our own profiling loop and wrote our own fix, and then dropped ours, because his matched Rails more closely.

Our numbers below were measured during development, one fix at a time, on an Intel i9-11900K running Linux with the app on four CPUs. Jose’s were measured on his own machine. Neither set is the final benchmark.

The symptom

The benchmark harness runs every app with RAILS_LOG_LEVEL=warn. At that level Rails writes nothing per request. The C# server never read the variable, so it stayed at its default of Information, and at Information ASP.NET Core’s hosting diagnostics write two lines for every request: “Request starting” and “Request finished”.

Two lines doesn’t sound like much. A 70-second run of the room page left 6.7 million lines in the container’s log.

What the profiler showed

CPU samples on the room page at about 29,000 requests a second:

  • ConsoleLogger.Log was 5.9% of the samples, counting everything it called.
  • The lock in ConsoleLoggerProcessor.Enqueue, which hands each line to the console logger’s background writer, accounted for 6,847 of the 9,600 samples spent waiting on a contended lock. That’s 71% of all lock contention in the process, from logging.

The lock is the bigger problem. The console logger formats each message on the request thread and puts it on a queue that one background thread writes out. Every request thread takes the same lock to add to that queue. At tens of thousands of requests a second, that queue becomes a point where every request lines up.

The lesson

Your log level controls how much work every request does. At Information, ASP.NET Core logs every request, and so do many libraries. That’s useful in development and in a quiet production app. Under load it’s a per-request cost with a shared lock in the middle, and it scales with your traffic.

It’s also easy to lose. The ASP.NET Core project templates set Microsoft.AspNetCore to Warning in appsettings.json, which hides these two lines. If your app reads its log level some other way, from an environment variable, a container setting or code, check that the setting actually reaches the logging builder. Ours didn’t.

The fix

Rails reads its level from config.log_level = ENV.fetch("RAILS_LOG_LEVEL", "info"). Jose’s change reads the same variable, maps Ruby’s level names to .NET’s, and sets the minimum level when the host is built:

// config.log_level = ENV.fetch("RAILS_LOG_LEVEL", "info"). Logging__LogLevel__* in the
// environment still overrides it per category.
builder.Logging.SetMinimumLevel(settings.LogLevel);

The mapping follows Rails: debug, info, warn, error and fatal map to the matching .NET levels, unknown turns logging off, and any other value is a settings error, as it is in Rails. Unset, it’s still info, so nothing changes for anyone who didn’t ask for a quieter log.

The result

Our version of the fix, measured in a quick A/B with three alternating rounds per route, and on the full harness:

Route Quick A/B Benchmark harness
Room page +17.6% +15.7%
Messages page +18.7% +16.7%
Sidebar +21.0% +19.7%
Search +21.1% +20.3%

The container’s log went from about 6 million lines per round to none. Every response was validated against the route contracts in both runs.

Jose’s own measurement of his fix, over five paired rounds on his machine: +8% on the room page, +19% on search and +10% on posting, and the container’s CPU per room page request fell from 441 to 338 microseconds.

One fix can hide another

The same pull request turned off DATAS, .NET’s adaptive GC heap count, in the container image. Jose found that it cut time paused in the GC from 6.0% of wall time to 2.2% at benchmark load. With logging at Information, the throughput change was inside the noise. With logging at Warning, it added about 4 to 12 percentage points.

So the GC setting looked useless until the logging cost was gone. If you A/B one setting while a larger cost is still in the way, you can throw away a real gain. DATAS off also holds more memory (about 65 MB more under HTTP load in his measurements), and an environment variable turns it back on, so it’s a trade, and the commit message says so.

Check your own app

  • Run your app under load and count the log lines per request. Anything above zero at your production level is a cost you’re choosing.
  • Check that the level you set is the level the logging builder sees, especially if it comes from an environment variable or a container setting rather than appsettings.json.
  • In a contention profile, look for ConsoleLoggerProcessor or your logging library’s queue.
  • If you need request logs in production, prefer a structured logger with a non-blocking sink, and sample rather than log every request.
  • After removing a large cost, re-test the small changes you rejected earlier.

Try it in LINQPad

This script runs two copies of the same app, one at Information and one at Warning, and measures both. Enable “Reference ASP.NET Core” in the query properties (F4). It writes a lot of output at Information, which is the point, so run it with the results pane cleared.

// Two copies of the same app. The only difference is the minimum log level.
var info = await Start(5201, LogLevel.Information);
var warn = await Start(5202, LogLevel.Warning);

await RequestsPerSecond("http://127.0.0.1:5201/up", seconds: 2); // warm up
await RequestsPerSecond("http://127.0.0.1:5202/up", seconds: 2);

var results = new
{
    Information = await RequestsPerSecond("http://127.0.0.1:5201/up"),
    Warning = await RequestsPerSecond("http://127.0.0.1:5202/up"),
};

await info.StopAsync();
await warn.StopAsync();
results.Dump("Requests per second, 16 clients");

async Task<WebApplication> Start(int port, LogLevel level)
{
    var builder = WebApplication.CreateBuilder();
    builder.Logging.ClearProviders();
    builder.Logging.AddSimpleConsole();
    builder.Logging.SetMinimumLevel(level);
    var app = builder.Build();
    app.Urls.Add($"http://127.0.0.1:{port}");
    app.MapGet("/up", () => "OK");
    await app.StartAsync();
    return app;
}

async Task<double> RequestsPerSecond(string url, int clients = 16, int seconds = 5)
{
    using var client = new HttpClient();
    var stopAt = DateTime.UtcNow.AddSeconds(seconds);
    long count = 0;
    await Task.WhenAll(Enumerable.Range(0, clients).Select(async _ =>
    {
        while (DateTime.UtcNow < stopAt)
        {
            using var response = await client.GetAsync(url);
            Interlocked.Increment(ref count);
        }
    }));
    return Math.Round(count / (double)seconds);
}

I ran it with LPRun9 and sent the output to a file. The copy at Warning served about 154,000 requests a second and the copy at Information about 20,000, and the file had 130,000 “Request starting” lines in it. An endpoint that returns “OK” is the worst case, because logging is almost all the work, but the direction holds for real pages too, as the table above shows.

The next post is about a cost hidden inside a convenient API.

csharp dotnet performance logging aspnet core kestrel gc linqpad