New Posts New Posts RSS Feed: Startup performance drop after 6.1.4
  FAQ FAQ  Forum Search   Calendar   Register Register  Login Login

Startup performance drop after 6.1.4
 Post Reply Post Reply
Author
  Share Topic Share Topic  Topic Search Topic Search  Topic Options Topic Options
stephenmcd1 View Drop Down
DevForce MVP
DevForce MVP


Joined: 27-Oct-2009
Location: Los Angeles, CA
Posts: 166 		Post Options Post Options   Quote stephenmcd1 Quote  Post ReplyReply Direct Link To This Post Topic: Startup performance drop after 6.1.4
    Posted: 22-Mar-2012 at 4:01pm
We are currently in the process of upgrading from 6.1.3.1 to 6.1.6.0.  On the new version, our app now takes a very, very long time to start up.  It seems like it's related to the static constructors that have started being generated by the T4s ("Release build models may not initialize navigation properties correctly. Fixed in 6.1.3.3. [D1918]").

The slowdown is all in IIS (for some reason, our Silverlight client seems to still start up quickly).  The first time we make query  from the Silverlight client, IIS starts taking tons of CPU cycles and doesn't respond for about 4 minutes!  Previously, whatever startup logic IIS did wasn't even noticeable (probably a few seconds) - oh, and these numbers are from a pretty beefy dev box.

I tried to do some profiling and it looked like it was just spending like 99% of the time in various static constructors - first in the autogenerated EntityRelations class in then in all the PropertyMetadata classes.

I found that I can cutdown the time by accessing one of the EntityRelations members in Application_Start through straight C# code (e.g. var dummy = EntityRelations.SomeRandomRelation.Name).  But even that way takes about 45 seconds and it doesn't quite feel right.  In a production environment, a 45 second cold start might be barely acceptable but it is a deal-breaker when it comes to normal development (every code change and build incurs an extra 45 seconds of overhead to run a unit test, etc.).

We have a relatively complex data model (lots of entities and lots of relationships between them) but it's never been a problem before this upgrade.

Any suggestions on what we might be able to do or look at to help performance?

Thanks,
-Stephen
Back to Top
kimj View Drop Down
IdeaBlade
IdeaBlade
Avatar

Joined: 09-May-2007
Posts: 1391 		Post Options Post Options   Quote kimj Quote  Post ReplyReply Direct Link To This Post Posted: 22-Mar-2012 at 5:48pm
Hi Stephen,
 
We're not aware of any performance issues inadvertently (or otherwise) introduced since the 6.1.3 release.  A 4 minute cold start time is awful, and really a 45 second startup time isn't all that great either, so something odd is going on. 
 
DevForce has always performed metadata initialization, which is what those static constructors help kick off.   When the constructors aren't there your application won't run, so it probably wasn't the D1918 fix that triggered this problem since I'm assuming your metadata was loading successfully before.
 
Generally large, complex models will incur a first query and first save startup penalty, but if you didn't see the problem before then the hit shouldn't be any greater in the new release.  For the record, you can use pre-generated views to work around this problem, and we can provide more information if you're interested.
 
A common cause for startup performance problems is the automatic probing DevForce does when the application loads.   If too many files are being probed that can cause significant delays.  Your debug log will indicate the total probing time.
 
If you can upload (or email) your debug log, we can analyze it further to see if anything stands out.  If you happen to have a debug log from a 6.1.3.1 run, it would help if we saw that too. 
 
 
Back to Top
stephenmcd1 View Drop Down
DevForce MVP
DevForce MVP


Joined: 27-Oct-2009
Location: Los Angeles, CA
Posts: 166 		Post Options Post Options   Quote stephenmcd1 Quote  Post ReplyReply Direct Link To This Post Posted: 22-Mar-2012 at 7:20pm
Hi Kim, thanks for the response.

Probing doesn't seem to be the problem.  Looking at the log it takes about a second to complete:
MEF assembly probing started: 3/22/2012 6:26:37 PM. If this takes a long time, use IdeaBlade.Core.Composition.CompositionHost to specify/restrict which assemblies to probe.

Assembly 'MyApp.Business, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null' added to PartsCatalog

Assembly 'MyApp.Data, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null' added to PartsCatalog

MEF assembly probing completed: 3/22/2012 6:26:38 PM
The slowdown we see is before any querying takes places (although, for the record, I believe we do pre-generate the EF views).  Looking at the debug log, there is a 3 minute gap between these two entries:
18:26:38 - EntityServer listening on https://localhost/Dev/60/Alt/EntityServer.svc/sl
18:29:47 - CompositionContext: '-IbDefault-' - Probed for default 'IDataSourceKeyResolver' and found 'IdeaBlade.EntityModel.DefaultDataSourceKeyResolver'.
If you want the entire debug log, I'd be happy to email it (rather not post it here just to avoid exposing any sensitive info).  Let me know what email I should send it to.  I'll also get a debug log from before we did the upgrade so you can compare.

In trying to isolate the problem, I wrote a simple unit test.  All I do is make a call to initialize EntityRelations for our main assembly (all our entities are in this one assembly).  When I've profiled the app, it's seemed that this was the big bottleneck.  I couldn't real nail down the specifics of the slowdown but I thought I saw a lot of time spent in the PropertyInterceptor<,,> constructor as it sets up the ThreadLocal variable....and interestingly enough, that is a new field in 6.1.6 (at least compared to 6.1.3).  But I don't claim to be a profiling expert so.... :-)

Anyway, here's the test along with results from 6.1.6.0 and 6.1.3.1:
[TestMethod]
public void TestPerformance()
{
    var ibVersion = typeof (EntityManager).Assembly.GetName().Version;
    var sw = Stopwatch.StartNew();
    EntityMetadataStore.Instance.InitializeEntityRelations(typeof (MyEntity).Assembly);
    Assert.Fail("Version " + ibVersion + " took " + sw.Elapsed);
}
Results:
Assert.Fail failed. Version 6.1.6.0 took 00:01:07.4042727
Assert.Fail failed. Version 6.1.3.1 took 00:00:10.6463887
So the same call used to take 10 seconds but now takes over a minute. 
Back to Top
kimj View Drop Down
IdeaBlade
IdeaBlade
Avatar

Joined: 09-May-2007
Posts: 1391 		Post Options Post Options   Quote kimj Quote  Post ReplyReply Direct Link To This Post Posted: 22-Mar-2012 at 7:40pm
I would like to see the full debug logs, or at least everything up to the completion of the first query.  Also, would you be willing to send your EDMX?  You can mail to IdeaBladeSupportTrack with task id 11702 in the subject line. 
 
 
Back to Top
stephenmcd1 View Drop Down
DevForce MVP
DevForce MVP


Joined: 27-Oct-2009
Location: Los Angeles, CA
Posts: 166 		Post Options Post Options   Quote stephenmcd1 Quote  Post ReplyReply Direct Link To This Post Posted: 22-Mar-2012 at 8:00pm
I wish we only had a single EDMX but we actually have 12!  :-(.  Yup, a lot of entities.  I believe we have a little over 400 entities at the moment and the EDMX designer doesn't seem to like complex models so we've had to split them up.  

Further complicating things, we've tweaked the T4s templates to do various other code generation for us.  The one thing that our T4s do that is probably pertinent to this issue is that we auto-generate some additional DataEntityProperties in places where we want to be able to navigate between models (we can't use normal navigation properties because they can't span models so we do a little bit of that ourselves).  I'm not sure that affects this issue but at the very least the 'graph' of entities and how they are connected is pretty massive.  I don't really know how the CLR does static constructors but I can imagine things get complicated when types start referencing each other and even more complicated when there are hundreds of them.

With that being said, would you need all the EDMX's or just one to sample?  Anything else you'd need?

I just sent you an email with the full debug logs.
Back to Top
kimj View Drop Down
IdeaBlade
IdeaBlade
Avatar

Joined: 09-May-2007
Posts: 1391 		Post Options Post Options   Quote kimj Quote  Post ReplyReply Direct Link To This Post Posted: 28-Mar-2012 at 9:25am
For anyone else interested, the problem turned out to have been introduced in the 6.1.5 release when we made some changes to the PropertyInterceptor class to fix a thread safety issue.    When a model loads at startup DevForce loads all the entity properties, each of which has a getter, and often a setter, property interceptor.   In large models the problem is especially apparent, but all models will see some performance hit at startup.
 
We'll get this fixed in the 6.1.7 release. 
Back to Top
stephenmcd1 View Drop Down
DevForce MVP
DevForce MVP


Joined: 27-Oct-2009
Location: Los Angeles, CA
Posts: 166 		Post Options Post Options   Quote stephenmcd1 Quote  Post ReplyReply Direct Link To This Post Posted: 23-May-2012 at 2:52pm

Did the fix to this ever make it into 6.1.7?  I just upgraded our project but I'm still seeing very poor startup performance.  From the release notes, I saw some fixes to Property Interceptors but I'm thinking that those changes could have been related to a different performance problem that I reported.

What is the status of this issue?
Back to Top
kimj View Drop Down
IdeaBlade
IdeaBlade
Avatar

Joined: 09-May-2007
Posts: 1391 		Post Options Post Options   Quote kimj Quote  Post ReplyReply Direct Link To This Post Posted: 23-May-2012 at 3:41pm
We did fix this in the 6.1.7 release.  It was defect #2012 in the release notes, and involved the use of ThreadLocal variables within the PropertyInterceptor class.  However, I just reran your test solution and still see a performance hit, so it's possible some later changes made to the PropertyInterceptor logic caused a regression we didn't catch.  We'll take a look at this and let you know what we find.
Back to Top
kimj View Drop Down
IdeaBlade
IdeaBlade
Avatar

Joined: 09-May-2007
Posts: 1391 		Post Options Post Options   Quote kimj Quote  Post ReplyReply Direct Link To This Post Posted: 24-May-2012 at 6:01pm

Stephen,

Our fix for the SL5 performance problem you also reported (defect #2034) did introduce a new performance problem at startup.  We've fixed this in current bits.  Please contact us via email (kimj or IdeaBladeSupportTrack) to let us know how you want to proceed. 
Back to Top
stephenmcd1 View Drop Down
DevForce MVP
DevForce MVP


Joined: 27-Oct-2009
Location: Los Angeles, CA
Posts: 166 		Post Options Post Options   Quote stephenmcd1 Quote  Post ReplyReply Direct Link To This Post Posted: 30-May-2012 at 12:19pm
After testing everything, it looks like the performance problems have been solved in the patch build (6.1.7.1).  Thanks!
Back to Top
kimj View Drop Down
IdeaBlade
IdeaBlade
Avatar

Joined: 09-May-2007
Posts: 1391 		Post Options Post Options   Quote kimj Quote  Post ReplyReply Direct Link To This Post Posted: 30-May-2012 at 2:10pm
For anyone interested, the 6.1.7.1 patch release is also now available from our web site.  The only difference from 6.1.7.0 is the fix for this startup performance issue.
Back to Top
 Post Reply Post Reply

Forum Jump Forum Permissions View Drop Down