Skip to content

.NET console logging uses a blocking collection which is not optimal for cloud-native applications #65264

@maryamariyan

Description

@maryamariyan

With the current design of console logging, there is a dedicated thread that writes outputs to console and once message queue is full (with 1024 messages in the queue) the console logger starts blocking the application.

This gist summarizes some trial and error experiments done to evaluate console logger against Console.WriteLine and in different scenarios. We couldn't prove that console logging is slower than console write line. Instead what we want to focus on for this issue is to make sure we don't get a sudden drop in RPS as soon as we hit the max queue size threshold limit.

We could add two configurations improvements to console logger: (1) to allow for both dropping logs and (2) making buffer size configurable.

Configuring buffer size

Given that the queue size today is limited for the blocking collection below:
https://source.dot.net/#Microsoft.Extensions.Logging.Console/ConsoleLoggerProcessor.cs,15

The easiest way is to just expose the queue length to make it configurable.

But instead the main proposal here is to keep track of how many bytes each item in the queue is collectively carrying to decide what the desired maximum buffer size for the blocking collection should be.

Dropping logs

Dropping logs would not be allowed by default. The way dropping of logs would work is "if enabled", then when blocking collection is full, the the console logger would throw the message away.

API Proposal

Since ConsoleLoggerProvider instantiates ConsoleLoggerProcessor, it makes sense to add these configurable options to ConsoleLoggerOptions which is inhected into ConsoleLoggerProvider:

public ConsoleLoggerProvider(IOptionsMonitor<ConsoleLoggerOptions> options, IEnumerable<ConsoleFormatter>? formatters)
{
_options = options;
_loggers = new ConcurrentDictionary<string, ConsoleLogger>();
SetFormatters(formatters);
ReloadLoggerOptions(options.CurrentValue);
_optionsReloadToken = _options.OnChange(ReloadLoggerOptions);
IConsole? console;
IConsole? errorConsole;
if (DoesConsoleSupportAnsi())
{
console = new AnsiLogConsole();
errorConsole = new AnsiLogConsole(stdErr: true);
}
else
{
console = new AnsiParsingLogConsole();
errorConsole = new AnsiParsingLogConsole(stdErr: true);
}
_messageQueue = new ConsoleLoggerProcessor(console, errorConsole);

namespace Microsoft.Extensions.Logging.Console
{
    /// <summary>
    /// Options for a <see cref="ConsoleLogger"/>.
    /// </summary>
    public class ConsoleLoggerOptions
    {
        public bool DisableColors { get; set; }
        public ConsoleLoggerFormat Format { get; set; }
        public string? FormatterName { get; set; }
        public bool IncludeScopes { get; set; }
        public LogLevel LogToStandardErrorThreshold { get; set; } = LogLevel.None;
        public string? TimestampFormat { get; set; }
        public bool UseUtcTimestamp { get; set; }

+        /// <summary>
+        /// Gets or sets the desired console logger behavior when queue becomes full. Defaults to <c>Wait</c>.
+        /// </summary>
+        public ConsoleLoggerBufferFullMode BufferFullMode { get; set; }

+        /// <summary>
+        /// Gets or sets the maximum buffer size before the queue becomes full. Defaults to <c>1MB</c>.
+        /// </summary>
+        public int MaxBufferSizeInBytes { get; set; } = 1048576;
    }

+    /// <summary>
+    /// Determines the console logger behaviour when queue becomes full.
+    /// </summary>
+    public enum ConsoleLoggerBufferFullMode
+    {
+        /// <summary>
+        /// Blocks the console thread once the queue limit is reached
+        /// </summary>
+        Wait,
+        /// <summary>
+        /// Drops new log messages when the queue is full
+        /// </summary>
+        DropNewest,
+    }
}

Alternative Design

Alternatively, MaxQueueBufferSizeInBytes could be nullable and when not specified use an unbounded queue:

-        public int MaxBufferSizeInBytes { get; set; } = 1048576;
+        public int? MaxBufferSizeInBytes { get; set; }

Questions with design

  • Do we want to allow the MaxQueueBufferSizeInBytes to be reconfigurable on reload?

Usage samples

using var loggerFactory = LoggerFactory.Create(builder =>
{
    builder
        .AddConsole(o => o.QueueFullMode = ConsoleLoggerQueueFullMode.DropNewest)
        .AddSimpleConsole(o => o.ColorBehavior = LoggerColorBehavior.Disabled);
});
Original Issue

Console logger not quick enough per request to log for real world production applications. Refer to aspnet/Logging#515 (comment)

With the current design console logging happens on a separate thread and once message queue is full (1000 messages) console logger could start blocking the application.

private const int _maxQueuedMessages = 1024;
private readonly BlockingCollection<LogMessageEntry> _messageQueue = new BlockingCollection<LogMessageEntry>(_maxQueuedMessages);

To improve this design, we could consider using a Channel rather than a blocking collection (refer to https://devblogs.microsoft.com/dotnet/an-introduction-to-system-threading-channels/). This would prevent something that would either block the app due to increased latency or cause out of memory exception.

With upside with the current blocking collection approach is that the order of logs gets respected but since the logging methods can be accompanied with timestamp, the channel approach may still be an improved approach overall to help with the goal of having a console logger that is performant enough for real world applications.

Metadata

Metadata

Assignees

No one assigned

    Labels

    api-approvedAPI was approved in API review, it can be implementedarea-Extensions-LoggingenhancementProduct code improvement that does NOT require public API changes/additions

    Type

    No type

    Projects

    No projects

    Milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions