LoggerMessage.Define vs. LogCritical

compare-perf.md

Overview:

We are comparing two different scenarios where logging will be noop (as it is not enabled). In one case, we have no logging providers, and in the other one we have console logger.

onlyconsole-warning-10000-define:

                    .ClearProviders()
                    .AddConsole()
                    .SetMinimumLevel(LogLevel.Critical));

clearproviders-warning-10000-define:

                    .ClearProviders()
                    .SetMinimumLevel(LogLevel.Critical));

and call to

                    for (int i = 0; i < 1000; i++)
                        _loggerMessage2(logger, ConnectionId, Start, End, Options, null);

where

        private static Action<ILogger, string, long, long, int, Exception?> _loggerMessage2 = LoggerMessage.Define<string, long, long, int>(LogLevel.Warning,
                            eventId: 381,
                            formatString: @"Connection id '{connectionId}', range [{start}..{end}], options {options}");

C:\CodeHub\Benchmarks\src\BenchmarksApps\Samples\Template>crank compare onlyconsole-consume-define-10000.json clearproviders-consume-define-10000.json

| application                   | onlyconsole-warning-10000-define | clearproviders-warning-10000-define |         |
| ----------------------------- | -------------------------------- | ----------------------------------- | ------- |
| CPU Usage (%)                 |                               98 |                                  98 |   0.00% |
| Cores usage (%)               |                            2,752 |                               2,747 |  -0.18% |
| Working Set (MB)              |                              360 |                                 211 | -41.39% |
| Private Memory (MB)           |                              443 |                                 296 | -33.18% |
| Build Time (ms)               |                            4,934 |                               2,815 | -42.95% |
| Start Time (ms)               |                              298 |                                 289 |  -3.02% |
| Published Size (KB)           |                           85,222 |                              85,483 |  +0.31% |
| .NET Core SDK Version         |        6.0.100-preview.4.21179.9 |           6.0.100-preview.4.21179.9 |         |
| Max CPU Usage (%)             |                              106 |                                 105 |  -0.94% |
| Max Working Set (MB)          |                              379 |                                 220 | -41.95% |
| Max GC Heap Size (MB)         |                              288 |                                 172 | -40.28% |
| Max Number of Gen 0 GCs / sec |                             1.00 |                                0.00 |         |
| Max Number of Gen 1 GCs / sec |                             1.00 |                                0.00 |         |
| Max Number of Gen 2 GCs / sec |                             0.00 |                                0.00 |         |
| Max Time in GC (%)            |                             0.00 |                                0.00 |         |
| Max Gen 0 Size (B)            |                              672 |                                   0 |         |
| Max Gen 1 Size (B)            |                        5,562,320 |                                   0 |         |
| Max Gen 2 Size (B)            |                        5,448,560 |                                   0 |         |
| Max LOH Size (B)              |                          314,728 |                                   0 |         |
| Max Allocation Rate (B/sec)   |                      105,806,368 |                          20,870,136 | -80.28% |
| Max GC Heap Fragmentation     |                                1 |                                   0 |         |
| # of Assemblies Loaded        |                               87 |                                  85 |  -2.30% |
| Max Exceptions (#/s)          |                            1,434 |                               1,434 |   0.00% |
| Max Lock Contention (#/s)     |                               15 |                                  15 |   0.00% |
| Max ThreadPool Threads Count  |                               76 |                                  76 |   0.00% |
| Max ThreadPool Queue Length   |                              302 |                                 268 | -11.26% |
| Max ThreadPool Items (#/s)    |                          218,277 |                             251,768 | +15.34% |
| Max Active Timers             |                                0 |                                   0 |         |
| IL Jitted (B)                 |                          145,492 |                             137,515 |  -5.48% |
| Methods Jitted                |                            1,607 |                               1,486 |  -7.53% |


| load                   | onlyconsole-warning-define-10000 | clearproviders-warning-define-10000 |         |
| ---------------------- | -------------------------------- | ----------------------------------- | ------- |
| CPU Usage (%)          |                               13 |                                  16 | +23.08% |
| Cores usage (%)        |                              368 |                                 451 | +22.55% |
| Working Set (MB)       |                                7 |                                   7 |   0.00% |
| Private Memory (MB)    |                              363 |                                 363 |   0.00% |
| Start Time (ms)        |                                0 |                                   0 |         |
| First Request (ms)     |                              100 |                                 101 |  +1.00% |
| Requests/sec           |                           82,453 |                              99,533 | +20.71% |
| Requests               |                          832,767 |                           1,005,279 | +20.72% |
| Mean latency (ms)      |                             8.55 |                               10.63 | +24.33% |
| Max latency (ms)       |                           405.49 |                              360.58 | -11.08% |
| Bad responses          |                                0 |                                   0 |         |
| Socket errors          |                                0 |                                   0 |         |
| Read throughput (MB/s) |                             7.23 |                                8.73 | +20.75% |
| Latency 50th (ms)      |                             5.84 |                                4.86 | -16.78% |
| Latency 75th (ms)      |                             6.26 |                                5.28 | -15.65% |
| Latency 90th (ms)      |                             8.31 |                                7.10 | -14.56% |
| Latency 99th (ms)      |                           100.54 |                              153.53 | +52.71% |

The benchmarks were created using https://github.com/aspnet/Benchmarks/tree/main/src/BenchmarksApps/Samples/Template

by changing Startup.cs to:

using System;
using System.Collections.Generic;
using System.Runtime.CompilerServices;
using System.Threading.Tasks;
using Microsoft.AspNetCore.Builder;
using Microsoft.AspNetCore.Hosting;
using Microsoft.AspNetCore.Routing;
using Microsoft.Extensions.Configuration;
using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.DependencyInjection.Extensions;
using Microsoft.Extensions.Logging;

namespace Template
{
    public class Startup
    {
        public Startup(IConfiguration configuration) => Configuration = configuration;

        public IConfiguration Configuration { get; }

        // This method gets called by the runtime. Use this method to add services to the container.
        public void ConfigureServices(IServiceCollection services)
        {
        }

        // This method gets called by the runtime. Use this method to configure the HTTP request pipeline.
        public void Configure(IApplicationBuilder app, IWebHostEnvironment env,
            ILogger<Startup> logger)
        {
            app.UseRouting();

            app.UseEndpoints(routeBuilder =>
            {
                routeBuilder.Map("InvariantCultureIgnoreCase/{count}", context =>
                {
                    Consume(logger);
                    return Task.CompletedTask;
                });
            });
        }

        // avoid possible dead code elimination
        [MethodImpl(MethodImplOptions.NoInlining)]
        private static void Consume(in ILogger logger)
        {
                    // for (int i = 0; i < 1000; i++)
                    // {
                    //     logger.LogDebug("try logging");
                    // }

            for (int i = 0; i < 10000; i++)
                _loggerMessage2(logger, ConnectionId, Start, End, Options, null);
        }

        private static Action<ILogger, string, long, long, int, Exception?> _loggerMessage2 = LoggerMessage.Define<string, long, long, int>(LogLevel.Warning,
                            eventId: 381,
                            formatString: @"Connection id '{connectionId}', range [{start}..{end}], options {options}");
                            
        private const string ConnectionId = "0x345334534678";
        private const long Start = 42;
        private const long End = 123456789;
        private const int Options = 0x1234;
    }
}

Crank command used:

> crank --config .\sample.yml --scenario sample --profile aspnet-citrine-win --application.framework net6.0 --variable warmup=0 --variable duration=10 --chart --application.options.collectCounters true --application.dotnetTrace true --output onlyconsole-warning-1000-define.json

> crank compare onlyconsole-warning-1000-define.json clearproviders-warning-1000-define.json

My only concern is that most of our users dont log 1000 messages per request and most probably the input is also changing over time.

My current best idea is to just try to log some details about the request: start time, connection id, user name, path etc. Sth like this:

// This method gets called by the runtime. Use this method to configure the HTTP request pipeline.
public void Configure(IApplicationBuilder app, IWebHostEnvironment env, ILogger<Startup> logger)
{
    app.UseRouting();

    app.UseEndpoints(routeBuilder =>
    {
        routeBuilder.Map("LoggingBenchmark/{count}", context =>
        {
            // I would make it more similar to what the end-users might be doing
            // and just log some info related to the current web request:
            _logTime(Enum.Start, DateTime.UtcNow, context.Connection.Id);

            _logRequestDetails(context.Request.Path, context.Request.Method, context.Request.ContentLength);

            _logUserName(context.User.Identity?.Name, context.User.Identity?.IsAuthenticated);

            _logTime(Enum.End, DateTime.UtcNow, context.Connection.Id);

            return Task.CompletedTask;
        });
    });
}