Create lazy-loading and change-tracking proxy types lazily

henrikdahl8240 commented 4 years ago

I have made this simple function:

private void buttonRoot_Click(object sender, EventArgs e)
{
    DateTime start = DateTime.Now;
    using (BikeShop_DbContext dbContext = new BikeShop_DbContext(new DbContextOptionsBuilder<BikeShop_DbContext>()
        //.UseLazyLoadingProxies()
        .UseSqlServer(@"data source=.;initial catalog=BikeShop;integrated security=True;MultipleActiveResultSets=True", opts => opts.CommandTimeout((int)TimeSpan.FromMinutes(10).TotalSeconds)).Options))
    {
        var root = dbContext.Roots.First();
        DateTime finish = DateTime.Now;
        MessageBox.Show(this, $"root.ID: {root.ID}.\n Start: {start}\nFinish: {finish}\nDuration: {finish - start}", "Root ID");
    }
}

On my machine, it takes 4:18 to execute, i.e. four minutes and 18 seconds.

It is important to notice, that I have commented out the invocation of .UseLazyLoadingProxies(). I obviously need these proxies, so it's just to compare.

So now I uncomment .UseLazyLoadingProxies() so it will also be run, i.e.:

private void buttonRoot_Click(object sender, EventArgs e)
{
    DateTime start = DateTime.Now;
    using (BikeShop_DbContext dbContext = new BikeShop_DbContext(new DbContextOptionsBuilder<BikeShop_DbContext>()
        .UseLazyLoadingProxies()
        .UseSqlServer(@"data source=.;initial catalog=BikeShop;integrated security=True;MultipleActiveResultSets=True", opts => opts.CommandTimeout((int)TimeSpan.FromMinutes(10).TotalSeconds)).Options))
    {
        var root = dbContext.Roots.First();
        DateTime finish = DateTime.Now;
        MessageBox.Show(this, $"root.ID: {root.ID}.\n Start: {start}\nFinish: {finish}\nDuration: {finish - start}", "Root ID");
    }
}

Now it takes 34:42 to execute, i.e. 34 minutes and 42 seconds. By simple subtraction, the invocation of .UseLazyLoadingProxies() adds approximately half an hour to the duration or makes initialization to take approximately 10 times longer time.

There was a lot of criticism on the initialization time in scope of EF 6. It seems like this gives exactly the same problem.

Can't you for instance lazy initialize or we could call it initialize on demand instead? Perhaps you have a better idea?

Do you agree, that it's a major problem, that use of your proxy feature forces initialization to take really long time?

I would like to mention, that I have in the magnitude of 4.000 entities in my model. Only one of these is being looked up by my small program example.

EF Core version: 3.1.2 Database provider: Microsoft.EntityFrameworkCore.SqlServer Target framework: NET Core 3.1 Operating system: Windows 10 Professional IDE: Visual Studio 2019 16.4.5.

ajcvickers commented 4 years ago

@henrikdahl8240 Can you attach your EF model (entity types and DbContext) so that we can investigate. This seems slower than expected even for 4000 entity types.

henrikdahl8240 commented 4 years ago

Can't you give a suggestion for how to do that without challenging the immaterial rights. Do you for example have a reference for a Roslyn project which anonymizes all names in all projects in a solution?

I would like to share the model, but I would like to do it without disclosing anything for real.

ErikEJ commented 4 years ago

@henrikdahl8240 You can run an obfuscator?

henrikdahl8240 commented 4 years ago

Yes, but I have never done that before. Can you suggest how to do that? Can I see the result myself? Is there one built-in in Visual Studio?

ErikEJ commented 4 years ago

https://docs.microsoft.com/en-us/visualstudio/ide/dotfuscator/?view=vs-2019 https://www.preemptive.com/dotfuscator/ce/docs/help/getting_started_gui.html

Then you can decompile the resulting dll and extract the relevant classes

henrikdahl8240 commented 4 years ago

Thank you very much, Erik. Do you also have a suggestion concerning the decompilation step?

ajcvickers commented 4 years ago

@henrikdahl8240 If you don't want to share it publicly, then you can send it to me directly and we will keep it private. avickers at microsoft.com

henrikdahl8240 commented 4 years ago

@ajcvickers It sounds excellent. I will put some efforts into that.

ErikEJ commented 4 years ago

I usually use dotPeek

henrikdahl8240 commented 4 years ago

OK. I will take a look. Thank you for the hints, @ErikEJ

henrikdahl8240 commented 4 years ago

@ajcvickers As you may see, I mailed you a soution on March 6. 2020 13:46. Perhaps you may run it to reproduce the problems yourself?

The mail details the few steps you should go through.

ajcvickers commented 4 years ago

@henrikdahl8240 Thanks--we got the code.

Note for team: I am able to reproduce this; culprit is model building but I haven't profiled to find out where. /cc @AndriySvyryd

Running the code below on my fast machine without lazy-loading proxies:

Creating model...
Done in 81904
Creating database...
Done in 113199
Running query...
Done in 124

With proxies:

Creating model...
Done in 701398
Creating database...
Done in 112623
Running query...
Done in 132

Model has 5,860 entity types with a total of 13,876 navigations.

EntityTypeConfigurations are already being used.

using (HenrikDahl_DbContext dbContext = new HenrikDahl_DbContext(new DbContextOptionsBuilder<HenrikDahl_DbCon
    .UseLazyLoadingProxies()
    .UseSqlServer(Your.SqlServerConnectionString, opts => opts.CommandTimeout((int)TimeSpan.FromMinutes(10).T
{
    Console.WriteLine("Creating model...");

    var timer = Stopwatch.StartNew();

    var model = dbContext.Model;
    timer.Stop();
    Console.WriteLine($"Done in {timer.ElapsedMilliseconds}");

    Console.WriteLine("Creating database...");

    timer = Stopwatch.StartNew();
    dbContext.Database.EnsureDeleted();
    dbContext.Database.EnsureCreated();
    timer.Stop();

    Console.WriteLine($"Done in {timer.ElapsedMilliseconds}");

    Console.WriteLine("Running query...");

    timer = Stopwatch.StartNew();
    var samoyed = dbContext.Samoyeds.FirstOrDefault();
    timer.Stop();

    Console.WriteLine($"Done in {timer.ElapsedMilliseconds}");
}

AndriySvyryd commented 4 years ago

It might be just the time it takes to create the proxy types

henrikdahl8240 commented 4 years ago

Shouldn't proxy types generally be created as they are needed and not up-frot, i.e. created lazy-wise? Perhaps it could be an option for UseLazyLoadingProxies whether the proxy classes should be created eager-wise or lazy-wise. Otherwise I guess it will always be a pain in situations with relatively many entity types. I assume that the requirement of using "virtual" for all collections and navigation properties enable this.

I would imagine, that EF Core should rather shine with many entity types than with few entity types. Probably many can figure out to make such ORM stuff if it only needs to perform well in situations with few entity types. I assume that all non-trivial enterprise solutions will have many, many entity types and it's here EF Core should shine, at least from my point of view.

ajcvickers commented 4 years ago

@AndriySvyryd Yes, but I think it would be good to understand where the time is being used even in the non-proxy model building.

ajcvickers commented 4 years ago

Notes from team triage:

We will investigate the model building perf to at least understand where the time is going without proxies
This issue will track lazy creation of proxy instances, but this won't make it in 5.0 since it requires changes to the way extensions interact with model building.

@henrikdahl8240

I assume that all non-trivial enterprise solutions will have many, many entity types

This number of entity types and relationships is at the high end of what we see. We have a long-term goal to pre-compile the model, which is ultimately the way to make this the most performant. That being said, the perf here is a lot slower than I expected, which is why we're investigating.

ErikEJ commented 4 years ago

@henrikdahl8240 Many modern enterprise solutions are based on micro services and a limited number of entity types managed by each micro service.

henrikdahl8240 commented 4 years ago

@ErikEJ How do you ensure domain level consistency in the situation you have on mind as you do not have the entire domain model in one database?

DeluxeAgency2020 commented 4 years ago

@AndriySvyryd, @ajcvickers Whats is the status of this issue. Is any workaround or suggestion? Will this issue be fixed in ef 5?

AndriySvyryd commented 4 years ago

@DeluxeAgency2020 We'll investigate this in 5.0 timeframe, but it's unlikely that any significant improvement will be made for 5.0 RTM

AndriySvyryd commented 4 years ago

Without proxies about 34% is spent in data annotation conventions and about 31% is spent in DerivedTypeDiscoveryConvention. It will be possible to disable these conventions once https://github.com/dotnet/efcore/issues/214 is implemented, provided the configuration is specified using Fluent API.

However most benefits would be provided by compiled model, eventually it can also include compiled proxies (https://github.com/dotnet/efcore/issues/24902).

cabal95 commented 3 years ago

I just wanted to note that we are also seeing this extremely slow performance when using .UseLazyLoadingProxies(). With lazy loading disabled time to first query results takes 6,000ms. When lazy loading is enabled, time to first query results takes 169,000ms. We are on .NET 5.0 and EF Core 5.0.

I saw this issue over on Castle.Core (which I believe is what EF uses for this feature): https://github.com/castleproject/Core/issues/486. The summary is that each call to create a new proxy causes the time taken to create that proxy to increase linearly. i.e. the first proxy created takes 100ms, second proxy takes 200ms, third proxy takes 300ms, etc. The project maintainer says this appears to be an issue in the core runtime, though it seems odd that (supposedly) creating a new ProxyGenerator solves the speed issue, though I'm not sure what those "bad performance/memory" issues referenced are by doing so.

In our case, we can't disable the lazy loading as we are passing the objects to a Liquid engine to let the user render out the content they want, and they often start accessing various navigation properties, including sub-navigation properties (e.g. {{ person.Family.GroupType.Name }}).

This is originally a WebForms EF 6 (classic) project that we are working on converting to EF Core so we don't have a stable EF Core branch but I can create a temporary branch with my WIP if that helps.

zeocrash commented 3 years ago

We have also had similar issues with performance on first query which I believe is to do with the lazy loading proxies.

We had a dbcontext with 28 entities mapped fluently all of which used TPH or TPT inheritance.

We found that on start up, the initial query on this dbcontext was taking approx. 14 seconds, which seems steep for a relatively small dbcontext.

Upon further inspection of the code I noticed that the developers who wrote it had made all the properties in the entity virtual, not just the navigation properties (Our dev team is migrating from NHibernate and in Nhibernate it's standard practice to make all entity properties virtual).

Upon making the non navigation properties non virtual we found the load time for the initial query to have dropped from 14 seconds down to about 3 seconds (which still seems steep but I'm putting that down to the 25 class discriminator in the mapping).

It seems to me that whatever the lazy loading proxies are doing they're not just processing navigation properties but any virtual property in the entity.

roji commented 3 years ago

Tested on 6.0.0-preview.7 without proxies:

29% of model building time is spent doing SortedDictionary.TryGetValue inside Annotatable.FindAnnotation, see #25488.
Another huge hotspot is Attribute.IsDefined, opened #25891 to track
Finally, turning on proxies shows the entire time spent in ProxyFactory.CreateProxyType. Castle.DynamicProxy has an internal caching mechanism so that it doesn't regenerate the proxy type for the same combination of CLR Type, interface list and ProxyGenerationOptions; as far as I can see we're not doing anything wrong, so this looks like pure proxy generation time which cannot be optimized away. We may have some opportunities for not generating proxies where they're not needed, opened #25892.
- Once crazy thought, is that in today's world these proxies could be generated at compile-time with source generators, I wonder if Castle or some other proxy generation package has this feature.

AndriySvyryd commented 3 years ago

Related to the last point: https://github.com/dotnet/efcore/issues/24902

ajcvickers commented 3 years ago

From https://github.com/dotnet/efcore/issues/20135#issuecomment-599256957

This issue will track lazy creation of proxy instances.

ajcvickers commented 2 years ago

Fixed in #28127.

Perf for model with 449 entity types, 6390 properties, and 720 relationships.

6.0

No proxies

Method	Mean	Error	StdDev
TimeToFirstQuery	1.085 s	0.0083 s	0.0167 s

Change tracking proxies

Method	Mean	Error	StdDev
TimeToFirstQuery	13.01 s	0.204 s	0.411 s

7.0

No proxies

Method	Mean	Error	StdDev
TimeToFirstQuery	1.442 s	0.0134 s	0.0272 s

Change tracking proxies

Method	Mean	Error	StdDev
TimeToFirstQuery	1.446 s	0.0160 s	0.0323 s

Change tracking proxies and compiled model

Method	Mean	Error	StdDev
TimeToFirstQuery	162.4 ms	6.16 ms	12.45 ms

See #24902.

Also, see #28129.

roji commented 2 years ago

Very nice!

dotnet / efcore