4

I have a simple EF implementation in which I retrieve ~20K records and include two child entities: 

using (InsightEntities context = new InsightEntities())
{
   return context.Accounts
   .Include(x => x.Division)
   .Include(x => x.Division.Company)
   .OrderBy(x => x.ID)
   .AsNoTracking()
   .ToList();
}

When I profile the EF call via SQL Profiler, the duration of the SQL command is ~1.2s, even on subsequent calls. But if I copy and paste the same SQL that EF is generating and run it directly through SSMS, the duration is half that.

Below is a screenshot of EF calls (red ovals) and direct calls (green ovals):

enter image description here

I understand that EF does a lot of work mapping data to objects, interpreting relationships, and so on, but why would the query alone take twice as long as the same query run directly? Are there changes to the default EF connection string that might optimize the queries?

(I should add that the query itself is completely optimized with indices for all foreign keys.)

Thank you!

hbeam
  • 187
  • 3
  • 9
  • Are you by any chance executing SSMS locally on the server, and EF is running on your local computer accessing the db server via network? – FrankPl Aug 21 '13 at 17:36
  • Good question. All code and the database are running locally though. – hbeam Aug 21 '13 at 17:38
  • The queries are the same. The read counts are different ? Best include the SQL generated and SQL used in post. – phil soady Aug 22 '13 at 01:08
  • @philsoady - The read counts are all 1487 except for the first direct call (green one) that is slightly higher. That may well be down to query compilation on the first time the direct query was run (Queries run in SSMS won't use execution plans cached by the application unless a load of session options are the same. This isn't normally the case due to different defaults for `ARITHABORT`) – Martin Smith Aug 22 '13 at 08:13

2 Answers2

3

The reads are the same between the two traces so it doesn't look plan related.

Quite likely it is just because Entity Framework does more when it consumes the result set so takes longer.

For example creating the following scalar UDF

CREATE FUNCTION dbo.GetTime()
RETURNS CHAR(12)
AS
  BEGIN
      RETURN CONVERT(VARCHAR(12), GETDATE(), 114)
  END

Then running in Management Studio

SELECT TOP (10) CAST(dbo.GetTime() AS CHAR(8000))
FROM   sys.all_objects

Completes almost instantly but simulating a client that does more work

using (SqlConnection con = new SqlConnection(connectionString))
{
    con.Open();

    using (SqlCommand command = new SqlCommand(
        @"SELECT TOP (10)  CAST(dbo.GetTime() AS CHAR(8000))
          FROM sys.all_objects", con))
    {
        using (SqlDataReader reader = command.ExecuteReader())
        {
            while (reader.Read())
            {
                Console.WriteLine(reader.GetString(0).TrimEnd());
                System.Threading.Thread.Sleep(1000);
            }
        }
    }
}

Shows up in Profiler as duration 8 seconds.

Profiler

The results of the run shown above are 

23:55:54:870
23:55:54:870
23:55:54:870
23:55:55:870
23:55:56:870
23:55:57:870
23:55:58:870
23:55:59:870
23:56:00:870
23:56:01:870

The difference in time stamps between 1st and last row are 7 seconds. The first three rows were returned almost immediately and there after SQL Server was delayed waiting on the client (with wait type ASYNC_NETWORK_IO) before continuing with execution.

Martin Smith
  • 438,706
  • 87
  • 741
  • 845
  • Does that mean that the "Duration" shown in the profiler is actually query execution time *plus* the time until the client picked up the result set? – Slauma Aug 21 '13 at 19:56
  • 1
    @Slauma - A slow client actually delays execution. I've edited the example in my answer to show that better (see the second delay between timestamps). I think the duration is counted as from start of query execution to sending the last result packet to the client. – Martin Smith Aug 21 '13 at 23:08
  • wow, now I want to know more about understanding times in SQL profiler. I had hoped/expected to see the time the DB spent processing something independent of how slow the client might me. That is serious heads for me.! – phil soady Aug 22 '13 at 10:42
  • 1
    @philsoady - As well as duration `8000` the CPU was `0`, Reads `2` and Writes `0` so that would give a good indication when looking in Profiler that the query was spending a lot of time waiting rather than actively busy processing. – Martin Smith Aug 22 '13 at 10:48
  • I see what your saying, and it makes sense. thanks for the tips. – phil soady Aug 22 '13 at 11:26
  • FWIW, I profiled the same code under EF6 RC1, and apparently EF releases the SQL connection before materializing the objects, resulting in much faster query durations. Unfortunately no change to the overall performance! – hbeam Aug 23 '13 at 20:13
1

The Include statements are known to cause slowdowns. I am not exactly sure why. Try commenting-out your include statements and use lazy loading instead. Here is another SO article with the same conclusion: Why is Entity Framework taking 30 seconds to load records when the generated query only takes 1/2 of a second?

Community
  • 1
  • 1
tgolisch
  • 6,549
  • 3
  • 24
  • 42
  • 2
    The issue there is probably compilation before the query even gets sent to the server. Using [compiled queries](http://msdn.microsoft.com/en-us/library/bb896297.aspx) can mitigate against this. – Martin Smith Aug 21 '13 at 18:41
  • +1 for the ref, definitely the Includes are causing the slowdown. I'm really surprised this hasn't been optimized out of the framework by this point. I imagine this comes up often when building screens with Address -> State -> Country relationships. Guessing the overhead comes from looking for existing entities (Departments, States) inside the context instead of making a bunch of copies. – hbeam Aug 23 '13 at 20:17