Change in query plan and execution time with TOP and ESCAPE

Question

One of the query (given below) is taking 90+ seconds to execute. It returns ~500 rows from a rather large table LogMessage. If ESCAPE N'~' is removed from the query it executes within few seconds. Similarly if TOP (1000) is removed, it executes within few seconds. The query plan shows Key Lookup (Clustered) PK_LogMessage, Index Scan (NonClustered) IX_LogMessage and Nested Loops (Inner Join) in the first case. When the clauses ESCAPE N'~' or TOP (1000) are removed the query plan changes and shows Clustered Index Scan (Clustered) PK_LogMessage. While we are looking into adding more indexes (probably on ApplicationName), we would like to understand what is going on currently.

The query is being generated from Entity Framework in case you wonder why it is being written this way. Also the actual query is more complex but this is the shortest possible version that exhibits the same behavior.

Query:

SELECT TOP (1000) 
    [Project1].[MessageID] AS [MessageID], 
    [Project1].[TimeGenerated] AS [TimeGenerated], 
    [Project1].[SystemName] AS [SystemName], 
    [Project1].[ApplicationName] AS [ApplicationName]
FROM
    (
        SELECT
            [Project1].[MessageID] AS [MessageID],
            [Project1].[TimeGenerated] AS [TimeGenerated],
            [Project1].[SystemName] AS [SystemName],
            [Project1].[ApplicationName] AS [ApplicationName]
        FROM
        (
            SELECT 
                [Extent1].[MessageID] AS [MessageID], 
                [Extent1].[TimeGenerated] AS [TimeGenerated], 
                [Extent1].[SystemName] AS [SystemName], 
                [Extent1].[ApplicationName] AS [ApplicationName]
            FROM
                [dbo].[LogMessage] AS [Extent1]
            INNER JOIN
                [dbo].[LogMessageCategory] AS [Extent2]
            ON
                [Extent1].[CategoryID] = [Extent2].[CategoryID]
            WHERE
                ([Extent1].[ApplicationName] LIKE N'%tier%' ESCAPE N'~')
        )  AS [Project1]
    )  AS [Project1]
ORDER BY
    [Project1].[TimeGenerated] DESC

Table LogMessage:

CREATE TABLE [dbo].[LogMessage](
    [MessageID] [int] IDENTITY(1000001,1) NOT NULL,
    [TimeGenerated] [datetime] NOT NULL,
    [SystemName] [nvarchar](256) NOT NULL,
    [ApplicationName] [nvarchar](512) NOT NULL,
        [CategoryID] [int] NOT NULL,
 CONSTRAINT [PK_LogMessage] PRIMARY KEY CLUSTERED 
(
    [MessageID] ASC
)WITH (PAD_INDEX  = OFF, STATISTICS_NORECOMPUTE  = OFF, IGNORE_DUP_KEY = OFF,
    ALLOW_ROW_LOCKS  = ON, ALLOW_PAGE_LOCKS  = ON, FILLFACTOR = 90) ON [PRIMARY]
) ON [PRIMARY]

ALTER TABLE [dbo].[LogMessage]  WITH CHECK ADD CONSTRAINT [FK_LogMessage_LogMessageCategory] FOREIGN KEY([CategoryID])
    REFERENCES [dbo].[LogMessageCategory] ([CategoryID])

ALTER TABLE [dbo].[LogMessage] CHECK CONSTRAINT [FK_LogMessage_LogMessageCategory]

ALTER TABLE [dbo].[LogMessage] ADD  DEFAULT ((100)) FOR [CategoryID]

CREATE NONCLUSTERED INDEX [IX_LogMessage] ON [dbo].[LogMessage] 
(
    [TimeGenerated] DESC
)WITH (PAD_INDEX  = OFF, STATISTICS_NORECOMPUTE  = OFF, SORT_IN_TEMPDB = OFF,
    IGNORE_DUP_KEY = OFF, DROP_EXISTING = OFF, ONLINE = OFF, ALLOW_ROW_LOCKS  = ON,
    ALLOW_PAGE_LOCKS  = ON, FILLFACTOR = 90) ON [PRIMARY]

Table LogMessageCategory:

CREATE TABLE [dbo].[LogMessageCategory](
    [CategoryID] [int] NOT NULL,
    [Name] [nvarchar](128) NOT NULL,
    [Description] [nvarchar](256) NULL,
 CONSTRAINT [PK_LogMessageCategory] PRIMARY KEY CLUSTERED 
(
    [CategoryID] ASC
)WITH (PAD_INDEX  = OFF, STATISTICS_NORECOMPUTE  = OFF, IGNORE_DUP_KEY = OFF, ALLOW_ROW_LOCKS  = ON, ALLOW_PAGE_LOCKS  = ON) ON [PRIMARY]
) ON [PRIMARY]

Query Plan 1 (takes 90+ seconds)

Query Plan 2 (takes ~3 seconds)

Answer 1

This looks like a straight forward parameter sniffing issue to me.

As you want the TOP 1000 ordered by TimeGenerated SQL Server can either scan down the index on TimeGenerated and do lookups against the base table to evaluate the predicate on ApplicationName and stop when row 1,000 has been found or it can do a clustered index scan, find all rows matching the ApplicationName predicate and then do a TOP N sort of these.

SQL Server maintains statistics on string columns. The first plan is more likely to be chosen if it believes that many rows will end up matching the ApplicationName predicate however this plan isn't really suitable for re-use as a parameterised query as it can be catastrophically inefficient in the event that few rows match. If less than 1,000 match it will definitely need to do as many key lookups as there are rows in the table.

From testing this end I wasn't able to find any situation where adding or removing the redundant ESCAPE altered SQL Server's cardinality estimates. Of course changing the text of a parametrised query means that the original plan can't be used however and it needs to compile a different one which will likely be more suited for the specific value under current consideration.

Answer 2

Why all these nested queries?? The code below does the same job

        SELECT TOP(1000)
            [Extent1].[MessageID] AS [MessageID], 
            [Extent1].[TimeGenerated] AS [TimeGenerated], 
            [Extent1].[SystemName] AS [SystemName], 
            [Extent1].[ApplicationName] AS [ApplicationName]
        FROM
            [dbo].[LogMessage] AS [Extent1]
        INNER JOIN
            [dbo].[LogMessageCategory] AS [Extent2]
        ON
            [Extent1].[CategoryID] = [Extent2].[CategoryID]
        WHERE
            ([Extent1].[ApplicationName] LIKE N'%tier%' ESCAPE N'~')
        ORDER BY [Extent1].[TimeGenerated] DESC

Also i agree that ESCAPE N'~' could be ommited as i can find no reason to use it.