Why is Entity Framework 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?

UPDATE: 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?

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; 
} 

Answer 1

I had this exact same problem, my query was taking 40 seconds.

I found the problem was with the .Include("table_name") functions. The more of these I had, the worse it was. Instead I changed my code to Lazy Load all the data I needed right after the query, this knocked the total time down to about 1.5 seconds from 40 seconds. As far as I know, this accomplishes the exact same thing.

So for your code it would be something like this:

var groupQuery = (from g in context.Groups
            where g.GroupKey == 6 
            select g).OfType<Deal>(); 

var groups = groupQuery.ToList();

foreach (var g in groups)
{
    // Assuming Dealcontract is an Object, not a Collection of Objects
    g.DealContractReference.Load();
    if (g.DealContract != null)
    {
        foreach (var d in g.DealContract)
        {
            // If the Reference is to a collection, you can just to a Straight ".Load"
            //  if it is an object, you call ".Load" on the refence instead like with "g.DealContractReference" above
            d.Contracts.Load();
            foreach (var c in d.Contracts)
            {
                c.AdvertiserAccountType1Reference.Load();
                // etc....
            }
        }
    }
}

Incidentally, if you were to add this line of code above the query in your current code, it would knock the time down to about 4-5 seconds (still too ling in my option) From what I understand, the MergeOption.NoTracking option disables a lot of the tracking overhead for updating and inserting stuff back into the database:

context.groups.MergeOption = MergeOption.NoTracking;