Rick Strahl's Weblog  

Wind, waves, code and everything in between...
.NET • C# • Markdown • WPF • All Things Web
Contact   •   Articles   •   Products   •   Support   •   Advertise
Sponsored by:
West Wind WebSurge - Rest Client and Http Load Testing for Windows

Don't let ASP.NET Core Console Logging Slow your App down


:P
On this page:

Earlier today I put my foot in my mouth on Twitter by running a quick and dirty perf test application to check out a question from a customer, without properly setting up configuration.

Specifically I ran my application directly out of the Release folder without first publishing and while that works to run the application, it doesn't copy over the configuration files. Since there was no configuration, ASP.NET Core started the console app without any explicit logging overrides and I got the default Console logging configuration which produced a crap-ton of Console log messages which in turn slowed the application under load to a crawl.

How slow? Take a look - here in WebSurge:

Figure 1 - Load testing with Information Console: 940 req/sec

Figure 2 - Load testing with Warning Console: 37,000+ req/sec

  • With Logging (Information): <1k req/sec
  • Without Logging (Warning): 37k+ req/sec

Yup, that's nearly a 40x difference in these admittedly small do-nothing requests. Even with the async logging improvements in .NET Core 2.x Console logging is very, very slow when it is set to Information or worse Debug. The default ASP.NET Core default if there's no configuration at all is Information. Not cool!

Luckily the default templates handle setting the Logging Level to Warning in production, but the raw default Logging Level of Information is still a headscratcher.

Moral of the story: Make sure you know what your Console logger is doing in your application and make sure it's turned down to at least Warning or off in production apps.

Operator Error: Missing Configuration

My error was that I tried to be quick about my test, simply compiling my tiny project and running it out of the Release folder. That works, but it's generally not recommended for an ASP.NET Core application.

Instead what I got was this:

Figure 3 - Running out of the Release folder rather than the Publish folder can cause problems due to missing configuration

Notice that the folder is Release/netcore22 which is the plain Release folder, not the published app folder!

ASP.NET Core applications should be published with dotnet publish which creates a self contained folder structure that includes all the dependencies and support files and folders that are needed for the application to run. In Web applications that tends to be the wwwroot folder, the runtime dependency graph and configuration files.

In this case specifically dotnet publish copies the appsettings.json configuration file(s) which is what I was missing to get the default Console Information logging behavior.

The default dotnet new template for Production (appsettings.json) sets the default logging level to Warning:

{
  "Logging": {
    "LogLevel": {
      "Default": "Warning"
    }
  }
}

which is appropriate for Production at runtime. And this works fine producing only console output on warnings and errors which should be relatively rare.

Here's the bummer though:

ASP.NET Core's default logging level is Information

By default if you don't apply explicit configuration (configuration file, environment vars, manual etc.), it will log a Information level messages which equals a ton of crap that you are unlikely to care about in the console or any other logging source in production.

Overriding Logging Behavior in ASP.NET Core

Logging is an important part of any application and ASP.NET Core introduces very nice logging infrastructure that is useful out of the box and allows for powerful extensibility via clearly defined and relatively easy to implement interfaces.

The Console Logger

One of the provided logging providers is the Console Logger which outputs logging information to the terminal. This is very useful during development as you can see exception information and log your own status information to the console for easy tracing and debugging.

It can also be useful in production. Even if you normally run your application behind a proxy normally it's possible to spin up the application from a terminal and potential check for terminal output directly. This can be especially useful for debugging startup errors. I've had to do that on a few occasions with IIS hosted applications because IIS failed to connect due the app not spinning up properly on the host.

Otherwise, realistically a Console logger is not the most useful thing in Production. The default configuration creates a Console logger regardless of configuration and there's no easy way to just remove a single logger. Rather you have to rebuild the entire logging configuration yourself (which is not that difficult but not all that obvious).

Console Logging is Very Slow

The problem with Console logging is that logging to the console is dreadfully slow at least on Windows as I showed above. In the past the biggest issue was that the Console (using System.Console.WriteLine()) is a sequential blocking call and under load that blocking is enough to seriously slow down request processing.

In .NET Core 2.0 and later improvements were made to provide a queue in front of the console and asynchronously log in a background thread writing out to the actual Console. Although that improved performance some the queue itself is also blocking so there's overhead there as well and performance still is quite slow potentially throttling request throughput.

Default Logging Configuration

The good news is if you create new ASP.NET Core 2.x project the default configuration for production does the right thing by setting the logging level to Warning in applicationsettings.json:

{
  "Logging": {
    "LogLevel": {
      "Default": "Warning"
    }
  }
}

The development version in applicationsettings.Development.json is more liberal and writes a lot more logging output:

{
  "Logging": {
    "LogLevel": {
      "Default": "Debug",
      "System": "Information",
      "Microsoft": "Information"
    }
  }
}

Logging levels are incremental so Trace logs everything, Warning logs Warning, Error and Critical, and None logs... well none.

  • Trace
  • Debug
  • Information
  • Warning
  • Error
  • Critical
  • None

So far so good.

What if you have no applicationsettings.json and no other configuration overrides? In this case the default is Information meaning a lot of logging happens to Console and this is how I ended up with this post.

Turning Off Console Logging

You can turn off console logging in a number of ways:

  • appsettings.json
  • custom logging configuration
  • removing the console log provider

Using Configuration

The easiest way to get control over your Console logging is to simply turn down your Logging volume by setting the logging level to Warning or Error. Any lower than that - Information or Debug - should really just be used during development or in special cases when you need to track down a hard to find bug. In Production there should rarely be a need to do information/debug level logging.

Any changes you make to the configuration settings either in appsettings.json or any other configuration providers like environment variables, affects all Logging providers that are configured. By default ASP.NET Core configures DebugLogger, ConsoleLogger and EventSourceLogger. Any logging level settings affect all of these providers by default.

Using the configuration settings in appsetting.json and setting to Warning was enough to get my scrappy test application to run at full throttle closer to the 37k request/sec.

Where does Default Logging Configuration come from

The default logging configuration originates in the ASP.NET Core's default configuration which is part of the WebHost.CreateDefaultBuilder() configuration during the host startup in program.cs:

public static IWebHostBuilder CreateWebHostBuilder(string[] args) =>
                WebHost.CreateDefaultBuilder(args)
                .UseStartup<Startup>();

You can take a look at what the default builder does by source stepping (or decompiling) WebHost.CreateDefaultBuilder(). The relevant logging configuration code in the default WebHost looks like this:

.ConfigureLogging((Action<WebHostBuilderContext, ILoggingBuilder>) ((hostingContext, logging) =>
      {
        logging.AddConfiguration((IConfiguration) hostingContext.Configuration.GetSection("Logging"));
        logging.AddConsole();
        logging.AddDebug();
        logging.AddEventSourceLogger();
      }))

Using the Logger in your Code

Once configuration has been configured you can use the logger via Dependency injection by injecting ILogger<T> into your code.

[ApiController]
public class ValuesController : ControllerBase
{
    public ILogger<ValuesController> Logger { get; }

    public ValuesController(ILogger<ValuesController> logger)
    {
        Logger = logger;
    }

    // GET api/values
    [HttpGet]
    public string  Get()
    {
        Logger.LogInformation("Hello World In Values Controller");            
        return "Hello World " + DateTime.Now;
    }
}    

The T in ILogger<T> provides a logging context that is shown on log messages so you can decide on whether to use a local or more global scope. ILogger has a number of methods to log the various logging levels like LogInformation() above or LogError(), LogCritical() and so on.

Overriding the Default Logging Configuration

If the default logging setup provided by the WebHostBuilder doesn't suit you you can clear everything out and configure your own logging stack from scratch by doing something like the following in your Startup.ConfigureServices() method:

public void ConfigureServices(IServiceCollection services)
{
    services.AddLogging(config =>
    {
        // clear out default configuration
        config.ClearProviders();

        config.AddConfiguration(Configuration.GetSection("Logging"));
        config.AddDebug();
        config.AddEventSourceLogger();
        
        if(Environment.GetEnvironmentVariable("ASPNETCORE_ENVIRONMENT") == EnvironmentName.Development) 
        {
        	config.AddConsole();
        }
    });

    ... 
}

There are no config.RemoveProviderXXX() functions - once created the logging configuration has to be cleared and effectively rebuilt completely, and since the default config sets this up, any changes pretty much require this type of code.

You can control the logging levels via configuration, but you can't add or remove providers that way, so if you need custom providers or want to remove provider like say the Console provider in production you have to do it in code.

Summary

What I've covered here is probably an odd edge case that you may never see, but it's one that can bite you when you're not paying attention. Heck logging in general can add significant overhead. It's a good reminder that Console logging can have a big performance hit for little benefit. There are more efficient ways to log and other than for on site debugging there's not much use for console logging in the first place at least running in production.

Ah, the little consolations in life... they always come back to bite 'ya!

this post created and published with Markdown Monster
Posted in ASP.NET  

The Voices of Reason


 

Mani Gandham
December 31, 2018

# re: Don't let ASP.NET Core Console Logging Slow your App down

We ran into this too with console logging.

System.Console.Out is a TextWriter for stdout and that already supports WriteAsync and WriteLineAsync so replacing the default Console logger with a custom one with a in-memory buffer and async methods removed all the blocking and latency overhead.

This is also much easier to do with Serilog or other logging frameworks that have more fine-grained configs around logging outputs.


Rick Strahl
December 31, 2018

# re: Don't let ASP.NET Core Console Logging Slow your App down

@Mani - yeah I use Serilog in most production apps as well but for test and play projects the internal logging is 'just there' and it works well.

Still not clear why the Console logger is so slow. The default implementation in 2.x and later uses a queue to buffer the messages and I can see the intermediate queue handling in the code firing and not directly writing, but it's still deadly slow. I wonder if the queue synchronization itself is so slow as the request count gets big that it's actually not much faster than the Console.Write() calls. Seems odd.


Tisho Iliev
June 10, 2019

# re: Don't let ASP.NET Core Console Logging Slow your App down

Thanks a lot dude, I was one step away to release logging with Debug log level on prod 😭


Igor Manushin
July 29, 2019

# re: Don't let ASP.NET Core Console Logging Slow your App down

I suggest you to consider asynchronous logging. I made several benchmarks here, which shows, that in the most cases non-blocking tracing has the same speed with no-op log methods calls (e.g. just call method of Logger, which is disabled for now).


Matteo Contrini
September 15, 2019

# re: Don't let ASP.NET Core Console Logging Slow your App down

@Rick Strahl, the problem of the console logger implementation is that the BlockingCollection is limited to just 1024 items. When that limit is exceeded, the Add() calls will hang there and cause the slowdown.

I run a quick benchmark by logging 10k lines with and without the capacity set on the BlockingCollection. On my machine, the result is about 8 seconds with a capacity of 1024 and 30 milliseconds with a high/unlimited capacity. Memory usage seems to be only slightly higher.


Rick Strahl
December 25, 2019

# re: Don't let ASP.NET Core Console Logging Slow your App down

@Matteo - thanks for that - that's a good data point.

Still not sure if that is the cause though -I'm running 8 simultaneous requests in these tests (full throttle, no delay) so in theory there shouldn't be more than 8 requests running simultaneously (maybe with some rolloff, but not massively over the 8 client treshold), unless... the caching is actually slow and the many debug log requests are quickly filling up the cache.


Peter Kellner
February 28, 2020

# re: Don't let ASP.NET Core Console Logging Slow your App down

As always, thanks for this article. so much easier to add logging then what is on docs.microsoft.com (Sorry Steve).

With core 3.1, this doesn't compile anymore: config.AddConfiguration(Configuration.GetSection("Logging")); (can not resolve symbol Config) Thoughts? (love breaking changes)

How's your immune system Rick?


Rick Strahl
February 28, 2020

# re: Don't let ASP.NET Core Console Logging Slow your App down

@Peter - hmmm that's odd. Just tried custom config in a 3.1 app and that code works for me without issue. You need Microsoft.Extensions.Configuration and IConfiguration injected, but I think new projects do that by default now.


Steve Pettifer
March 17, 2020

# re: Don't let ASP.NET Core Console Logging Slow your App down

Just been bitten by this - somehow our default logging level block was removed from config so it defaulted to Information. Cue a crap ton of junk heading out to console and once deployed to AKS, that got piped straight to Log Analytics (we didn't realise it was doing that - our team and the team that manage our AKS instances had a mis communication!). turns out Log Analytics was costing more than the AKS resources. Oops.


Sebastian
March 19, 2020

# re: Don't let ASP.NET Core Console Logging Slow your App down

I always use Console logger and the performance does not depend that much on the logger itself, but more how stdout is handled.

Yes, usually it is very slow, Powershell or Command Line are terribly slow. But not as terrible as in your micro benchmark. When your request has a total of 20ms compute time than the 0.2ms for logging does not matter that much. In real application the difference is not that big.

But more importantly it also depends on your deployment.

I think in IIS, the stdout is usually just discarded, but you can also forward stdout to a file.

In docker or kubernetes, stdout is forwarded to the logging driver, which is usually just a file. Then you can either use another logging driver or setup another container which reads the files and forwards the log entries to a logging system such as ElasticSearch. I use Google Cloud Engine and you get this for free there.

Btw: Stdout is also one of the principles of a 12-factor app: https://12factor.net/logs


Rick Strahl
March 19, 2020

# re: Don't let ASP.NET Core Console Logging Slow your App down

@Sebastian - there's nothing wrong with using the Console logger, if you don't log in info mode. That's because normal production error mode only writes out error info which hopefully should be infrequent. But if you have info logging going on you will slow down your app regardless of where stdout points or how the logger writes it out. It's obviously exaggerated by a high volume scenario where many threads are competing for the same log resource, but that's the point of this post.

The key is to make sure that logging only logs errors in production 😃


Povilas Panavas
May 13, 2020

# re: Don't let ASP.NET Core Console Logging Slow your App down

Hi!

My issue was that it was logging into EventLog (3.1 core, and happens only on Windows machines). Windows locked up the file after about a month in prod, and logging started to crash together with API requests.

After that I've realised that Console is on by default as well, and from experience I knew how slow it was. And wanted to check online if it's still the same. This landed me on this website.

However, today after spending 3 hours testing deployments in Azure (apps run on App Service Plans), I CAN TELL THAT CONSOLE HAS NO IMPACT ON PERFORMANCE when using deployments in Azure with App Service Plan (Windows).

I think that's what Sebastian is saying. Any Console logs are disregarded, so it's almost the same as changing logging Level.

However, I can confirm that locally, the difference in speed was 10+ times when running as console app or using IIS express.

My point is, that as long as you hosting it in App Service Plan (Windows), console doesn't matter.

Anyone has performance results to prove that Console reduces speed on APIs hosted in App Service Plans using Windows (IIS)?

My test was simply to use ConfigureWebHostDefaults (which will provide four logging providers as can be seen in documentation), and to put no configuration at all in *.json files. That means I used totally default logging settings.

To benchmark I used the same app as the author here, and settings were 60 seconds, and threads 200 and 500. In both cases, there's no noticeable speed difference between using Console and not.

I couldn't believe results, so I tried JMeter, but again, no impact when using console.

And thank you for this detailed article, it helped me understand better how defaults work.


Blair Allen
September 10, 2020

# re: Don't let ASP.NET Core Console Logging Slow your App down

@Rick Strahl, in your last code example where you conditionally add the console logging provider, you could make the code more robust/easy to read by depending on an instance of IHostEnvironment or IWebHostEnvironment. e.g.:

private readonly IConfiguration _configuration;
private readonly IWebHostEnvironment _hostEnvironment;

public Startup(IConfiguration configuration, IWebHostEnvironment hostEnvironment)
{
    _configuration = configuration;
    _hostEnvironment = hostEnvironment;
}

public void ConfigureServices(IServiceCollection services)
{
    services.AddLogging(config =>
    {
        // clear out default configuration
        config.ClearProviders();

        config.AddConfiguration(_configuration.GetSection("Logging"));
        config.AddDebug();
        config.AddEventSourceLogger();
        
        if (_hostEnvironment.IsDevelopment()) 
        {
            config.AddConsole();
        }
    });

    ...
}

public void Configure(IApplicationBuilder app)
{
    if (_hostEnvironment.IsDevelopment())
    {
        app.UseDeveloperExceptionPage();
    }

    ...
}

Now both Configure and ConfigureServices are depending upon the same environment helper class and the code to check the current environment is much cleaner.

Per Visual Studio template, Configure already wants an argument for IWebHostEnvironment. I removed it since an instance is now provided via dependency injection (just like IConfiguration) and did not notice any adverse side effects. The framework seemingly is happy to call Configure with just the argument for the app builder.

Question: Wouldn't you also want to move config.AddDebug(); to the conditional test for a development environment? It seems the debug provider provides logging to a debugger, which you are unlikely to do in a production environment. Am I correct, or is AddDebug() useful even in production environments?

That all aside, thank you for providing this in-depth explanation of how the framework sets up the logging providers by default and how to make production code more efficient!


Sandeep Parmar
October 08, 2020

# re: Don't let ASP.NET Core Console Logging Slow your App down

Hello,

I have dotnet core 2.2 where I am facing similar issue with console logging. I have multi threaded console application where I have configure logging as below but somehow I am not able to turn off the logging. I tried different options. As I have long running process as time goes I see many threads and memory increase in task manager.

"Logging": {
    "LogLevel": {
      "Default": "Warning",
      "System": "Information",
      "Microsoft": "Information",
      "Microsoft.EntityFrameworkCore.Database.Command": "Warning"
    },
    "Console": {
      "LogLevel": {
        "Default": "None"
      }
    }
  }

 services.AddLogging(b =>
            {
                b.ClearProviders();
                //b.AddConfiguration(s_configuration.GetSection("Logging"));
                //b.AddFilter((category, level) => true);
                //b.AddConsole(options => options.IncludeScopes = false);
            });

Dima
May 24, 2021

# re: Don't let ASP.NET Core Console Logging Slow your App down

Is this true for .NET 5.0?

If not, you can use this code, instead of the authors:

if (env.IsProduction())
{
    var consoleLogger = services.FirstOrDefault(x => x.ImplementationType == typeof(ConsoleLoggerProvider));
    services.Remove(consoleLogger);
}

Benk
December 10, 2021

# re: Don't let ASP.NET Core Console Logging Slow your App down

This is windows only , its because console has a giant lock on it to prevent multi threaded garbling of the messages serilogs console is even worse.


West Wind  © Rick Strahl, West Wind Technologies, 2005 - 2024