SQL Query Using Entity Framework Runs Slower, uses bad query plan

Question

am using entity framework generally successfully, but one query is running remarkably slowly. The query (generated by EF) is as follows:

exec sp_executesql N'SELECT 
[Project1].[downtimeId] AS [downtimeId], 
CASE WHEN ([Extent12].[downtimeStart] > @p__linq__7) THEN [Extent13].[downtimeStart] ELSE @p__linq__8 END AS [C1], 
CASE WHEN ([Extent14].[equipmentID] IS NULL) THEN 0 ELSE [Extent15].[equipmentID] END AS [C2], 
CASE WHEN ([Extent16].[equipmentID] IS NULL) THEN N''Unit Overhead'' ELSE [Extent18].[equipmentCode] END AS [C3], 
CASE WHEN ( CAST( [Project1].[downtimeEquipmentStart] AS datetime2) > @p__linq__9) THEN  CAST( [Project1].[downtimeEquipmentStart] AS datetime2) ELSE @p__linq__10 END AS [C4], 
CASE WHEN ( CAST( [Project1].[downtimeEquipmentEnd] AS datetime2) < @p__linq__11) THEN  CAST( [Project1].[downtimeEquipmentEnd] AS datetime2) ELSE @p__linq__12 END AS [C5], 
CASE WHEN ([Extent19].[standardHourRate] IS NULL) THEN cast(0 as decimal(18)) ELSE [Extent20].[standardHourRate] END AS [C6], 
CASE WHEN ([Extent21].[equipmentID] IS NULL) THEN 0 ELSE [Filter2].[reportingSequence] END AS [C7]
FROM                    (SELECT 
    @p__linq__0 AS [p__linq__0], 
    [Extent1].[downtimeId] AS [downtimeId], 
    [Extent1].[equipmentID] AS [equipmentID], 
    [Extent1].[downtimeEquipmentStart] AS [downtimeEquipmentStart], 
    [Extent1].[downtimeEquipmentEnd] AS [downtimeEquipmentEnd]
    FROM [dbo].[DowntimeEquipment] AS [Extent1] ) AS [Project1]
OUTER APPLY  (SELECT [Extent2].[reportingSequence] AS [reportingSequence]
    FROM   [dbo].[ProcessUnitEquipment] AS [Extent2]
    INNER JOIN [dbo].[Downtime] AS [Extent3] ON [Extent3].[equipmentID] = [Extent2].[equipmentID]
    LEFT OUTER JOIN  (SELECT 
        [Extent4].[downtimeId] AS [downtimeId]
        FROM [dbo].[Downtime] AS [Extent4]
        WHERE [Project1].[downtimeId] = [Extent4].[downtimeId] ) AS [Project2] ON 1 = 1
    WHERE ([Project1].[downtimeId] = [Extent3].[downtimeId]) AND ([Extent2].[processUnitID] = @p__linq__0) AND (@p__linq__0 IS NOT NULL) ) AS [Filter2]
LEFT OUTER JOIN [dbo].[Downtime] AS [Extent5] ON [Project1].[downtimeId] = [Extent5].[downtimeId]
LEFT OUTER JOIN [dbo].[Downtime] AS [Extent6] ON [Project1].[downtimeId] = [Extent6].[downtimeId]
LEFT OUTER JOIN [dbo].[Downtime] AS [Extent7] ON [Project1].[downtimeId] = [Extent7].[downtimeId]
LEFT OUTER JOIN [dbo].[Downtime] AS [Extent8] ON [Project1].[downtimeId] = [Extent8].[downtimeId]
LEFT OUTER JOIN [dbo].[Downtime] AS [Extent9] ON [Project1].[downtimeId] = [Extent9].[downtimeId]
LEFT OUTER JOIN [dbo].[Downtime] AS [Extent10] ON [Project1].[downtimeId] = [Extent10].[downtimeId]
LEFT OUTER JOIN [dbo].[DownTimeType] AS [Extent11] ON [Extent10].[downTimeTypeId] = [Extent11].[downTimeTypeId]
LEFT OUTER JOIN [dbo].[Downtime] AS [Extent12] ON [Project1].[downtimeId] = [Extent12].[downtimeId]
LEFT OUTER JOIN [dbo].[Downtime] AS [Extent13] ON [Project1].[downtimeId] = [Extent13].[downtimeId]
LEFT OUTER JOIN [dbo].[Downtime] AS [Extent14] ON [Project1].[downtimeId] = [Extent14].[downtimeId]
LEFT OUTER JOIN [dbo].[Downtime] AS [Extent15] ON [Project1].[downtimeId] = [Extent15].[downtimeId]
LEFT OUTER JOIN [dbo].[Downtime] AS [Extent16] ON [Project1].[downtimeId] = [Extent16].[downtimeId]
LEFT OUTER JOIN [dbo].[Downtime] AS [Extent17] ON [Project1].[downtimeId] = [Extent17].[downtimeId]
LEFT OUTER JOIN [dbo].[Equipment] AS [Extent18] ON [Extent17].[equipmentID] = [Extent18].[equipmentID]
LEFT OUTER JOIN [dbo].[Equipment] AS [Extent19] ON [Project1].[equipmentID] = [Extent19].[equipmentID]
LEFT OUTER JOIN [dbo].[Equipment] AS [Extent20] ON [Project1].[equipmentID] = [Extent20].[equipmentID]
LEFT OUTER JOIN [dbo].[Downtime] AS [Extent21] ON [Project1].[downtimeId] = [Extent21].[downtimeId]
WHERE ([Extent5].[downtimeEnd] >= @p__linq__1) AND ([Extent6].[downtimeStart] < @p__linq__2) AND ([Project1].[downtimeEquipmentStart] < @p__linq__3) AND ([Project1].[downtimeEquipmentEnd] > @p__linq__4) AND ((([Extent7].[processUnitID] = @p__linq__5) AND ( NOT ([Extent8].[processUnitID] IS NULL OR @p__linq__5 IS NULL))) OR (([Extent9].[processUnitID] IS NULL) AND (@p__linq__5 IS NULL))) AND (@p__linq__6 = 1 OR [Extent11].[includeInDowntimeAnalysis] = 1)',N'@p__linq__0 int,@p__linq__1 datetime2(7),@p__linq__2 datetime2(7),@p__linq__3 datetime2(7),@p__linq__4 datetime2(7),@p__linq__5 int,@p__linq__6 bit,@p__linq__7 datetime2(7),@p__linq__8 datetime2(7),@p__linq__9 datetime2(7),@p__linq__10 datetime2(7),@p__linq__11 datetime2(7),@p__linq__12 datetime2(7)',@p__linq__0=1,@p__linq__1='2015-03-02 00:00:00',@p__linq__2='2015-05-09 00:00:00',@p__linq__3='2015-05-09 00:00:00',@p__linq__4='2015-03-02 00:00:00',@p__linq__5=1,@p__linq__6=1,@p__linq__7='2015-03-02 00:00:00',@p__linq__8='2015-03-02 00:00:00',@p__linq__9='2015-03-02 00:00:00',@p__linq__10='2015-03-02 00:00:00',@p__linq__11='2015-05-09 00:00:00',@p__linq__12='2015-05-09 00:00:00'

This was captured using the SQL Server Profiler. When I run this using SSMS query window, I get 8000+ rows in under 2 seconds. With set statistics io on, I see that it does about 16,000 logical reads.

When I see the same query coming from my website using EF, it times out after 30 seconds, having done over 1.4 million logical reads.

Using the profiler, I saw that both sessions had the following settings during login:

-- network protocol: TCP/IP
set quoted_identifier on
set arithabort off
set numeric_roundabort off
set ansi_warnings on
set ansi_padding on
set ansi_nulls on
set concat_null_yields_null on
set cursor_close_on_commit off
set implicit_transactions off
set language us_english
set dateformat mdy
set datefirst 7
set transaction isolation level read committed

Both queries are done using the same login and password.

I saw that SSMS was sending some sets to the server, so I added the following code to my C# EF application right before my query:

_context.Database.ExecuteSqlCommand(
"SET ROWCOUNT 0 
 SET TEXTSIZE 2147483647 
 SET NOCOUNT OFF 
 SET CONCAT_NULL_YIELDS_NULL ON 
 SET ARITHABORT ON 
 SET LOCK_TIMEOUT -1 
 SET QUERY_GOVERNOR_COST_LIMIT 0 
 SET DEADLOCK_PRIORITY NORMAL 
 SET TRANSACTION ISOLATION LEVEL READ COMMITTED 
 SET ANSI_NULLS ON 
 SET ANSI_NULL_DFLT_ON ON 
 SET ANSI_PADDING ON 
 SET ANSI_WARNINGS ON 
 SET CURSOR_CLOSE_ON_COMMIT OFF 
 SET IMPLICIT_TRANSACTIONS OFF 
 SET QUOTED_IDENTIFIER ON");

(carriage returns added for readability)

I hypothesize that the dates passed as arguments at the end of the query are being interpreted differently, forcing an implicit data type conversion when coming from the EF, but I don't know what to do about it.[Note from later edit: This is incorrect, and not the root of the problem]

Please don't tell me to make it a stored procedure.

The C# code is as follows:

           _context.Database.ExecuteSqlCommand(
            "SET ROWCOUNT 0 SET TEXTSIZE 2147483647 SET NOCOUNT OFF SET CONCAT_NULL_YIELDS_NULL ON SET ARITHABORT ON SET LOCK_TIMEOUT -1 SET QUERY_GOVERNOR_COST_LIMIT 0 SET DEADLOCK_PRIORITY NORMAL SET TRANSACTION ISOLATION LEVEL READ COMMITTED SET ANSI_NULLS ON SET ANSI_NULL_DFLT_ON ON SET ANSI_PADDING ON SET ANSI_WARNINGS ON SET CURSOR_CLOSE_ON_COMMIT OFF SET IMPLICIT_TRANSACTIONS OFF SET QUOTED_IDENTIFIER ON");
        DateTime sdate = startDate;
        var downtimeQueryRaw = from de in _context.DowntimeEquipments
                               join p in sequenceQuery
                                   on de.Downtime.equipmentID equals p.equipmentID into sequenceEquipments
                               from sequence in sequenceEquipments.DefaultIfEmpty()

                               where de.Downtime.downtimeEnd >= sdate &&
                                     de.Downtime.downtimeStart < workingEnd &&
                                     de.downtimeEquipmentStart < workingEnd &&
                                     de.downtimeEquipmentEnd > sdate &&
                                     de.Downtime.processUnitID == processUnitId &&
                                     (includeUncontrollable ||
                                      de.Downtime.DownTimeType.includeInDowntimeAnalysis)

                               select new DowntimeCostByEquipmentRaw
                               {
                                   DowntimeStart = ((de.Downtime.downtimeStart>sdate)
                                        ? de.Downtime.downtimeStart
                                        : sdate),
                                   EquipmentId = de.Downtime.equipmentID ?? 0,
                                   EquipmentCode =
                                       (de.Downtime.equipmentID == null 
                                            ? "Unit Overhead" 
                                            : de.Downtime.Equipment.equipmentCode),
                                   Start = ((((DateTime)de.downtimeEquipmentStart)>sdate)
                                            ?((DateTime)de.downtimeEquipmentStart)
                                            : sdate),
                                   End = ((((DateTime)de.downtimeEquipmentEnd) < workingEnd)
                                            ?((DateTime)de.downtimeEquipmentEnd)
                                            : workingEnd),
                                   StandardHourRate = de.Equipment.standardHourRate ?? 0,
                                   ReportingSequence = (de.Downtime.equipmentID == null ? 0 : sequence.reportingSequence)
                               };


        var downtimeList = downtimeQueryRaw.ToList();

See above for the query and the immediately surrounding code from the C#, per annemartijn request: — Glenn Gordon, May 21 '15 at 19:34
sounds like mine : http://stackoverflow.com/questions/30188589/ef-very-slow-from-a-view-in-certain-circumstances-prevent-ef-to-mimic-optionr. see last edit — tschmit007, May 21 '15 at 19:35
There is no conversion over the dates passed. As you can see on the last line of your SQL command: `N'@p__linq__0 int,@p__linq__1 datetime2(7)`. (These are the first two arguments passed as an int and **datetime**) — annemartijn, May 21 '15 at 19:40
See above: Arithabort is set on immediately before my query in the ExecuteSqlCommand in the c# example code. No performance enhancement provided. tschmit007 — Glenn Gordon, May 21 '15 at 19:41
i was thinking to `EXEC sp_updatestats` this solve my problem of performance difference between EF and SSMS — tschmit007, May 21 '15 at 19:43
annemartijn: I agree. It was the only thing that I could think of. Perhaps the strings in the argument list didn't convert nicely to dates. i.e.: @p__linq__1='2015-03-02 00:00:00' — Glenn Gordon, May 21 '15 at 19:44
tschmit007: I update statistics on all tables every Saturday night. I don't see how it could be appropriate in this case, since both queries are going against the same database, seconds apart, and one is working and one is not. — Glenn Gordon, May 21 '15 at 19:46
I was in the same case (except for the planification): same database, same query — tschmit007, May 21 '15 at 19:56
tschmit007: Do you have any reason to think that wrapping the arithabort in a transaction would matter? — Glenn Gordon, May 21 '15 at 20:46
It looks like classic parameter sniffing: http://sommarskog.se/query-plan-mysteries.html Read the article. It explains what ARITHABORT does, why it seems to help and how to figure out whether the problem is indeed caused by parameter sniffing. Since you already know how to use SQL Profiler it should be easy for you to extract execution plans from the cache for the query run by the app and for the query run by SSMS. The article explains it. — Vladimir Baranov, May 22 '15 at 04:10
@GlennGordon your problem is solved but please report this query to the EF team. There are like 10 redundant joins. This is a bug. Your query will go probably like 10x faster after that is fixed. — usr, May 24 '15 at 22:28
usr: I manually removed the redundant joins. Using Set Statistics io On, I saw that the number of reads on the DowntimeTable dropped from 16.143 logical + 0 read-ahead reads to 4554 logical+3182 read-ahead reads. While not 10x, I'll take what I can get. — Glenn Gordon, May 25 '15 at 17:18
@usr Microsoft was sanguine on the issue. They recommended doing an explicit join in my query, rather than relying on EF to figure it out. [editorial comment: EF works ever so much better if you think about the SQL that it is creating, but you knew that...] — Glenn Gordon, May 30 '15 at 03:22

score 7 · Accepted Answer · answered May 22 '15 at 18:11

The problem was a stale or incorrect query plan for my query.

I solved the problem for deleting the existing query plans for this query.

Thanks to Vladimir Baranov for pointing me at sommarskog.se/query-plan-mysteries.html. Thanks also to tschmit007 and annemartijn.

I had to identify the query plans for my query in the database using the following query:

SELECT qs.plan_handle, a.attrlist, est.dbid, text
FROM   sys.dm_exec_query_stats qs
CROSS  APPLY sys.dm_exec_sql_text(qs.sql_handle) est
CROSS  APPLY (SELECT epa.attribute + '=' + convert(nvarchar(127), epa.value) + '   '
          FROM   sys.dm_exec_plan_attributes(qs.plan_handle) epa
          WHERE  epa.is_cache_key = 1
          ORDER  BY epa.attribute
          FOR    XML PATH('')) AS a(attrlist)
 WHERE  est.text LIKE '%standardHourRate%' and est.text like '%q__7%'and est.text like '%Unit Overhead%'
 AND  est.text NOT LIKE '%sys.dm_exec_plan_attributes%'

This is a lightly modified version of the query from sommarskog's paper. Note that you have to put your own code in the like statements to find your query. This query responds with the attribute list and the plan handle for each query plan for my query.

I tried to figure out which plan came from SSMS and which from EF, so I deleted all of them, using the following syntax:

dbcc freeproccache([your plan handle here])

The new plan created for my EF query worked perfectly. Apparently, the EF plan did not take into consideration that I had updated statistics on the database recently. Unfortunately, I don't know how to do a sp_recompile for an EF query.

SQL Query Using Entity Framework Runs Slower, uses bad query plan

1 Answers1

Linked