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();

Answer 1

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.