Performance Issue increases time between logs

[alvarovalle]

Performance Issue increases time between logs

using Serilog;
using Serilog.Sinks.SystemConsole.Themes;
using System;
using System.IO;
namespace serilog
{
    class Program
    {
        static void Main(string[] args)
        {
           Log.Logger = new LoggerConfiguration()
           .WriteTo.Console()
           .WriteTo.File("log.txt")
           .CreateLogger();
           DateTime start = DateTime.MinValue;
           DateTime end = DateTime.MinValue;
           double delta = 0.0;
           for(int x=0;x<=10;x++)
           {
              start = DateTime.Now;
              Log.Information($"SIMPLE TEXT");
              end = DateTime.Now;
              delta = end.Subtract(start).TotalMilliseconds;
              Console.WriteLine($"============> It takes [{delta}] to print SnapShot number {x}");
           }
           Log.CloseAndFlush();
        }
    }
}

<Project Sdk="Microsoft.NET.Sdk">
  <PropertyGroup>
     <OutputType>Exe</OutputType>
     <TargetFramework>netcoreapp3.1</TargetFramework>
   </PropertyGroup>
   <ItemGroup>
    <PackageReference Include="Serilog.Sinks.Async" Version="1.4.0" />
    <PackageReference Include="Serilog" Version="2.10.0-dev-01226" />
    <PackageReference Include="Serilog.Sinks.Console" Version="4.0.0-dev-00839" />
    <PackageReference Include="Serilog.Sinks.File" Version="5.0.0-dev-00887" />
  </ItemGroup>
 </Project>

All of a sudden time increases among log prints, I expect to see a decrease of duration due to warm up process, but it did not happen. instead, time increases and decresases at will in random.

what is happening here? why do I need to wait that long in order to print another log?
( by the way I am in a high performance delivery scenario, so each miliseccond worth a lot for me )

thank you in advance.

[rafaelsc]

I couldn't reproduce this problem in my machine.

This is the result of your code running in LinqPad in Release mode.

============> It takes [16.9535] to print SnapShot number 0
[10:27:13 INF] SIMPLE TEXT
============> It takes [0] to print SnapShot number 1
[10:27:13 INF] SIMPLE TEXT
============> It takes [0] to print SnapShot number 2
[10:27:13 INF] SIMPLE TEXT
============> It takes [0] to print SnapShot number 3
[10:27:13 INF] SIMPLE TEXT
============> It takes [0] to print SnapShot number 4
[10:27:13 INF] SIMPLE TEXT
============> It takes [0] to print SnapShot number 5
[10:27:13 INF] SIMPLE TEXT
============> It takes [0] to print SnapShot number 6
[10:27:13 INF] SIMPLE TEXT
============> It takes [0] to print SnapShot number 7
[10:27:13 INF] SIMPLE TEXT
============> It takes [0] to print SnapShot number 8
[10:27:13 INF] SIMPLE TEXT
============> It takes [0] to print SnapShot number 9
[10:27:13 INF] SIMPLE TEXT
============> It takes [0] to print SnapShot number 10

I think in your case is the Serilog.Sinks.File that is taking more time to flush the file in your harddisk.

Can you do more tests on your machine?

Testing with these scenarios:

• Without the File Sink,
• Enabling the Buffered mode in the File Sink,
• Using the Async Sink with the File Sink,
• Disable your Anti-virus,
• Save the file in your faster drive.