ecs-dotnet icon indicating copy to clipboard operation
ecs-dotnet copied to clipboard

[BUG] ECS Serilog: Bad performance with default configuration

Open MrVinkel opened this issue 3 years ago • 0 comments

ECS integration/library project(s) (e.g. Elastic.CommonSchema.Serilog): Elastic.CommonSchema.Serilog

ECS schema version (e.g. 1.4.0): latest

ECS .NET assembly version (e.g. 1.4.2): 1.6.0-alpha1

Elasticsearch version (if applicable): N/A

.NET framework / OS: .NET 6.0 Windows 10

Description of the problem, including expected versus actual behavior:

When using default configuration for setting up a console sink using ECS format, it is only possible to write ~100 logs lines a second. Setting EcsTextFormatterConfiguration.MapCurrentThread(false); increases performance more than tenfold to far over 1000 log lines a second.

I looked through the code and it seems it is because the 'TryGetProcess' call is extremely slow in https://github.com/elastic/ecs-dotnet/blob/main/src/Elastic.CommonSchema.Serilog/LogEventConverter.cs#L294. Setting MapCurrentThread to false avoids making this call, but does not map the process information.

It can be solved easily by caching the process ID, name and executable instead of looking it up on every log event.

Steps to reproduce:

  1. Create a simple service with minimal configuration of a console sink using ECS format.
  2. Time writing 1000 log lines
  3. Time writing 1000 log lines with EcsTextFormatterConfiguration.MapCurrentThread(false);
using Elastic.CommonSchema.Serilog;
using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Hosting;
using Microsoft.Extensions.Logging;
using Serilog;
using System.Diagnostics;

IHostBuilder builder = new HostBuilder();
builder.ConfigureServices(services =>
{
    services.AddHostedService<MyService>();
});
builder.UseSerilog((hostingContext, services, loggerConfiguration) =>
{
    var formatterConfig = new EcsTextFormatterConfiguration();
    // Changing 'MapCurrentThread' to false increases performance tenfold
    // formatterConfig.MapCurrentThread(false);
    loggerConfiguration.MinimumLevel.Information()
        .WriteTo.Console(new EcsTextFormatter(formatterConfig));
});
var app = builder.Build();
await app.RunAsync();


public class MyService : IHostedService
{
    private readonly ILogger<MyService> logger;

    public MyService(ILogger<MyService> logger)
    {
        this.logger = logger;
    }

    public Task StartAsync(CancellationToken cancellationToken)
    {
        var stopWatch = new Stopwatch();
        stopWatch.Start();
        for (int i = 0; i < 1000; i++)
        {
            logger.LogInformation("Log message number {i}", i);
        }
        stopWatch.Stop();
        var duration = stopWatch.Elapsed;
        var logDuration = string.Format("Duration: {0:00}:{1:00}:{2:00}.{3:00}", duration.Hours, duration.Minutes, duration.Seconds, duration.Milliseconds / 10);
        logger.LogInformation(logDuration);
        return Task.CompletedTask;
    }

    public Task StopAsync(CancellationToken cancellationToken)
    {
        return Task.CompletedTask;
    }
}

MrVinkel avatar Oct 10 '22 12:10 MrVinkel