Very different performance of EF with very similar queries

Question

We have two Entity Framework queries, one with Include one with standalone query. Here they are

        ConfigModelContainer model = new ConfigModelContainer();
        var scope = model.Scopes.Include("Settings")
            .Where(s => (s.Level == intLevel && s.Name == name))
            .First();

        ConfigModelContainer model = new ConfigModelContainer();
        var scope = model.Scopes
            .Where(s => (s.Level == intLevel && s.Name == name))
            .First();
        var settings = model.Settings.Where(s => s.Scope.Id == scope.Id).ToList();

one more case that has same performance as first one (Query2)

        var scope1 = model.Scopes
            .Where(s => (s.Level == intLevel && s.Name == name))
            .First();
        scope1.Settings.Load();

First one runs for 30 seconds, second runs for sub-second. This is so weird, that I have no ideas.

Does anyone know why this might happen?

Edit: Actual TSQL queries run very fast (subsecond)

Edit 2: Here are queries:

First:

SELECT 
[Project2].[Level] AS [Level], 
[Project2].[Id] AS [Id], 
[Project2].[Name] AS [Name], 
[Project2].[ParentScope_Id] AS [ParentScope_Id], 
[Project2].[C1] AS [C1], 
[Project2].[Id1] AS [Id1], 
[Project2].[Type] AS [Type], 
[Project2].[Value] AS [Value], 
[Project2].[Scope_Id] AS [Scope_Id]
FROM ( SELECT 
    [Limit1].[Id] AS [Id], 
    [Limit1].[Name] AS [Name], 
    [Limit1].[Level] AS [Level], 
    [Limit1].[ParentScope_Id] AS [ParentScope_Id], 
    [Extent2].[Id] AS [Id1], 
    [Extent2].[Type] AS [Type], 
    [Extent2].[Value] AS [Value], 
    [Extent2].[Scope_Id] AS [Scope_Id], 
    CASE WHEN ([Extent2].[Id] IS NULL) THEN CAST(NULL AS int) ELSE 1 END AS [C1]
    FROM   (SELECT TOP (1) 
        [Extent1].[Id] AS [Id], 
        [Extent1].[Name] AS [Name], 
        [Extent1].[Level] AS [Level], 
        [Extent1].[ParentScope_Id] AS [ParentScope_Id]
        FROM [dbo].[Scopes] AS [Extent1]
        WHERE ([Extent1].[Level] = @p__linq__0) AND ([Extent1].[Name] = @p__linq__1) ) AS [Limit1]
    LEFT OUTER JOIN [dbo].[Settings] AS [Extent2] ON [Limit1].[Id] = [Extent2].[Scope_Id]
)  AS [Project2]
ORDER BY [Project2].[Id] ASC, [Project2].[C1] ASC

Second:

SELECT 
[Limit1].[Level] AS [Level], 
[Limit1].[Id] AS [Id], 
[Limit1].[Name] AS [Name], 
[Limit1].[ParentScope_Id] AS [ParentScope_Id]
FROM ( SELECT TOP (1) 
    [Extent1].[Id] AS [Id], 
    [Extent1].[Name] AS [Name], 
    [Extent1].[Level] AS [Level], 
    [Extent1].[ParentScope_Id] AS [ParentScope_Id]
    FROM [dbo].[Scopes] AS [Extent1]
    WHERE ([Extent1].[Level] = @p__linq__0) AND ([Extent1].[Name] = @p__linq__1)
)  AS [Limit1]

SELECT 
1 AS [C1], 
[Extent1].[Id] AS [Id], 
[Extent1].[Type] AS [Type], 
[Extent1].[Value] AS [Value], 
[Extent1].[Scope_Id] AS [Scope_Id]
FROM [dbo].[Settings] AS [Extent1]
WHERE [Extent1].[Scope_Id] = @EntityKeyValue1

Third:

SELECT 
[Limit1].[Level] AS [Level], 
[Limit1].[Id] AS [Id], 
[Limit1].[Name] AS [Name], 
[Limit1].[ParentScope_Id] AS [ParentScope_Id]
FROM ( SELECT TOP (1) 
    [Extent1].[Id] AS [Id], 
    [Extent1].[Name] AS [Name], 
    [Extent1].[Level] AS [Level], 
    [Extent1].[ParentScope_Id] AS [ParentScope_Id]
    FROM [dbo].[Scopes] AS [Extent1]
    WHERE ([Extent1].[Level] = @p__linq__0) AND ([Extent1].[Name] = @p__linq__1)
)  AS [Limit1]

SELECT 
1 AS [C1], 
[Extent1].[Id] AS [Id], 
[Extent1].[Type] AS [Type], 
[Extent1].[Value] AS [Value], 
[Extent1].[Scope_Id] AS [Scope_Id]
FROM [dbo].[Settings] AS [Extent1]
WHERE [Extent1].[Scope_Id] = @p__linq__0

Edit 3:

I was not able to continue tests on same machine. Here are results on faster machine. Here is code and and results:

    static void Main(string[] args)
    {
        int intLevel = 2;
        string name = "fb226050-4f92-4fca-9442-f76565b33877";
        Stopwatch sw = new Stopwatch();
        using (CMEntities model = new CMEntities())
        {
            sw.Start();
            for (int i = 0; i < 5; i++)
            {

                var scope1 = model.Scopes.Include("Settings")
                   .Where(s => (s.Level == intLevel && s.Name == name))
                   .First();

                Console.WriteLine("Query:1, Iter:{0}, Time:{1}", i, sw.ElapsedMilliseconds);
                sw.Reset();
                sw.Start();
            }
        }
        Console.WriteLine();
        using (CMEntities model = new CMEntities())
        {
            sw.Start();
            for (int i = 0; i < 5; i++)
            {

                var scope1 = model.Scopes
                   .Where(s => (s.Level == intLevel && s.Name == name))
                   .First();
                scope1.Settings.Load();
                Console.WriteLine("Query:2, Iter:{0}, Time:{1}", i, sw.ElapsedMilliseconds);
                sw.Reset();
                sw.Start();
            }
        }
        Console.WriteLine();
        using (CMEntities model = new CMEntities())
        {
            for (int i = 0; i < 5; i++)
            {
                var scope = model.Scopes
                    .Where(s => (s.Level == intLevel && s.Name == name))
                    .First();
                var settings = model.Settings.Where(s => s.Scope.Id == scope.Id).ToList();
                Console.WriteLine("Query:3, Iter:{0}, Time:{1}", i, sw.ElapsedMilliseconds);
                sw.Reset();
                sw.Start();
            }                
        }
    }
    }

Results:

Query:1, Iter:0, Time:2477
Query:1, Iter:1, Time:1831
Query:1, Iter:2, Time:1933
Query:1, Iter:3, Time:1774
Query:1, Iter:4, Time:1949

Query:2, Iter:0, Time:2036
Query:2, Iter:1, Time:1870
Query:2, Iter:2, Time:1921
Query:2, Iter:3, Time:1751
Query:2, Iter:4, Time:1758

Query:3, Iter:0, Time:188
Query:3, Iter:1, Time:201
Query:3, Iter:2, Time:185
Query:3, Iter:3, Time:203
Query:3, Iter:4, Time:217

Edit 4: I rewrote the code using NHibernate:

    static void Main(string[] args)
    {

        var cfg = new StoreConfiguration();
        var sessionFactory = Fluently.Configure()
          .Database(MsSqlConfiguration.MsSql2005
              .ConnectionString("Data Source=.;Initial Catalog=CM;Integrated Security=True;MultipleActiveResultSets=True")
          )
          .Mappings(m =>
                m.AutoMappings.Add(
                    AutoMap.AssemblyOf<Entities.Scope>(cfg)
                        .Conventions
                            .Add(
                                Table.Is(x => x.EntityType.Name + "s"),
                                PrimaryKey.Name.Is(x => "Id"),
                                ForeignKey.EndsWith("_id")
                            )
                    )
          )             
          .BuildSessionFactory();
        Stopwatch sw = new Stopwatch();
        for (int i = 0; i < 5; i++)
        {
            sw.Start();
            var session = sessionFactory.OpenSession();
            int intLevel = 2;
            string name = "fb226050-4f92-4fca-9442-f76565b33877";
            var scope = session.CreateCriteria<Entities.Scope>()
                .SetFetchMode("Settings", FetchMode.Eager)
                .Add(Restrictions.Eq("Name", name))
                .Add(Restrictions.Eq("Level", intLevel))                    
                .UniqueResult<Entities.Scope>();
            Console.WriteLine("Query:0, Iter:{0}, Time:{1}", i, sw.ElapsedMilliseconds);
            sw.Reset();
        }
    }

results are:

Query:0, Iter:0, Time:446
Query:0, Iter:1, Time:223
Query:0, Iter:2, Time:303
Query:0, Iter:3, Time:275
Query:0, Iter:4, Time:284

So NHibernate forms proper collection 10 times faster than EF. This is really sad.

Here is query generated by NHibernate:

SELECT this_.id            AS id0_1_, 
       this_.name          AS name0_1_, 
       this_.LEVEL         AS level0_1_, 
       settings2_.scope_id AS scope4_3_, 
       settings2_.id       AS id3_, 
       settings2_.id       AS id1_0_, 
       settings2_.TYPE     AS type1_0_, 
       settings2_.VALUE    AS value1_0_, 
       settings2_.scope_id AS scope4_1_0_ 
FROM   scopes this_ 
       LEFT OUTER JOIN settings settings2_ 
         ON this_.id = settings2_.scope_id 
WHERE  this_.name = @p0 
       AND this_.LEVEL = @p1 

Answer 1

When you say that the actual TSQL queries run fast, are you talking about hand-coded queries?

Try using SQL Profiler to see what is being generated by EF 3.5. Perhaps this will show why the performance would be so different, and provide some insight into whether and how it would be possible to improve the performance of the first query.

Also, here are a couple of blog posts giving specific examples of how sql generation was improved in EF 4. Even if upgrading to EF 4 isn't an option, they might provide food for thought.

Improvements to the Generated SQL in .NET 4.0 Beta1

Improvements to Generated SQL in .NET 4.0

Edit

Here's the code I used to try and reproduce your results. This is using SQL Server 2008 R2, VS 2010 (no SP1) and Entity Framework 4.0. I had to guess at the schema; hopefully it's close.

To create the tables and populate them:

set nocount on

create table Scopes
(
    [Id]                int identity primary key,
    [Level]             int,
    [Name]              nvarchar(50),
    [ParentScope_Id]    int foreign key references Scopes(Id)
)
create table Settings
(
    [Id]            int identity primary key,
    [Type]          nvarchar(20),
    [Value]         nvarchar(50),
    [Scope_Id]      int foreign key references Scopes(Id)   
)
go

declare @scopeId int,
        @scopeCount int,
        @settingCount int,
        @value nvarchar(50)

set @scopeCount = 0

while @scopeCount < 10
begin   
    insert into Scopes([Level], [Name]) values(1, 'Scope ' + cast(@scopeCount as nvarchar))
    select @scopeId = @@IDENTITY
    set @settingCount = 0

    while @settingCount < 10000
    begin
        set @value = 'Setting ' + cast(@scopeId as nvarchar) + '.' + cast(@settingCount as nvarchar)
        insert into Settings([Type], [Value], [Scope_Id]) values ('Test', @value, @scopeId)
        set @settingCount = @settingCount + 1
    end

    set @scopeCount = @scopeCount + 1
end

Using a console application to test:

using System;
using System.Collections.Generic;
using System.Linq;
using System.Text;
using System.Diagnostics;

namespace so_q5205281
{
    class Program
    {
        static void Main(string[] args)
        {
            using (var context = new EFTestEntities())
            {
                int level = 1;
                string name = "Scope 4";

                ExecQuery1(context, level, name);
                ExecQuery1(context, level, name);
                ExecQuery1(context, level, name);

                ExecQuery2(context, level, name);
                ExecQuery2(context, level, name);
                ExecQuery2(context, level, name);
            }

            Console.ReadLine();
        }

        static void ExecQuery1(EFTestEntities context, int level, string name)
        {
            Stopwatch stopwatch = Stopwatch.StartNew();

            var scope = context.Scopes.Include("Settings")
                .Where(s => s.Level == level && s.Name == name)
                .First();

            int settingsCount = scope.Settings.Count();

            stopwatch.Stop();

            Console.WriteLine("Query 1, scope name: {0}, settings count: {1}, seconds {2}", scope.Name, settingsCount, stopwatch.Elapsed.TotalSeconds);
        }

        static void ExecQuery2(EFTestEntities context, int level, string name)
        {
            Stopwatch stopwatch = Stopwatch.StartNew();

            var scope = context.Scopes
                .Where(s => s.Level == level && s.Name == name)
                .First();

            var settings = context.Settings.Where(s => s.Scope.Id == scope.Id).ToList();

            int settingsCount = scope.Settings.Count();

            stopwatch.Stop();

            Console.WriteLine("Query 2, scope name: {0}, settings count: {1}, seconds {2}", scope.Name, settingsCount, stopwatch.Elapsed.TotalSeconds);
        }
    }
}

The EF model was created using the default settings, and updating the model from the database:

The sql sent from EF for the first query:

exec sp_executesql N'SELECT 
[Project2].[Id] AS [Id], 
[Project2].[Level] AS [Level], 
[Project2].[Name] AS [Name], 
[Project2].[ParentScope_Id] AS [ParentScope_Id], 
[Project2].[C1] AS [C1], 
[Project2].[Id1] AS [Id1], 
[Project2].[Type] AS [Type], 
[Project2].[Value] AS [Value], 
[Project2].[Scope_Id] AS [Scope_Id]
FROM ( SELECT 
    [Limit1].[Id] AS [Id], 
    [Limit1].[Level] AS [Level], 
    [Limit1].[Name] AS [Name], 
    [Limit1].[ParentScope_Id] AS [ParentScope_Id], 
    [Extent2].[Id] AS [Id1], 
    [Extent2].[Type] AS [Type], 
    [Extent2].[Value] AS [Value], 
    [Extent2].[Scope_Id] AS [Scope_Id], 
    CASE WHEN ([Extent2].[Id] IS NULL) THEN CAST(NULL AS int) ELSE 1 END AS [C1]
    FROM   (SELECT TOP (1) 
        [Extent1].[Id] AS [Id], 
        [Extent1].[Level] AS [Level], 
        [Extent1].[Name] AS [Name], 
        [Extent1].[ParentScope_Id] AS [ParentScope_Id]
        FROM [dbo].[Scopes] AS [Extent1]
        WHERE ([Extent1].[Level] = @p__linq__0) AND ([Extent1].[Name] = @p__linq__1) ) AS [Limit1]
    LEFT OUTER JOIN [dbo].[Settings] AS [Extent2] ON [Limit1].[Id] = [Extent2].[Scope_Id]
)  AS [Project2]
ORDER BY [Project2].[Id] ASC, [Project2].[C1] ASC',N'@p__linq__0 int,@p__linq__1 nvarchar(4000)',@p__linq__0=1,@p__linq__1=N'Scope 4'

and for the second query:

exec sp_executesql N'SELECT TOP (1) 
[Extent1].[Id] AS [Id], 
[Extent1].[Level] AS [Level], 
[Extent1].[Name] AS [Name], 
[Extent1].[ParentScope_Id] AS [ParentScope_Id]
FROM [dbo].[Scopes] AS [Extent1]
WHERE ([Extent1].[Level] = @p__linq__0) AND ([Extent1].[Name] = @p__linq__1)',N'@p__linq__0 int,@p__linq__1 nvarchar(4000)',@p__linq__0=1,@p__linq__1=N'Scope 4'

exec sp_executesql N'SELECT 
[Extent1].[Id] AS [Id], 
[Extent1].[Type] AS [Type], 
[Extent1].[Value] AS [Value], 
[Extent1].[Scope_Id] AS [Scope_Id]
FROM [dbo].[Settings] AS [Extent1]
WHERE [Extent1].[Scope_Id] = @p__linq__0',N'@p__linq__0 int',@p__linq__0=5

and the output:

Query 1, scope name: Scope 4, settings count: 10000, seconds 0.6657546
Query 1, scope name: Scope 4, settings count: 10000, seconds 0.1608498
Query 1, scope name: Scope 4, settings count: 10000, seconds 0.1097625
Query 2, scope name: Scope 4, settings count: 10000, seconds 0.0742593
Query 2, scope name: Scope 4, settings count: 10000, seconds 0.0551458
Query 2, scope name: Scope 4, settings count: 10000, seconds 0.0555465

Answer 2

A couple things to check...

1. How is the relationship between Scopes and Settings defined in the entity model? Are the correct foreign keys used? How about multiplicity (one-to-many, etc.)?
2. Does your execution time improve if you change your first query to:

.

ConfigModelContainer model = new ConfigModelContainer();
var scope = model.Scopes.Include("Settings")
                 .First<Scope>(s => s.Level == intLevel && s.Name == name);

I don't know for sure that Linq will optimize this query any differently from yours, but maybe see if it happens to do so.

As regards upgrading to EF 4.0, I don't know how feasible that is if your project is in .NET 3.5. Nevertheless, I never had this problem when our projects were using .NET 3.5/EF 1.