Extensions: Resolving from D.I. is "slow"

[ajcvickers]

Moving this here as a perf issue in D.I. per @divega's request.

Original issue https://github.com/aspnet/EntityFrameworkCore/issues/12031 filed by @suchoss

Hello, it seems to me that performance of injected EF inside scoped service is really low.

There is a high chance that I am using EF incorrectly in this case, but I have not been able to find proper description/documentation how to use EF in this case (Inject it into custom hosted service).

In EasyRabbit/startup.cs (ConfigureServices) are registered following services:
```c#
// db
services.AddDbContext(options =>
{
options.UseSqlServer("Server=localhost; Database=RabbitTest; MultipleActiveResultSets=true; User ID=sa; Password=Admin1234");
});

// default REST Api
services.AddMvc();
// Configuration for Rabbit connector
services.Configure(Configuration.GetSection("RabbitConfig"));
// Rabbit Connector
services.AddSingleton();
// Subscriber which listens if some new message arrives
services.AddSingleton>();

// Every arival message is then processed in following scope
// ApplicationDbContext dbContext is injected into this RabbitSubscribers.Adder
services.AddScoped, RabbitSubscribers.Adder>();

Now if I understand it correctly, it should automatically create db context scope for every new RabbitSubscribers.Adder scope.

Problem is that like this it can consume/process only about 50 messages per second on average.

When I comment all operations with db (AddAsync and SaveChangesAsync) from following code, then it can process about 2000 messages per second which is nice but without db useless for me :(
```c#
namespace EasyRabbit.RabbitSubscribers
{
    public class Adder : IScopedProcessingService<CalculatorInputs>
    {
        private ILogger<Adder> _logger;
        private ApplicationDbContext _db;

        public Adder(ApplicationDbContext dbContext, ILogger<Adder> logger)
        {
            _logger = logger;
            _db = dbContext;

        }

        public async Task HandleMessageAsync(CalculatorInputs message)
        {

            Console.WriteLine($"Calculator: [{message.FirstNumber}] + [{message.SecondNumber}] = {message.FirstNumber + message.SecondNumber}");
            await _db.Calculations.AddAsync(new Calculation()
            {
                FirstNumber = message.FirstNumber,
                SecondNumber = message.SecondNumber,
                Result = message.FirstNumber + message.SecondNumber
            });

            await _db.SaveChangesAsync();

        }
    }
}

When I tried to replace EF with System.Data.SqlClient (following piece of code directly used in Adder.cs), then it could process 1100 messages per second on average. But to work with DB like this is really unconvinient :-/
```c#
public static class DB
{
private static string _connectionString = "Server=localhost; Database=RabbitTest; MultipleActiveResultSets=true; User ID=sa; Password=Admin1234";

public static void AddRecord(MyDBObject myDBObject)
{
    using (SqlConnection con = new SqlConnection(_connectionString))
    {
        using (SqlCommand cmd = new SqlCommand("insert into test (FirstNumber, SecondNumber, Result) values (@FirstNumber, @SecondNumber, @Result)", con))
        {
            cmd.CommandType = CommandType.Text;
            cmd.Parameters.AddWithValue("@FirstNumber", myDBObject.FirstNumber);
            cmd.Parameters.AddWithValue("@SecondNumber", myDBObject.SecondNumber);
            cmd.Parameters.AddWithValue("@Result", myDBObject.Result);
            con.Open();
            cmd.ExecuteNonQuery();
            con.Close();
        }

    }
}

}

public class MyDBObject
{
public int FirstNumber { get; set; }
public int SecondNumber { get; set; }
public int Result { get; set; }
}

```

Thanks.

Steps to reproduce

1. Clone current repository from: https://github.com/suchoss/uServiceChasis
2. Install RabbitMQ from: https://www.rabbitmq.com/#getstarted
3. Install MSSQL
4. Change connector to DB in EasyRabbit/startup.cs (line 31)
5. Go to folder RandomNumberPairGenerator and run command dotnet run for a few seconds, then you can cancel it with ctrl+c (it creates some messages into RabbitMQ queue)
6. Run EasyRabbit project and watch how many messages per second is being processed
   *. If you have RabbitMQ management installed you can watch performance on http://localhost:15672 (default login: guest; password: guest)

Further technical details

EF Core version: EF Core 2.0.2
Database Provider: Microsoft.EntityFrameworkCore.SqlServer
Operating system: Win 10
IDE: Visual Studio 2017 15.7.1

[ajcvickers]

Comment by @ajcvickers:

@suchoss What happens if you replace the ADO AddRecord with something like:
```C#
using (var context = new ApplicationDbContext(new DbContextOptionsBuilder().UseSqlServer(_connectionString).Options)
{
await _db.Calculations.AddAsync(new Calculation()
{
FirstNumber = myDBObject.FirstNumber,
SecondNumber = myDBObject.SecondNumber,
Result = myDBObject.FirstNumber + myDBObject.SecondNumber
});

await _db.SaveChangesAsync();

}
```
This should have similar performance to your code that resolves from the service provider, so it should give some idea whether it is something in EF or service resolution that is the root cause.

Also, it's interesting that your ADO.NET code doesn't use async, while your EF code does. What happens to your numbers if you make them both async or both sync?

[ajcvickers]

Comment by @suchoss

@ajcvickers Here are current measured performances:

1. EF async inside adder.cs - 230/s
2. EF without async inside adder.cs - 100/s
3. ADO.NET async - 1300/s
4. ADO.NET without async - 150/s
5. EF injected context async - 40/s
6. EF injected context without async - 65/s

scenarios 1.,2.,3.,4. have adder.cs as a singleton
scenarios 5.,6. they have adder.cs as a scoped service

Sorry, I was tired yesterday and that measured number with ado.net belonged to async version. I posted incorrect piece of code with sync version here.

I hope it helps. Thanks

[ajcvickers]

Comment by @ajcvickers

@suchoss Which of the results above correspond to the code I posted? Also, have you considered using DbContext pooling?

Assigning to @divega as per triage.

[ajcvickers]

Comment by @suchoss

@ajcvickers It was the first one (EF async inside adder-cs) - 230 messages/sec.

I didn't consider DbContext pooling, because I have never heard of it. I will try it and let you know about results.

[ajcvickers]

Comment by @suchoss

Update:

1. EF injected context async + with Db context pooling - 150/s
2. EF injected context without async + with Db context pooling - 73/s

[ajcvickers]

Comment by @ajcvickers

@suchoss can you provide a simple runnable project/solution or complete code listing that demonstrates the behavior you are seeing?

[ajcvickers]

Comment by @ajcvickers

EF Team Triage: Closing this issue as the requested additional details have not been provided and we have been unable to reproduce it.

BTW this is a canned response and may have info or details that do not directly apply to this particular issue. While we'd like to spend the time to uniquely address every incoming issue, we get a lot traffic on the EF projects and that is not practical. To ensure we maximize the time we have to work on fixing bugs, implementing new features, etc. we use canned responses for common triage decisions.

[ajcvickers]

Comment by @suchoss

Guys, @ajcvickers, I was on vacation and therefore I couldn't respond in time - sorry. BTW there are links to source codes in steps to reproduce (in my first post here), you can follow them. If those steps are hard to follow, I am going to send you classic MVC example, which should be simpler.

[ajcvickers]

Comment by @ajcvickers

@suchoss No problem. We will re-open as needed.

[ajcvickers]

Comment by @suchoss

Hello @ajcvickers,

So today, I've created following three projects:
1) DependencyInjection - EF DbContext (ModelContext) is injected into controller through ctor
2) DirectAproach - EF DbContext is created direcly in controller with using block
3) MeasureApp - app which measures performance of both solutions

Steps to reproduce:

1. Download zip file from attachment
2. Install MSSQL server on localhost so you can connect with following connection string:
   "Server=localhost; Database=DIApproach; MultipleActiveResultSets=true; User ID=sa; Password=Admin1234"
   or change connection string accordingly in Startup.cs (DependencyInjection project) and in ModelContext.cs (DirectAproach project)
3. Run following command in DependencyInjection and DirectAproach project folders:
   dotnet ef database update
4. In both folders from step 3. run this command dotnet run
5. Wait until both apps start.
6. Go to the folder MeasureApp and run command dotnet run
7. Be patient - on my laptop it takes about 2 minutes until test ends.

Conclusion:

If you are successful with running test you should see following results - of course that on different hw those times are going to be different - (measured 10x):
Time: 00:00:51.5376170, url: http://localhost:5000/api/DI
Time: 00:00:46.4245608, url: http://localhost:5001/api/Direct
Time: 00:00:50.6788257, url: http://localhost:5000/api/DI
Time: 00:00:46.3511890, url: http://localhost:5001/api/Direct
Time: 00:00:52.3130819, url: http://localhost:5000/api/DI
Time: 00:00:47.1922426, url: http://localhost:5001/api/Direct
Time: 00:00:52.1807489, url: http://localhost:5000/api/DI
Time: 00:00:46.9598238, url: http://localhost:5001/api/Direct
Time: 00:00:50.8818136, url: http://localhost:5000/api/DI
Time: 00:00:45.2605405, url: http://localhost:5001/api/Direct
Time: 00:00:50.7522685, url: http://localhost:5000/api/DI
Time: 00:00:46.5828745, url: http://localhost:5001/api/Direct
Time: 00:00:51.2286150, url: http://localhost:5000/api/DI
Time: 00:00:47.3935218, url: http://localhost:5001/api/Direct
Time: 00:00:51.2117850, url: http://localhost:5000/api/DI
Time: 00:00:46.2748000, url: http://localhost:5001/api/Direct
Time: 00:00:51.4667565, url: http://localhost:5000/api/DI
Time: 00:00:45.4717610, url: http://localhost:5001/api/Direct
Time: 00:00:50.6048048, url: http://localhost:5000/api/DI
Time: 00:00:46.0667616, url: http://localhost:5001/api/Direct

From those numbers you can see that injected EF db context is on average about 9 % slower.

_This behaviour is getting even worse when used as described in my first post, but now I also noticed that it was maybe caused by "busy" hard drive (because of RabbitMQ). I'll try to verify that on some server machine (maybe next week), but meantime you can test scenario from this test if that reproduces even on your computers._
EFCoreIssue.zip

[davidfowl]

cc @pakrym FYI

[pakrym]

Not sure how I can help here. When replacing SqlServer database with InMemory I see the following results:

Time: 00:00:01.9909359, url: http://localhost:5000/api/DI
Time: 00:00:01.9428765, url: http://localhost:5001/api/Direct
Time: 00:00:02.0134510, url: http://localhost:5000/api/DI
Time: 00:00:01.9518071, url: http://localhost:5001/api/Direct
Time: 00:00:01.9790054, url: http://localhost:5000/api/DI
Time: 00:00:01.9603970, url: http://localhost:5001/api/Direct
Time: 00:00:02.0877762, url: http://localhost:5000/api/DI
Time: 00:00:01.9481849, url: http://localhost:5001/api/Direct
Time: 00:00:02.0307855, url: http://localhost:5000/api/DI
Time: 00:00:01.9531731, url: http://localhost:5001/api/Direct
Time: 00:00:02.0373713, url: http://localhost:5000/api/DI
Time: 00:00:01.9516358, url: http://localhost:5001/api/Direct
Time: 00:00:01.9781963, url: http://localhost:5000/api/DI
Time: 00:00:01.9652488, url: http://localhost:5001/api/Direct
Time: 00:00:01.9607650, url: http://localhost:5000/api/DI
Time: 00:00:01.9661921, url: http://localhost:5001/api/Direct

While "Direct" app is marginaly faster it's hard to approach this from "DI perf" point of view considering that benchmark is going through kestrel and mvc.

Furthermore, stripping benchmark apps to just:

            var serviceCollection = new ServiceCollection();
            serviceCollection.AddDbContext<ModelContext>(options =>
            {
                options.UseInMemoryDatabase(databaseName: "Add_writes_to_database");
            });
            var provider = serviceCollection.BuildServiceProvider();


            while (true)
            {
                Stopwatch stopWatch = new Stopwatch();

                stopWatch.Start();
                for (int i = 1; i < 10000; i++)
                {
                    using (var scope = provider.CreateScope())
                    {
                        var context = scope.ServiceProvider.GetService<ModelContext>();
                        {
                            Model model = new Model
                            {
                                X = 10,
                                Y = 20
                            };

                            context.Models.Add(model);
                            await context.SaveChangesAsync();
                        }
                    }
                }
                stopWatch.Stop();
                Console.WriteLine($"Time: {stopWatch.Elapsed} ");
          }

vs

            while (true)
            {
                Stopwatch stopWatch = new Stopwatch();

                stopWatch.Start();

                for (int i = 1; i < 10000; i++)
                {
                    using (var context = new ModelContext())
                    {
                        Model model = new Model
                        {
                            X = 10,
                            Y = 20
                        };

                        context.Models.Add(model);
                        await context.SaveChangesAsync();
                    }
                }
                stopWatch.Stop();
                Console.WriteLine($"Time: {stopWatch.Elapsed} ");
            }

I see even less difference:

Direct:

Time: 00:00:01.0901820
Time: 00:00:01.0431759
Time: 00:00:01.0462424
Time: 00:00:01.0323271
Time: 00:00:01.0549598
Time: 00:00:01.0439363
Time: 00:00:01.1199594
Time: 00:00:01.0487160
Time: 00:00:01.0413827
Time: 00:00:01.0485116
Time: 00:00:01.0365241
Time: 00:00:01.0952443
Time: 00:00:01.0886210
Time: 00:00:01.0637605
Time: 00:00:01.0613307
Time: 00:00:01.0380819
Time: 00:00:01.0451049
Time: 00:00:01.0318099
Time: 00:00:01.0657039
Time: 00:00:01.0372602
Time: 00:00:01.0374092

DI:

Time: 00:00:01.0968038
Time: 00:00:01.0660226
Time: 00:00:01.0681282
Time: 00:00:01.0729982
Time: 00:00:01.0726489
Time: 00:00:01.0573266
Time: 00:00:01.0643667
Time: 00:00:01.0741961
Time: 00:00:01.1785892
Time: 00:00:01.0871636
Time: 00:00:01.1239346
Time: 00:00:01.0686572
Time: 00:00:01.0681543
Time: 00:00:01.0744735
Time: 00:00:01.0654194
Time: 00:00:01.0853768
Time: 00:00:01.0601371
Time: 00:00:01.0796546
Time: 00:00:01.0619978
Time: 00:00:01.0721345
Time: 00:00:01.0698267
Time: 00:00:01.0841208
Time: 00:00:01.0767723
Time: 00:00:01.0804655

[muratg]

@ajcvickers @divega do you have further expectations here? If this is a big issue we can try to shuffle some other work off of 3.0 and look into this.

[ajcvickers]

@muratg I'll leave Diego to comment--I'm pretty sure we moved this here per his request.

[divega]

@muratg I had no specific expectations on this.

The 9% difference mentioned at https://github.com/aspnet/Extensions/issues/691#issuecomment-410825384 just made me wonder if there was a perf issue in DI worth looking at.

@pakrym's analysis indicates that the difference when you look at DI vs constructor in isolation is minimal. It seems ok to then conclude that it is not because of a perf issue in DI.

However, I don't think we have been able to explain why the difference becomes more noticeable when there are other components interacting. Not to mention the more significant differences mentioned in https://github.com/aspnet/Extensions/issues/691#issuecomment-410824355:

1. EF async inside adder.cs - 230/s
2. EF without async inside adder.cs - 100/s
3. ADO.NET async - 1300/s
4. ADO.NET without async - 150/s
5. EF injected context async - 40/s
6. EF injected context without async - 65/s

Of course, any differences between ADO.NET and EF Core are not likely attributable to DI.

[muratg]

Thanks @divega. I don't expect we'll get much time to investigate this further, so in the name of cleaning up the issue backlog, I'll close this. If we hear more from customers about this or related issues, let's bring back the discussion.