First query is slow and pre-generated views aren't being hit (probably)

Question

I'm having a bit of trouble with the time it takes EF to pull some entities. The entity in question has a boatload of props that live in 1 table, but it also has a handful of ICollection's that relate to other tables. I've abandoned the idea of loading the entire object graph as it's way too much data and instead will have my Silverlight client send out a new request to my WCF service as details are needed.

After slimming down to 1 table's worth of stuff, it's taking roughly 8 seconds to pull the data, then another 1 second to .ToList() it up (I expect this to be < 1 second). I'm using the stopwatch class to take measurements. When I run the SQL query in SQL management studio, it takes only a fraction of a second so I'm pretty sure the SQL statement itself isn't the problem.

Here is how I am trying to query my data:

public List<ComputerEntity> FindClientHardware(string client)
{
        long time1 = 0;
        long time2 = 0;
        var stopwatch = System.Diagnostics.Stopwatch.StartNew();

        // query construction always takes about 8 seconds, give or a take a few ms.
        var entities =
            DbSet.Where(x => x.CompanyEntity.Name == client); // .AsNoTracking() has no impact on performance
        //.Include(x => x.CompanyEntity)
        //.Include(x => x.NetworkAdapterEntities) // <-- using these 4 includes has no impact on SQL performance, but faster to make lists without these
        //.Include(x => x.PrinterEntities)        // I've also abandoned the idea of using these as I don't want the entire object graph (although it would be nice)
        //.Include(x => x.WSUSSoftwareEntities)

        //var entities = Find(x => x.CompanyEntity.Name == client); // <-- another test, no impact on performance, same execution time

        stopwatch.Stop();
        time1 = stopwatch.ElapsedMilliseconds;
        stopwatch.Restart();

        var listify = entities.ToList(); // 1 second with the 1 table, over 5 seconds if I use all the includes. 

        stopwatch.Stop();
        time2 = stopwatch.ElapsedMilliseconds;

        var showmethesql = entities.ToString();

        return listify;
    }

I'm assuming that using the .Include means eager loading, although it isn't relevant in my current case as I just want the 1 table's worth of stuff. The SQL generated by this statement (which executes super fast in SSMS) is:

SELECT 
  [Extent1].[AssetID] AS [AssetID],  
  [Extent1].[ClientID] AS [ClientID],  
  [Extent1].[Hostname] AS [Hostname],  
  [Extent1].[ServiceTag] AS [ServiceTag],  
  [Extent1].[Manufacturer] AS [Manufacturer],  
  [Extent1].[Model] AS [Model],  
  [Extent1].[OperatingSystem] AS [OperatingSystem],  
  [Extent1].[OperatingSystemBits] AS [OperatingSystemBits],  
  [Extent1].[OperatingSystemServicePack] AS [OperatingSystemServicePack],  
  [Extent1].[CurrentUser] AS [CurrentUser],  
  [Extent1].[DomainRole] AS [DomainRole],  
  [Extent1].[Processor] AS [Processor],  
  [Extent1].[Memory] AS [Memory],  
  [Extent1].[Video] AS [Video],  
  [Extent1].[IsLaptop] AS [IsLaptop],  
  [Extent1].[SubnetMask] AS [SubnetMask],  
  [Extent1].[WINSserver] AS [WINSserver],  
  [Extent1].[MACaddress] AS [MACaddress],  
  [Extent1].[DNSservers] AS [DNSservers],  
  [Extent1].[FirstSeen] AS [FirstSeen],  
  [Extent1].[IPv4] AS [IPv4],  
  [Extent1].[IPv6] AS [IPv6],  
  [Extent1].[PrimaryUser] AS [PrimaryUser],  
  [Extent1].[Domain] AS [Domain],  
  [Extent1].[CheckinTime] AS [CheckinTime],  
  [Extent1].[ActiveComputer] AS [ActiveComputer],  
  [Extent1].[NetworkAdapterDescription] AS [NetworkAdapterDescription],  
  [Extent1].[DHCP] AS [DHCP] 
FROM  
  [dbo].[Inventory_Base] AS [Extent1] 
  INNER JOIN [dbo].[Entity_Company] AS [Extent2] 
    ON [Extent1].[ClientID] = [Extent2].[ClientID] 
WHERE 
  [Extent2].[CompanyName] = @p__linq__0

Which is basically a select all columns in this table, join a second table that has a company name, and filter with a where clause of companyname == input value to the method. The particular company I'm pulling only returns 75 records.

Disabling object tracking with .AsNoTracking() has zero impact on execution time.

I also gave the Find method a go, and it had the exact same execution time. The next thing I tried was to pregenerate the views in case the issue was there. I am using code first, so I used the EF power tools to do this.

This long period of time to run this query causes too long of a delay for my users. When I hand write the SQL code and don't touch EF, it is super quick. Any ideas as to what I'm missing?

Also, maybe related or not, but since I'm doing this in WCF which is stateless I assume absolutely nothing gets cached? The way I think about it is that every new call is a firing up this WCF service library for the first time, therefore there is no pre-existing cache. Is this an accurate assumption?

Update 1
So I ran this query twice within the same unit test to check out the cold/warm query thing. The first query is horrible as expected, but the 2nd one is lightning fast clocking in at 350ms for the whole thing. Since WCF is stateless, is every single call to my WCF service going to be treated as this first ugly-slow query? Still need to figure out how to get this first query to not suck.
Update 2
You know those pre-generated views I mentioned earlier? Well... I don't think they are being hit. I put a few breakpoints in the autogenerated-by-EF-powertools ReportingDbContext.Views.cs file, and they never get hit. This coupled with the cold/warm query performance I see, this sounds like it could be meaningful. Is there a particular way I need to pregenerate views with the EF power tools in a code first environment?

You have a misconception of when the SQL statement is actually executed (which in your case isn't until `ToList()` occurs). So the time1 should always be less then 1 second (probably 10ms). Each include will pull more than 1 table's worth of data, it's joining one (or two if it's a many-to-many) tables worth of data. — Erik Philips, Sep 19 '13 at 18:58
I would recommend using Profiler to see how long the SQL EF generates executes. You can then execute that specific SQL by hand in SMSS and see what the execution plan looks like and see whats happening. If the plan is optimal, you may be running into a volume problem on the number of rows and columns, if you don't need all the columns I'd recommend using a `Select()` before the `ToList()` to reduce the number of columns returned. — Erik Philips, Sep 19 '13 at 19:04
In SSMS by hand, it is near instantaneous. I realize that the .ToList() is responsible for making the query actually execute and go fetch data, but I am a bit mystified as to why the actual construction of the query itself is taking 8 seconds. Since the .ToList() is about 1 second (which is much slower than expected), why does the query construction that happens behave so slowly? In the SQL profiler, the query executes in a few ms. — Bill Sambrone, Sep 19 '13 at 19:19
There is a good amount of missing information here that I don't know. I'll assume Sql-Server. Also I've never seen anyone query against [DbSet](http://msdn.microsoft.com/en-us/library/system.data.entity.dbset(v=vs.103).aspx) that is particularly strange, usually it's [DbContext](http://msdn.microsoft.com/en-us/library/system.data.entity.dbcontext(v=vs.103).aspx).Iventory_Base. I don't know what your EDMX file looks like nor your database. My experience has been very good querying. — Erik Philips, Sep 19 '13 at 19:36
I just tested my own query (4 includes including a include on an include) which has 1 Union that each have 4 joins and 2 subquerys each. A total of 183 records, 66 columns takes 155ms to Run the Query and Materialized into c# object classes. Sql Server is running on a Virtual Machine on the same computer I am debugging on. — Erik Philips, Sep 19 '13 at 19:41
No EDMX file, I did code first against an existing database. From reading a few other SO questions regarding EF query compilation, I think I might need the EDMX file. It is MS-SQL Server. In my repository class I have a .Find method that runs against the DbSet - but i'm open to a different way of querying. — Bill Sambrone, Sep 19 '13 at 19:42
But you do have a [DbContext](http://msdn.microsoft.com/en-us/library/system.data.entity.dbcontext(v=vs.103).aspx) right (I don't do Code First and it shouldn't matter at all)? — Erik Philips, Sep 19 '13 at 19:42
Yep, I have a ReportinDbContext : DbContext in which I have all my DbSet's defined. This is instantiated through my UnitOfWork, which in turn exposes my repositories. My FindClientHardware method is a fancy version of the basic Find(Expression> predicate) in my generic repository class. — Bill Sambrone, Sep 19 '13 at 19:45
let us [continue this discussion in chat](http://chat.stackoverflow.com/rooms/37693/discussion-between-erik-philips-and-bill-sambrone) — Erik Philips, Sep 19 '13 at 21:40

score 4 · Accepted Answer · edited May 23 '17 at 11:45

Got it! The core problem was the whole cold query thing. How to get around this cold query issue? By making a query. This will "warm up" EntityFramework so that subsequent query compilation is much faster. My pre-generated views did nothing to help with the query I was compiling in this question, but they do seem to work if I want to dump an entire table to an array (a bad thing). Since I am using WCF which is stateless, will I have to "warm up" EF for every single call? Nope! Since EF lives in the app domain and not the context, I just to need to do my warm up on the init of the service. For dev purposes I self host, but in production it lives in IIS.

To do the query warm up, I made a service behavior that takes care of this for me. Create your behavior class as such:

using System;
using System.Collections.ObjectModel;
using System.ServiceModel;
using System.ServiceModel.Channels; // for those without resharper, here are the "usings"
using System.ServiceModel.Description;

public class InitializationBehavior : Attribute, IServiceBehavior 
{
    public InitializationBehavior()
    {

    }

    public void Validate(ServiceDescription serviceDescription, ServiceHostBase serviceHostBase)
    {

    }

    public void AddBindingParameters(ServiceDescription serviceDescription, ServiceHostBase serviceHostBase, Collection<ServiceEndpoint> endpoints,
                                     BindingParameterCollection bindingParameters)
    {
        Bootstrapper.WarmUpEF();
    }

    public void ApplyDispatchBehavior(ServiceDescription serviceDescription, ServiceHostBase serviceHostBase)
    {

    }
}

I then used this to do the warmup:

  public static class Bootstrapper
  {
    public static int initialized = 0;

    public static void WarmUpEF()
    {            
        using (var context = new ReportingDbContext())
        {
            context.Database.Initialize(false);
        }
        initialized = 9999; // I'll explain this
    }
}

This SO question helped with the warmup code: How do I initialize my Entity Framework queries to speed them up?

You then slap this behavior on your WCF service like so:

   [InitializationBehavior]
   public class InventoryService : IInventoryService 
   {
     // implement your service
   }

I launched my services project in debug mode which in turn fired up the initialization behavior. After spamming the method that makes the query referenced in my question, my breakpoint in the behavior wasn't being hit (other than being hit when I first self hosted it). I verified that it was it by checking out the static initialized variable. I then published this bad boy into IIS with my verification int and it had the exact same behavior.

So, in short, if you are using Entity Framework 5 with a WCF service and don't want a crappy first query, warm it up with a service behavior. There are probably other/better ways of doing this, but this way works too!

edit:
If you are using NUnit and want to warm up EF for your unit tests, setup your test as such:

[TestFixture]
public class InventoryTests
{

    [SetUp]
    public void Init()
    {
        // warm up EF.
        using (var context = new ReportingDbContext())
        {
            context.Database.Initialize(false);
        }
        // init other stuff
    }

  // tests go here
}

First query is slow and pre-generated views aren't being hit (probably)

1 Answers1