[BUG] ECS Serilog: Bad performance with default configuration
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:
- Create a simple service with minimal configuration of a console sink using ECS format.
- Time writing 1000 log lines
- 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;
}
}