3

Could anyone explain why there is a huge time execution time between the console application, which takes less than a second to execute, and the API takes minutes. Is it possible to improve ?

I am using .NET 7

Web app

var builder = WebApplication.CreateBuilder(args);

var cnn = new SqliteConnection("Data Source=EmployeeCacheStore;Mode=Memory;Cache=Shared");
cnn.Open();

builder.Services.AddDbContext<DataContext>(options => options.UseSqlite(cnn));

var app = builder.Build();

app.MapGet("/weatherforecast", (DataContext context1) =>
{
    var time = Stopwatch.GetTimestamp();
    context1.ChangeTracker.QueryTrackingBehavior = QueryTrackingBehavior.NoTracking;
    context1.ChangeTracker.AutoDetectChangesEnabled = false;

    var list = Enumerable.Range(1, 8000).Select(x => new Record() { Id = x }).ToList();
    context1.Record.AddRange(list);
    context1.SaveChanges();

    return $"Executed in: {Stopwatch.GetElapsedTime(time)}";
}).WithName("GetWeatherForecast");

app.Run();

Console:

var conn = new SqliteConnection("Data Source=EmployeeCacheStore;Mode=Memory;Cache=Shared");
conn.Open(); 
var options = new DbContextOptionsBuilder<DataContext>().UseSqlite(conn).Options;

using (var ctx = new DataContext(options))
{
    var time = Stopwatch.GetTimestamp();
    ctx.ChangeTracker.QueryTrackingBehavior = QueryTrackingBehavior.NoTracking;
    ctx.ChangeTracker.AutoDetectChangesEnabled = false;
    var list = Enumerable.Range(1, 8000).Select(x => new Record() { Id = x }).ToList();
    ctx.Records.AddRange(list);
    ctx.SaveChanges();

    Console.WriteLine("Executed in: {0}", Stopwatch.GetElapsedTime(time));
}

Context:

public class Record
{
    public int Id { get; set; }
    public string? Name { get; set; }
}

public class DataContext : DbContext
{
    public DbSet<Record> Records { get; set; }

    public DataContext(DbContextOptions options) : base(options)
    {
        Database.EnsureCreated();
    }
}
Guru Stron
  • 102,774
  • 10
  • 95
  • 132
Zulander
  • 648
  • 1
  • 10
  • 22
  • In which order are you running the tests? Web -> Console, or Console -> Web? Are you completely destroying the DB between tests, or are you using TRUNCATE or DELETE [TABLE]? Are the EF generated queries the same? Are the query execution plans the same? These are some of the questions running through my head. – Adam Vincent Aug 30 '23 at 13:55
  • I ran them both in two different projects (one after the other), it's memory db so no need to truncate/delete, and it's just an insert. No, I am not "completely destroying" It's only 8k insert – Zulander Aug 30 '23 at 14:04

2 Answers2

3

The reason is that EF Core when run inside ASP.NET Core project by default hooks up to the Microsoft.Extensions.Logging infrastructure:

Microsoft.Extensions.Logging is an extensible logging mechanism with plug-in providers for many common logging systems. EF Core fully integrates with Microsoft.Extensions.Logging and this form of logging is used by default for ASP.NET Core applications.

Which results in 8000 messages written to the console/debug in default setup which obviously slows the processing. You can disable logging in EF Core, for example via config (see also this answer):

{
  "Logging": {
    "LogLevel": {
      "Default": "Information",
      "Microsoft.AspNetCore": "Warning",
      "Microsoft.EntityFrameworkCore": "None"
    }
  }
}

Or clearing logger factory:

builder.Services.AddDbContext<DataContext>(options => options.UseSqlite(cnn)
    .UseLoggerFactory(new NullLoggerFactory()));
Guru Stron
  • 102,774
  • 10
  • 95
  • 132
2

DEBUG:

  • Web: Executed in: 00:00:10.0011561
  • Console: Executed in: 00:00:00.4682114

In more recent versions of .NET / EF Core, (.NET 6+) EF Logging is configured by default when calling AddDbContext or AddDbContextPool.

The reason it takes 10 seconds to execute in debug mode because that's how long it takes to write ~24k lines of logging to the console during the execution.

Initially I thought the Console logging provider.
Turns out most of the performance impact is coming from the Debug logging provider. This is provider only works when the debugger is attached, so when you run it in release mode, the execution is significantly faster.

You can visualize this by removing logging:

// this effectively removes all logging providers that were added
// by WebApplication.CreateBuilder();
// making this the same logging setup as the console app.
builder.Logging.ClearProviders();

//builder.Logging.AddConsole(); //uncomment to get log output to the console.
//builder.Logging.AddDebug(); //uncomment to get debug logs while attached to the debugger.  Most performance impact, in this scenario, is here.


//output:
//Web: Executed in: 00:00:00.3051866
//Web (With Console logging): Executed in: 00:00:00.5858375
//Web (With Debug logging): Executed in: 00:00:11.6470355
//Web (With both console and debug): Executed in: 00:00:11.6980340

This is not a preferred method for controlling logging for EF Core.

First: You can control the logging level by configuring the log levels in appsettings.json and appsettings.{Environment}.json configuration files.

Second: You can control the logger provider (as pointed out by @Guru Stron) by configuring the options in the context.

builder.Services.AddDbContext<DataContext>(options => options.UseSqlite(cnn)
    .UseLoggerFactory(new NullLoggerFactory()));

RELEASE:

  • Web: Executed in: 00:00:00.5546975
  • Console: Executed in: 00:00:00.2601217
Adam Vincent
  • 3,281
  • 14
  • 38