20

Closed

[Performance] EF6 startup performance issue (without debugger attached)

description

Note: We have create a separate item to track the performance issue with the debugger attached . Aside from this issue, there is still a performance regression without the debugger attached in this bug report that needs to be understood.

We are working on a new crm application using entity-framework and I am seriously scared if we will soon get to the point
where developing with EF gets highly unproductive because of the extremley poor startup performance.

We started using EF since the EF 6.0 Alpha1 release, and were on RC1 for some months now.
In the hope that startup performance has increased, I have updated the solution to EF 6.0.1 today.
Unfortunately startup performance is even worse than in RC1 and I am seriously concerned about that poor performance.

Let me share you some stats of our new application:

Current Status:

  • Currently we have about 55 Entities (Code first)
  • First Query Performance with attached debugger: ~ 10 seconds (EF 6 RC1)
  • First Query Performance without debugger: ~ 5 seconds (EF 6 RC1)
  • First Query Performance with attached debugger: ~ 15 seconds (EF 6.0.1)
  • First Query Performance without debugger: ~ 7 seconds (EF 6.0.1)
Hardware: DualCore 2.5 Ghz Core2, 4GB Ram

As you can see, every time a developer hits F5, we have to wait for about 10-15 seconds until the applications is usable.
That's pretty bad, even if the performance is currently still acceptable.

But this is only the beginning:

Planned Future Status:

The application is rapidly evolving at the moment, and If all parts are implemented, we are expecting to have about 200-300 entities in the final stage.
So this is my quick estimation of the apps expected final startup performance:
  • Expected final entities: 300
  • This is about 6 times more than now ...
  • ... expected first query performance with debugger: ~ 10*6 = 60 seconds (EF 6 RC1)
  • ... expected first query performance without debugger: 20-30 seconds (EF 6.0 RC1)
What do these numbers indicate:

If we continue using ef, every developer hitting (F5) will have to wait 1 minute until the app is usable.
That means, if the application is finally launched, the developer has probably forgotten what he wanted to do at all.
The end-user has to wait 30 seconds for the app to be initialized. That means that the app will have a bad reputation because of the slow startup.

These are pretty bad perspectives and I need to know if there is a solution for this performance problem.

The sample code

I really hope that you, the highly talented ef developer team, can significantly reduce this startup penalty.
So I prepared a sample project, where I extracted the following parts of our solution:
  • code-first conventions
  • anonymized sample-domain
Since I cannot share our complete real domain, I extracted some root entities (VersionedEntity, User, Catalogue)
and created some faked entities which have similar properties as our real entities (Company, Person etc.).
I then duplicated them 100 times so that the final domain includes about 100 entities to simulate the size of our future domain with about 100 entities. (and we are expecting over 200!)

The benchmark output is worse than expected:
  • 108 Entities ...
  • First Query with attached debugger: ~ 1.45 Minutes
  • First Query without debugger: 22 Seconds
When I add a precompiled view file the following exception is raised: "The current model no longer matches the model used to pre-generate the mapping views." (seems to be a bug)
However, these are the times of how long it takes until the exception is raised:
  • With attached debugger: 1.28 Minutes
  • Without attached debugger: 10 seconds
Even if these would be the final times (but I am expecting some additional seconds) it is too slow since starting with a debugger still consumes 1.30 minutes.
Also keep in mind that this is a 100-entities sample (and we are expecting 200-300 entities!)

Questions

  • Is there any hope that you can significantly optimize the first query performance so that a 200 entity-domain with our complexity is ready in a reasonable time when hitting (f5) ("reasonable" means max 15 seconds with a debugger and max 10 seconds without)
  • The "Attached-Debugger" overhead is massive. Is this solely because of the missing JIT-Optimizations or are there some hidden if(Debugger.Attached) paths?
  • Would it be possible that you could somehow serialize the entity-model-mapping-graph to a binary-file and than load it at startup so that the compilation of the entity-model is cached? (I am not talking about view generation)
  • Microsoft is advertising entity-framework as "the recommended OR-Mapping solution". I am curious how anybody can use this technology in a seriously big domain if the startup-penalty is that big? Is our domain that special or do all EF-Devs take a coffee break when starting their big application?
Please have a look at the attached solution. Everything is cleanly organized so that you can easily understand the structure.

Thank you!

file attachments

Closed Dec 4, 2013 at 4:26 PM by mgirgin
Verified.

Copying from earlier comment:

1.The original bug for the scenario with a debugger attached is already fixed in 6.0.2 (see #1778).
2.The original repro provided now starts up in under 8 seconds (in our testing) with 6.0.2 and with NGEN-ed EntityFramework.dll and EntityFramework.SqlServer.dll (we have a separate work item for creating better documentation on how to use NGEN with EF, see #1855)
3.The repro provided by clement_911 turned out to expose a different regression, in this case in view generation (tracked as #1877). A fix for this issue was already checked-in in the master branch but that should make its way into 6.0.2 as well very soon.
4.We have ideas on how to improve start up performance for the particular case of Code First models even further post-6.0.2. I have summarized those in #1876.

comments

divega wrote Oct 18, 2013 at 7:54 PM

Hi rothdave,

Thanks for the detailed bug report and the repro! You raise very important points about startup performance, the impact of debugging and a possible bug in view generation that we want to investigate. We will do some analysis will come back with answers to those. In the meanwhile I just wanted to provide a few data points that might help:
  • Startup time has a few components that don't grow with the size or complexity of the model, among many others we have found that because the EF runtime is no longer automatically pre-jitted, you can usually shave around 1 second of startup time by using NGEN.exe (there are more details about this in the release blog post)
  • The parts that do depend on the size and complexity of the model don't necessarily grow linearly according to some entities per second ratio, e.g. aspects such as inheritance strategies, independent vs. foreign key associations have different impacts.
Also, curious about the pre-generated views. Did you use PowerTools Beta 4 to get them? Pre-generated views from previous releases are known not to work.

Thanks,
Diego

jsmircic wrote Oct 18, 2013 at 11:50 PM

Hi divega,
I too can confirm this issue with EF 6.0.1. We have a code first model with about 300 classes and we upgraded from EF5 to EF6. With EF5 we had first query execution time at about 5 seconds. Now with EF6 it's more than two minutes on I7 machine with 8Gb.
Also, we did View generation with PowerTools 4, but it seams that the EF is no longer using pregenerated view classes. With EF5 i could set the breakpoint in the GetView method and it would be hit when the query is executed. Now the tool generates the ViewsForEntitySets class but the breakpoint is never being hit.
Can you confirm that there is some bug in the EF6, as in the current state this is not usable for us. I would like to hear from someone in the team before we revert back to EF5.

Thanks,
jure

divega wrote Oct 19, 2013 at 2:25 AM

Hi jsmircic,

There is no known issue with generated views in neither 6.0.0 nor 6.0.1. I tried to repro the behavior describe with my own model but I haven't been able to, i.e. after generating EF6 views in the application, the breakpoint is hit and the views are utilized. Could you verify that the views class derives from DbMappingViewCache and that the DbMappingViewCacheTypeAttribute at the beginning of the source file points to the correct context type?

Thanks,
Diego

divega wrote Oct 19, 2013 at 2:28 AM

Hi again jsmircic,

Also, would it be possible for you to provide a model that repros the startup performance issue you are experiencing? You can share it by mail (or uploading it to SkyDrive and sending me an email with the link). Your help in understanding the issue is appreciated.

Thanks,
Diego

jsmircic wrote Oct 19, 2013 at 11:22 AM

Hi divega

It looks I was wrong with views not being used. Yes, the tool generates the view class derived from DbMappingViewCache and the breakpoint is being hit. But on the same model in EF5 that would happen in about 7-10 seconds, and in EF6 I had to wait full 12 minutes for that to happen. I just didn’t wait long enough first time. So the views are utilized.
But, the issue seems to be related to only when running in debug mode. Without debugger performance is actually better than EF5, we have first query execution in about 20s.
I think it’s obvious this is something related to running code under debugger. In EF5 debugger didn’t have such impact on startup performance.
Also, the view generation is now much faster. For our model in EF5 view generation took 3-5 minutes. Now it’s in seconds which is great improvement.
So to correct myself, we are happy with startup performance in run-time, but when debugger is attached it’s terrible. And the debug experience is really important.
If you still need sample to try to reproduce this I could create a sample model for you, but I think sample project from rothdave reproduces the same issue.

Regards,
jure

jsmircic wrote Oct 19, 2013 at 11:28 AM

And just to give you some more info on enviroment

Im using:

VS 2013 Premium
Project target Framework is .NET 4.0 Client Profile
Windows 8.1 64 bit
PC: I7 6Gb RAM

divega wrote Oct 19, 2013 at 6:13 PM

Hi Jure,

Thanks for the additional information. The performance improvement between EF5 and EF6 that you are seeing without a debugger attached is at the level we have come to expect, in particular after the view generation was sped up. We are in agreement that "F5 performance" is very important. We need to figure out what is going on there and we will keep this thread updated.

Thanks,
Diego

divega wrote Oct 19, 2013 at 7:49 PM

Hello rothdave,

While we continue investigating, I wanted to share some initial results based on the sample model you shared. Keep in mind that any numbers were obtained running tests a few times on a local machine (most likely different from yours) in a very ad-hoc manner and are not representative benchmarks of EF performance:
  1. We were able to generate the views, store them, and feed them in. We would like to understand what process you followed to generate the views when you found the error saying "The current model no longer matches the model used to pre-generate the mapping views".
  2. As expected, the majority of the time is spent building the model (DbModelBuilder.Build), compiling it (DbModel.Compile) and generating views.
  3. Also, as expected, the time spent generating views is eliminated by having pre-generated views.
  4. Here are some initial numbers for the total time to the first query in EF 6.0.1 with your model:
With debugger attached, no pre-generated views: 40.954 seconds
With debugger attached, pre-generated views: 28.297 seconds
With no debugger attached, no pre-generated views: 18.11 seconds
With no debugger attached, pre-generated views: 8.508 seconds

rothdave wrote Oct 20, 2013 at 12:06 PM

Hy Diego,

first of all I wanna thank you for your quick response and that you started investigating the cause of this large perf issue.
I am happy that you agree that the current performance is terrible (especially the "F5"-Performance) and I am eager to know what these massive startup-times are caused by.

Of course, I wanna answer your question regarding which process I followed when I got the error "The current model no longer matches the model used to pre-generate the mapping views":
.

System.Data.Entity.Core.EntityCommandCompilationException: An error occurred while preparing the command definition. See the inner exception for details.
---> System.Data.Entity.Core.MappingException: The current model no longer matches the
model used to pre-generate the mapping views, as indicated by the ViewsForBaseEntitySets87e1d4ca44164978b0902b65026c77fb.MappingHashValue property.
Pre-generated mapping views must be either regenerated using the current model or removed if mapping views generated at runtime should be used instead.

With the initial model provided (105 entities) these are my up-to-date "performance stats" on a "Intel Core2Duo CPU P8600 @ 2.4 GHZ"
  • Without pre-compiled views:
    • With Debugger: 1 minute 9 seconds
    • Without Debugger: 33 second
  • With pre-compiled views (until I get the Mapping-Exception regarding the invalid Hash)
    • With Debugger: 45.000 seconds
    • Without Debugger: 16.123 seconds
I am wondering which CPU did you use when performing the benchmarks at your lab? Is it an I5/I7 Core?

As I have already mentioned in my initial post, we are expecting to have at least 200 entities in the final application.
So I once again, I generated some duplicates from the relatively simple "Entity3.cs" (which as some strings and only 2 one-to-many associations) to simulate the future.

These are the pretty scary results on my P8600 @ 2.4GHZ Core2:
  • Without pre-compiled views:
    • With Debugger: 2 minutes and 16 seconds
    • Without Debugger: 47 seconds
  • With pre-compiled views (until I get the Mapping-Exception regarding the invalid Hash)
    • With Debugger: 1 minute 36 seconds
    • Without Debugger 34 seconds
If I think about what other libraries/applications can render/calculate in - 2 minutes with debugger / 47 seconds without debugger - using a 2.4 GHZ Core2,
I have the feeling that there must be a big optimization potential in the algorithms EF is using for building models.

I have attached the modified project so that you can also measure the performance with 205 entities on your machine(s).

Once again, thanks for your assistance. I really appreciate that!

best regards,
david

moozzyk wrote Oct 20, 2013 at 10:35 PM

What version of the template for generating views are you using (the latest one is 1.0.1)? If you are using the latest version it would meant that the bug https://entityframework.codeplex.com/workitem/1258 was not fully fixed and EF still can generate different hashes for models build by CodeFirst and models loaded from Edmx.

rothdave wrote Oct 21, 2013 at 7:08 AM

Hi moozzyk,

Yes, I am using the latest version of the template (1.0.1).
You can reproduce this issue by downloading my sample app (EFSlowStartup_205_entities.zip) and by adding the T4-Template to the startup project.

moozzyk wrote Oct 21, 2013 at 1:25 PM

@rothdave - Thanks for the repro. I will check this out and re-open bug 1258.

moozzyk wrote Oct 21, 2013 at 8:22 PM

@rothdave - I looked with my colleague at the mismatched view hash issue. We found that you are setting a prefix for your tables which you then apply when configuring the model. However the prefix was set only in the non-default ctors. So, when using the default ctor the prefix was not set and the table names did not have the prefix and therefore the model looked differently than the one created using a non-default ctor. The T4 templates for generating views (and as far as I remember Power Tools too) is using the default ctor and therefore the generated views are essentially for a different model than you are using at runtime hence the exception you are seeing is correct.

ajcvickers wrote Oct 21, 2013 at 9:03 PM

This discussion thread looks like it is referring to the same issue: https://entityframework.codeplex.com/discussions/462470#post1108322

rothdave wrote Oct 22, 2013 at 7:41 AM

@moozzyk - Thanks for the info - yes that seems to resolve the issue with the exception because of the invalid hash.

Unfortunately this also means that the current assembly-based precompiled views cannot be used in a multi-tenancy scenario, where I use the same context with a different prefix multiple times. I think I already saw some suggestions here which proposed to allow loading pre-compiled views from disk. This would allow to use some custom logic (for example load a view file based on the used table prefix) etc.
However, I think this should be discussed in a different issue so that this issue keeps focused on the model-building/compiling startup perf.

divega wrote Oct 25, 2013 at 11:52 PM

I just want to provide a quick update:

We have identified the cause of the startup performance deterioration with the debugger attached. Our metadata collections use Lazy<T> in a way that triggers numerous invocations of Debugger.NotifyOfCrossThreadDependency() at model creation time. This call is very expensive when there is a debugger attached. We are currently evaluating different approaches to fix the issue and possible delivery vehicles for it. We will provide another update when the fix is checked in and available in our nightly builds.

Thanks,
Diego

clement_911 wrote Oct 30, 2013 at 12:17 AM

Hi all,

We are suffering from the same issue after upgrading to EF 6.0.1 (code first).

We have about 100 entities, half of those deriving from a same base abstract class.

The first query now takes
-2.58min with the debugger attached (Debug build)
-1.23min without the debugger attached (Debug build)

Needless to say that this has completed killed our development workflow. We are considering reverting to EF5 until the issue is fixed.

Thanks to the EF team for taking a serious look at this issue.

I wouldn't want the team to think this regression only occurs when the debugger is attached though. The regression is twice as bad when the debugger is attached, but the time it takes to load even without the debugger is still much worse than with EF 5 (I haven't measured the time with EF 5 but it wasn't an issue anyone of us noticed, even with the debugger).

ps: is there a post describing how to pregenerate views for EF 6.0.1 (code first). I would like to give this a try.

Thanks

clement_911 wrote Oct 30, 2013 at 12:41 AM

A bit more info..
CPU is at about 15% during the first query on my intel i7 8x CPU 2.8GHz 64 bit.
I just tried with the Release build, no debugger => 38 seconds, which is quite a bit better, even though it's my code that was build in Release mode.
I don't suppose the build generation could be re-written in c++? ;-)

clement_911 wrote Oct 30, 2013 at 12:44 AM

Actually sorry ignore the comment about the Release build result, I was measuring wrong...

divega wrote Oct 30, 2013 at 1:22 AM

Hi Clement,

are you using pre-generated views with EF5? Currently it is possible to generate views for EF6 either using EF Power Tools beta 4 or the template here: http://visualstudiogallery.msdn.microsoft.com/ae7730ce-ddab-470f-8456-1b313cd2c44d.

It would really help to have the EF5 numbers and a way to repro this.

Thanks,
Diego

clement_911 wrote Oct 30, 2013 at 3:58 AM

No we were not using pre-generated views with EF5 since it was fast enough.
I tried the tool that you have linked above. One issue is that it doesn't support vs 2013.
I did try running in VS2012 but it failed with the following exception (after I fixed another issue where it would try to use the current project app.config, whereas it should use the web.config of the web project):

Error 8 Running transformation: System.Data.ProviderIncompatibleException: The provider did not return a ProviderManifest instance. ---> System.ArgumentException: Could not determine storage version; a valid storage connection or a version hint is required.
at System.Data.SqlClient.SqlVersionUtils.GetSqlVersion(String versionHint)
at System.Data.SqlClient.SqlProviderManifest..ctor(String manifestToken)
at System.Data.SqlClient.SqlProviderServices.GetDbProviderManifest(String versionHint)
at System.Data.Common.DbProviderServices.GetProviderManifest(String manifestToken)
--- End of inner exception stack trace ---
at System.Data.Common.DbProviderServices.GetProviderManifest(String manifestToken)
at System.Data.Metadata.Edm.StoreItemCollection.Loader.InitializeProviderManifest(Action3 addError)
at System.Data.Metadata.Edm.StoreItemCollection.Loader.OnProviderManifestTokenNotification(String token, Action
3 addError)
at System.Data.EntityModel.SchemaObjectModel.Schema.HandleProviderManifestTokenAttribute(XmlReader reader)
at System.Data.EntityModel.SchemaObjectModel.Schema.HandleAttribute(XmlReader reader)
at System.Data.EntityModel.SchemaObjectModel.SchemaElement.ParseAttribute(XmlReader reader)
at System.Data.EntityModel.SchemaObjectModel.SchemaElement.Parse(XmlReader reader)
at System.Data.EntityModel.SchemaObjectModel.Schema.HandleTopLevelSchemaElement(XmlReader reader)
at System.Data.EntityModel.SchemaObjectModel.Schema.InternalParse(XmlReader sourceReader, String sourceLocation)
at System.Data.EntityModel.SchemaObjectModel.Schema.Parse(XmlReader sourceReader, String sourceLocation)
at System.Data.EntityModel.SchemaObjectModel.SchemaManager.ParseAndValidate(IEnumerable1 xmlReaders, IEnumerable1 sourceFilePaths, SchemaDataModelOption dataModel, AttributeValueNotification providerNotification, AttributeValueNotification providerManifestTokenNotification, ProviderManifestNeeded providerManifestNeeded, IList1& schemaCollection)
at System.Data.Metadata.Edm.StoreItemCollection.Loader.LoadItems(IEnumerable
1 xmlReaders, IEnumerable1 sourceFilePaths)
at System.Data.Metadata.Edm.StoreItemCollection.Init(IEnumerable
1 xmlReaders, IEnumerable1 filePaths, Boolean throwOnError, DbProviderManifest& providerManifest, DbProviderFactory& providerFactory, String& providerManifestToken, Memoizer2& cachedCTypeFunction)
at System.Data.Metadata.Edm.StoreItemCollection..ctor(IEnumerable`1 xmlReaders)
at Microsoft.VisualStudio.TextTemplating9430F4430E66228853F221FFCE762B13B49B462BBEB19E52F821DDD2799631A1811C82B6978B035A96EDFE82FC8F150A6020338C87FB877D91DAFC81BD85F3CF.GeneratedTextTransformation.GenerateViews(String contextTypeName)
at Microsoft.VisualStudio.TextTemplating9430F4430E66228853F221FFCE762B13B49B462BBEB19E52F821DDD2799631A1811C82B6978B035A96EDFE82FC8F150A6020338C87FB877D91DAFC81BD85F3CF.GeneratedTextTransformation.TransformText() C:\Users\Clement\Documents\Projects\FarmBooster\Wish.DataModel\FbDbContext.Views.tt 1 1 FarmBooster.DataModel

clement_911 wrote Oct 30, 2013 at 4:34 AM

I've stripped down our solution to only the class library project that contains our context and the entities.
Then I've added a console program that runs a single query.
The exact same project takes less than 30 sec with EF5, and over 3minutes after upgrading to EF6.
Hopefully that'll help you pinpointing the issue:
http://sdrv.ms/18AR05e

divega wrote Oct 30, 2013 at 5:19 AM

Clement, your help is very appreciated. We will investigate with this repro.

divega wrote Nov 28, 2013 at 1:45 AM

Resolving this bug given actionable items have either been already addressed or begun to be tracked somewhere else:
  1. The original bug for the scenario with a debugger attached is already fixed in 6.0.2 (see #1778).
  2. The original repro provided now starts up in under 8 seconds (in our testing) with 6.0.2 and with NGEN-ed EntityFramework.dll and EntityFramework.SqlServer.dll (we have a separate work item for creating better documentation on how to use NGEN with EF, see #1855)
  3. The repro provided by clement_911 turned out to expose a different regression, in this case in view generation (tracked as #1877). A fix for this issue was already checked-in in the master branch but that should make its way into 6.0.2 as well very soon.
  4. We have ideas on how to improve start up performance for the particular case of Code First models even further post-6.0.2. I have summarized those in #1876.

rothdave wrote Nov 28, 2013 at 9:19 AM

@Diego Thx for sharing these results and for the improvements made in this area.
Did you get your benchmark-result (8 seconds) by using pre-compiled views? Which Hardware did you use?

On a Core I5 3.2 GHZ I get the following numbers:

(Using pre-generated views):
W.o debugger: 8 seconds (first query)
With debugger: 11.6 seconds (first query)

Without pre-generated views:
W.o debugger: 18 seconds (first query)
With debugger: 24 seconds (first query)

So I can confirm that startup time with debugger is now much better and the general startup time has also been slightly improved (Although performance is still not great, but better).

Your suggestion in #1876 looks very promising and I am eager to test this approach, as 2 second startup time would be a fantastic result.

clement_911 wrote Nov 28, 2013 at 10:21 AM

Thanks for that!

divega wrote Dec 2, 2013 at 11:26 PM

Hi Rothdave,

yes, I can confirm that the 8 seconds result is with pre-generated views. In our testing it is taking 19 seconds with runtime view generation.

Thanks,
Diego