none
Query VERY slow on upgrade to version 6.1.3 from version 5.0.0 RRS feed

  • Question

  • We have a released application using the entity framework 5.0.0 with SQL Server Express 2012. We are working on a new version of the app, and decided to upgrade SQL to 2014 and the Entity framework to 6.1.3. Now the first query to the database slows our application load time by 20 seconds!! Same unchanged code.

    This code section takes 5.4 seconds where RowId is the primary key. The small table has only 18 rows

    using (NxSummaryOnlyContainer db = new NxSummaryOnlyContainer()) { //select Top summary

        var tss = (from s in db.TxSummaries

                    orderby s.RowId descending // This will give us the Last Treatment First

                    select s).Take(1); //get only top row

            Mgr.AppLog.AddLogEntry("SQL Query complete");

    This code section takes 14 seconds to complete

            if ((tss != null) && (tss.Count() > 0)) {

                TxSummary ts = tss.First();

                Mgr.AppLog.AddLogEntry("SQL Get first");

    To further complicate matters we are and have been running this on a Windows 7 embedded system with File Base Write Filter (Drive lock) turned on. The SQL db is exempted. Same situation in release and no problems. In order to update the systems we are updating the drive image. Before doing this we export the sql and other data from SQL 2012 using bcp, then after reimaging we import the sql data into the SQL 2014 db. The code for that is below. We have tried running it initially with the drive lock off to see if that made a difference, but it didn't.

    I am not sure how to even find out the problem, much less fix it(except reverting to old versions). Any good ideas would be appreciated.

    ::Export NxView's SQL data from Sql Server 2012

    "%SQL%\bcp.exe" NxView.dbo.TxSummary out "%AppData%\TxSummary.txt" -c -T -S .\SQLEXPRESS

    if %errorlevel% NEQ 0 set exit=2

    "%SQL%\bcp.exe" NxView.dbo.TxDetail out "%AppData%\TxDetail.txt" -c -T -S .\SQLEXPRESS

    if %errorlevel% NEQ 0 set exit=3

    IMPORT DATA to SQL Server 2014

    ::Clear existing DB Without this -E would have to used in bcp import to handle the software managed foreign key and could cause corruption

    "%SQL%\SQLCMD.EXE" -S .\SQLEXPRESS -i "%~dp0\clear.sql"

    if %errorlevel% NEQ 0 set exit=6

    ::Import DB

    "%SQL%\bcp.exe" NxView.dbo.TxSummary in "%AppData%\TxSummary.txt" -c -T -S .\SQLEXPRESS

    if %errorlevel% NEQ 0 set exit=7

    "%SQL%\bcp.exe" NxView.dbo.TxDetail in "%AppData%\TxDetail.txt" -c -T -S .\SQLEXPRESS

    if %errorlevel% NEQ 0 set exit=8

    del /Q "%AppData%\TxSummary.txt"

    if %errorlevel% NEQ 0 set exit=9

    del /Q "%AppData%\TxDetail.txt"

    if %errorlevel% NEQ 0 set exit=10

    Tuesday, May 12, 2015 1:22 PM

All replies

  • UPDATE: If I run this(essentially the same query as above) - "C:\Program Files\Microsoft SQL Server\110\Tools\Binn\SQLCMD.EXE" -S .\SQLEXPRESS -Q "SELECT TOP 1 * FROM [NxView].[dbo].[TxSummary]" -o "C:\TxSummary.txt"  It finishes very quickly. This bypasses the Entity Framework, and would therefore imply the problem lies with the use of EF.
    Tuesday, May 12, 2015 2:00 PM
  • Hello Rich±,

    >>Now the first query to the database slows our application load time by 20 seconds!! Same unchanged code.

    Do you mean it just the first time query have a long time delay? If so, as far as I know, Entity Framework has a by designed feature - Cold query: The very first time any query is made against a given model, the Entity Framework does a lot of work behind the scenes to load and validate the model. However, there is workarounds for this scenario, for details, please check this link: https://msdn.microsoft.com/en-us/data/hh949853.aspx?f=255&MSPPError=-2147217396, it discusses performance considerations for Entity Framework 4, 5, and 6.

    If this does not help, please feel free to let me know.

    Regards.


    We are trying to better understand customer views on social support experience, so your participation in this interview project would be greatly appreciated if you have time. Thanks for helping make community forums a great place.
    Click HERE to participate the survey.

    Wednesday, May 13, 2015 2:02 AM
    Moderator
  • Update: First we ruled out SQL or our update process as being the source of the problem. It must be the EF.

    Fred, The links you provided on cold vs. warm queries shows only IMPROVEMENT or same performance from EF5 to EF6. We dropped from milliseconds query to 20 seconds query in the change from EF5 to EF6. That is insane. The performance stuff is interesting, but I don't see any of it making much difference here. The compiled query information indicates a 7% performance improvement. We are talking a performance loss in orders of magnitude. When querying a tiny database with only a few records, performance technique changes should be discussing milliseconds (as they are in that link), not going from 500ms to 20 seconds with the exact same code, but different framework. I would just go immediately back to EF5, but we upgraded to get the Transient SQL error handling.

    The answer to your question is yes. I tried a couple of user interface actions which cause a DB query after the application is loaded, and there is no indication of noticeable delays. Performance seems normal except for first load.

    I setup the database logger that was discussed on the link, combined with a little more of my own logging and here is the result.

    1.26 seconds to run the following line

    using (NxSummaryOnlyContainer db = new NxSummaryOnlyContainer()) {

    16ms to run the following line

    db.Database.Log = new Action<string>(x => Mgr.AppLog.AddLogEntry(x));

    about 4.6 seconds to run the following line

    var tss = (from s in db.TxSummaries

                orderby s.RowId descending

                select s).Take(1);

    1.3 seconds later the db log indicates it opened the connection

    12.8 seconds later the db logs the actual select statement it will run and it then completes the query in 25 ms. Then a few more milliseconds and it closes the connection

    It takes less than 1 ms to run the following line

    if ((tss != null) && (tss.Count() > 0)) {

    This next part I don’t understand why it does another query. Someone please explain how to avoid that. All I am trying to do is read a few values from the first row returned in a query ordered by the primary key descending (essentially it should be the last row in the database).

    The db the logs the unexpected open connection a few ms later, and then the sql text about a half second later. It completes the execution of the query in 4ms, and a few ms later closes the connection. All of that open, query, close, is to execute this line of code. I thought that only was looking at the result set already returned. Tss is an Iqueryable list of what I actually need. I can’t reference the column information of the item without somehow getting to the item in the list. I don’t know why an IQueryable.First is running database code.

    TxSummary ts = tss.First();

    The entire segment counting logging and everything is 20.797 seconds. Almost all of that is EF time.

    Wednesday, May 13, 2015 2:06 PM
  • Update: The same code on my dev machine(much more powerful) takes 2 seconds rather than 20. It is also using the same version of sql, and EF.
    Wednesday, May 13, 2015 2:57 PM
  • Hello Rich,

    >> Update: The same code on my dev machine(much more powerful) takes 2 seconds rather than 20. It is also using the same version of sql, and EF.

    This seems to be that the performance would be affected by the environment machine.

    I suggest you could customize you used Entity Framework version(since the source code is open, you could add your code into the solution) to add some log trace to detect which part(create the connection, execute the sql statement, fill data to memory collection type or others) cost a longer time comparing with Entity Framework 5.

    Regards.


    We are trying to better understand customer views on social support experience, so your participation in this interview project would be greatly appreciated if you have time. Thanks for helping make community forums a great place.
    Click HERE to participate the survey.

    Thursday, May 14, 2015 6:28 AM
    Moderator
  • "This seems to be that the performance would be affected by the environment machine. "

    Yes, a 3.1 GHz core i7 will perform faster than an Atom D525, but the query was performing quickly on the D525 for EF5.

    I have neither the time nor the inclination to find EF source code, add my 19 projects into its solution, spend time trying to get it all running, spend time trying to find where in the EF the problem, only to find that if I could make a fix in the EF, I would then have to spend more time testing, and testing to make sure I didn't mess anything else up, and then continue to support a customized version of EF. No I have things to do to actually add value to my product. I hope the EF team will have fixed this by EF7. I have seen many other complaints online about performance degradation in EF6. This should be very easy for the EF team to fix. One small table, querying on the primary key as above, and no foreign key relationships, no special contraints, just the simplest of tables and query. EF5 to EF6 major performance drop. I am reverting to EF5.

    Thursday, May 14, 2015 12:38 PM
  • Also no one answered why the query is happening twice, or how to avoid it.

    This hits the database once:

    var tss = (from s in db.TxSummaries

                orderby s.RowId descending

                select s).Take(1);

    then this hits the database again

    TxSummary ts = tss.First();

    Thursday, May 14, 2015 12:40 PM
  • >I don’t know why an IQueryable.First is running database code.

    Because queries are composable.  eg

    var q = from c in db.Customers select c;

    var q2 = from c in q where c.Name = "Jones" select c;

    var results = q2.ToList();

    will result in a single SQL query like

    SELECT * FROM CUSTOMERS WHERE NAME = 'Jones';

    >Also no one answered why the query is happening twice,

    Because you ran it twice.  The important thing to realize is that tss is a query, not a collection of query results.

    The expression:

    tss.Count()

    runs the query and produces a result.

    and the expression:

    tss.First()

    runs the query (again) and produces a result.

    >or how to avoid it.

    Keep your queries and your query results separate to avoid accidently running your queries multiple times. EG:

    var results = tss.ToList();

    David


    David http://blogs.msdn.com/b/dbrowne/


    Thursday, May 14, 2015 3:43 PM
  • The expression:

    tss.Count()

    runs the query and produces a result.

    and the expression:

    The log results did not indicate that. The query did not run again until *.First().

    We found out more information. Inexplicably An upgrade we did from .Net Framework 4.5 to 4.5.2 causes the same delay regardless of the EF. Yet, upgrading the EF from 5 to 6 causes the delay regardless of the .Net Framework. Just seems wrong. Still working on it

    Wednesday, May 20, 2015 5:33 PM
  • query.Count() and query.First() will execute different queries. 

    EG

                using (var db = new AdventureWorks2012Entities())
                {
                    db.Database.Log = (s) => Console.WriteLine(s);
                    var q = from dept in db.Departments select dept;
                    
                    var deptCount = q.Count();
                    var firstDept = q.First();    
                }

    outputs

    Opened connection at 5/20/2015 2:42:46 PM -05:00
    
    SELECT
        [GroupBy1].[A1] AS [C1]
        FROM ( SELECT
            COUNT(1) AS [A1]
            FROM [HumanResources].[Department] AS [Extent1]
        )  AS [GroupBy1]
    
    
    -- Executing at 5/20/2015 2:42:46 PM -05:00
    
    -- Completed in 28 ms with result: SqlDataReader
    
    
    
    Closed connection at 5/20/2015 2:42:47 PM -05:00
    
    Opened connection at 5/20/2015 2:42:47 PM -05:00
    
    SELECT TOP (1)
        [c].[DepartmentID] AS [DepartmentID],
        [c].[Name] AS [Name],
        [c].[GroupName] AS [GroupName],
        [c].[ModifiedDate] AS [ModifiedDate]
        FROM [HumanResources].[Department] AS [c]
    
    
    -- Executing at 5/20/2015 2:42:47 PM -05:00
    
    -- Completed in 13 ms with result: SqlDataReader
    
    
    
    Closed connection at 5/20/2015 2:42:47 PM -05:00

    David


    David http://blogs.msdn.com/b/dbrowne/



    Wednesday, May 20, 2015 7:48 PM