none
Why is EF taking 30 seconds to load records when the generated query only takes 1/2 of a second?

    Question

  • The executeTime below is 30 seconds the first time, and 25 seconds the next time I execute the same set of code.  When watching in SQL Profiler, I immediately see a login, then it just sits there for about 30 seconds.  Then as soon as the select statement is run, the app finishes the ToList command.  When I run the generated query from Management Studio, the database query only takes about 400ms.  It returns 14 rows and 350 columns.  It looks like time it takes transforming the database results to the entities is so small it is not noticable.


    So what is happening in the 30 seconds before the database call is made?

    If entity framework is this slow, it is not possible for us to use it.  Is there something I am doing wrong or something I can change to speed this up dramatically?




    using (EntitiesContext context = new EntitiesContext()) 
                { 
                    Stopwatch sw = new Stopwatch(); 
                    sw.Start(); 
                    var groupQuery = (from g in context.Groups.Include("DealContract") 
                                    .Include("DealContract.Contracts") 
                                    .Include("DealContract.Contracts.AdvertiserAccountType1") 
                                    .Include("DealContract.Contracts.ContractItemDetails") 
                                    .Include("DealContract.Contracts.Brands") 
                                    .Include("DealContract.Contracts.Agencies") 
                                    .Include("DealContract.Contracts.AdvertiserAccountType2") 
                                    .Include("DealContract.Contracts.ContractProductLinks.Products") 
                                    .Include("DealContract.Contracts.ContractPersonnelLinks") 
                                    .Include("DealContract.Contracts.ContractSpotOrderTypes") 
                                    .Include("DealContract.Contracts.Advertisers") 
                                where g.GroupKey == 6 
                                select g).OfType<Deal>(); 
                    sw.Stop(); 
                    var queryTime = sw.Elapsed; 
                    sw.Reset(); 
                    sw.Start(); 
                    var groups = groupQuery.ToList(); 
                    sw.Stop(); 
                    var executeTime = sw.Elapsed; 
                } 
     
    • Edited by Shanewho Thursday, March 26, 2009 4:00 PM fixed formatting
    Thursday, March 26, 2009 3:59 PM

Answers

  • Looks like EF is spending a lot of time trying to optimize the query before it gets sent to the database. Queries with many Include()s typically require many JOINs and result in many columns being returned from the store. This makes the generated query big and complicated so preparing the query takes a lot of time. If you have inheritance in the picture (and it seems you do, because you use OfType<>()) it adds even more to the cost of query processing.

    You can take a look at the query by calling groupQuery.ToTraceString().

    In such case, our recommendation would be to simplify the query by removing includes which aren't immediately needed and using EntityCollection.Load() to populate them before actual use. This will result in more than one query being sent to the store as you walk your object graph, but each individual query can be simpler.

    Here are the steps you can take to determine which Include() is causing most problems:

    1.       Remove all the Includes
    2.       Start adding them one by one, starting with those paths that are *:1 only.
    3.       Stop adding Includes when the performance becomes inacceptable and remove the last include added.
    4.       Use explicit loading from there, or simply load the remaining entities on independent queries and let identity resolution and relationship span do their thing.

    In this particular case, it seems that most of the paths you're interested in focus on Contracts. Maybe you can rewrite the query so that it starts from Contract object and include DealContract and the remaining ones instead and see whether this improves anything?

    BTW. Entity Framework which ships in .NET Framework 4.0 will have support for on-demand loading, so that you will not have to call EntityCollection.Load() explicitly. See http://blogs.msdn.com/efdesign for more information on this and other features.


    This posting is provided "AS IS" with no warranties, and confers no rights.
    Friday, March 27, 2009 4:03 PM
    Moderator
  • All right, if I use a Compiled query, the first time it take 30 seconds, and the second time it takes 1/4th of a second.  Is there anything I can do to speed up the first call?
    Thursday, March 26, 2009 7:23 PM

All replies

  • All right, if I use a Compiled query, the first time it take 30 seconds, and the second time it takes 1/4th of a second.  Is there anything I can do to speed up the first call?
    Thursday, March 26, 2009 7:23 PM
  • Thursday, March 26, 2009 8:11 PM
  • This saved a second or two, but it is still taking 23-28 seconds...
    Thursday, March 26, 2009 9:17 PM
  • Shanewho,

    Would it be possible for you to share your schema files so that we can investigate this issue?

    If so, please send your csdl/ssdl/msl or edmx to jaroslaw dot kowalski at microsoft dot com.

    Thanks,

    Jarek
    This posting is provided "AS IS" with no warranties, and confers no rights.
    Friday, March 27, 2009 2:37 AM
    Moderator
  • Looks like EF is spending a lot of time trying to optimize the query before it gets sent to the database. Queries with many Include()s typically require many JOINs and result in many columns being returned from the store. This makes the generated query big and complicated so preparing the query takes a lot of time. If you have inheritance in the picture (and it seems you do, because you use OfType<>()) it adds even more to the cost of query processing.

    You can take a look at the query by calling groupQuery.ToTraceString().

    In such case, our recommendation would be to simplify the query by removing includes which aren't immediately needed and using EntityCollection.Load() to populate them before actual use. This will result in more than one query being sent to the store as you walk your object graph, but each individual query can be simpler.

    Here are the steps you can take to determine which Include() is causing most problems:

    1.       Remove all the Includes
    2.       Start adding them one by one, starting with those paths that are *:1 only.
    3.       Stop adding Includes when the performance becomes inacceptable and remove the last include added.
    4.       Use explicit loading from there, or simply load the remaining entities on independent queries and let identity resolution and relationship span do their thing.

    In this particular case, it seems that most of the paths you're interested in focus on Contracts. Maybe you can rewrite the query so that it starts from Contract object and include DealContract and the remaining ones instead and see whether this improves anything?

    BTW. Entity Framework which ships in .NET Framework 4.0 will have support for on-demand loading, so that you will not have to call EntityCollection.Load() explicitly. See http://blogs.msdn.com/efdesign for more information on this and other features.


    This posting is provided "AS IS" with no warranties, and confers no rights.
    Friday, March 27, 2009 4:03 PM
    Moderator
  • Hi ShaneWho,

    I have same exact problem with my LinqToEntities query, ie, cold query taking 30 seconds and subsequent warm queries taking less than 1/2 second. I am using EF5 and the query uses many includes like you do here and entities used in the query using TPT inheritance. 

    Appreciate if you can share me the experience how you resolved this cold query performance issue if you had found a solution.

    Thanks

    Srini

    Friday, January 04, 2013 8:03 PM