6

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 1 (takes 90+ seconds)

Query Plan 2 (takes ~3 seconds)

Query Plan 2 (takes ~3 seconds)

Martin Smith
  • 438,706
  • 87
  • 741
  • 845
amit_g
  • 30,880
  • 8
  • 61
  • 118
  • 1
    Can you post the exact code for execution plan 1 and 2? The plan does not seem to match the query posted. The query has a join to the LogMessageCategory table but that is not represented in the execution plan (should be an INNER JOIN). Also the LogMessage table does not have a CategoryID. – 8kb Jun 13 '11 at 18:13
  • I'm also confused by the ESCAPE usage. Typically ESCAPE is used to make a wildcard part of the search. For example, you would use LIKE '%50~%%' ESCAPE '~' to search for all strings that contain "50%". But your LIKE statement does not contain a '~' – 8kb Jun 13 '11 at 18:15
  • @8kb, this is the query plan displayed in SQLMS. – amit_g Jun 13 '11 at 18:34
  • @amit_g: Are you sure? For example, query plan 1 scans the non-clustered index IX_LogMessage and then does a bookmark lookup against the clustered index in LogMessage. That is the inner join in the execution plan. But the query you posted also joins to the LogMessageCategory table. This join is not represented in the execution plan. I noticed this when trying to reproduce the query on my system. If you take out the INNER JOIN to LogMessageCategory, then the query plan matches what you have. – 8kb Jun 13 '11 at 18:40
  • Yes. Checked again. This is exactly what is displayed in the SQLMS. – amit_g Jun 13 '11 at 19:57
  • Have you tried dumping your second **select** statement into a #temp table first? Yes, you'll maybe have to go through more steps - perhaps processing through multiple temp tables, so that you get your **top** before using **escape**, but that'd cut your set down to size before performing the expensive operation. – David T. Macknet Jun 15 '11 at 09:32
  • 1
    @David, I want to understand what is going on here. This query is generated by EF and is much more complex than the one I have posted so there is not much we can do to it. The real question is why is it happening. Workarounds are not the problem. We will move the query to stored procedure and call that instead of letting EF generate it. – amit_g Jun 15 '11 at 16:19
  • I believe that the use of ESCAPE is being performed across the entire index, rather than against filtered results returned from the index - it's doing the equivalent of a full table-scan, rather than using the index seeking it should be doing. That's a guess - without delving into the implementation of ESCAPE, I couldn't say any more, but that's what it looks like from the query plan. – David T. Macknet Jun 27 '11 at 16:27
  • @amit-g - Are your actual queries parameterised? It may just be that removing the `ESCAPE` means that you get a new plan that is more suited to that particular search value with a leading wildcard. – Martin Smith Sep 22 '11 at 15:47
  • @Martin, yes the actual query is parametrized but the same behavior is observed. Also, the search value doesn't change the behavior, it is same for variety of values. – amit_g Sep 22 '11 at 16:10
  • @amit-g - The first plan looks as though it has been compiled for a value that is expected to be much more common than the second plan. What do the estimated number of rows vs actual number of rows say for the index scan on `IX_Log_Message` also check the compile time value for the parameters in the XML execution plan if you still have it. – Martin Smith Sep 23 '11 at 08:29
  • @8kb - Because there is a trusted Foreign Key constraint between the tables SQL Server can optimise this out. I presume you didn't bother creating the FK as the OP left out the `CategoryID` column from `LogMessage` in the `CREATE TABLE` script (I just added it in) – Martin Smith Sep 23 '11 at 09:37
  • @MartinSmith, there are ~50M total rows and ~10k of the specific value searched in the example (uniformly spread). When one of the more common values for this parameter are used, the query time reduces in both cases but the query plan is consistently the same, regardless of parameter value. – amit_g Oct 28 '11 at 22:08
  • @amit_g - That's expected because it will be compiled according to the parameter value passed in the first invocation then it will re-use the same plan for other invocations with different parameter values. If you select the left hand `SELECT` operator in the plan and view the properties window in SSMS it will tell you the value of the parameters the plan was compiled for. – Martin Smith Oct 28 '11 at 22:11
  • @MartinSmith, yes it makes sense. What doesn't makes sense is the query plan change due to innocuous inclusion or exclusion of "ESCAPE N'~'". – amit_g Oct 28 '11 at 22:15
  • @amit_g - Please check both plans as described above and confirm that they were compiled (or not) for the same parameter value. – Martin Smith Oct 28 '11 at 22:17
  • @MartinSmith, in the plan xml StmtSimple element has exact same StatementText. What else could I check? – amit_g Oct 28 '11 at 22:28
  • @amit_g - In the **actual** execution plan (not estimated). Look for the `ParameterList` section and the `ParameterCompiledValue` attribute. – Martin Smith Oct 28 '11 at 22:34
  • @MartinSmith, everything I have posted is the actual execution plan. I don't see any ParameterList section in the XML though. – amit_g Oct 28 '11 at 22:53

4 Answers4

2

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.

Martin Smith
  • 438,706
  • 87
  • 741
  • 845
  • Thanks for replying. This query is not in use and also now there are some more indexes on the table so I can't reproduce the exact same plan but the behavior of removing/adding "ESCAPE N'~'" still alters the plan (similar to the one shown above) and the query execution time (again not exactly what is posted above but relatively it is similar). – amit_g Oct 28 '11 at 22:00
1

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.

niktrs
  • 9,858
  • 1
  • 30
  • 30
  • The nested queries are generated by the entity framework, you might not agree with it but it's just the way the entity framework rolls. – Kane Jun 17 '11 at 10:23
  • that is not the point of this question. The real question is why the SQL Server is doing that kind of plan change and resulting performance with those two clauses. – amit_g Jun 17 '11 at 16:27
  • 1
    @Kane -- as @niktrs points out, the triple-nested sql is completely unnecessary. If you say that's just how entity framework rolls...that's kind of a sad answer to your own question then -- your problem is entity framework, not SQL-Server. I'd recommend re-tagging your question so you can (hopefully) get some better answers on how to tune EF so it generates better sql -- most importantly, getting rid of the nesting. – Chains Jul 06 '11 at 15:33
  • @kuru kuru pa - the execution plans shown in the OP indicate that SQL Server does a good job of ignoring the redundant nesting. – Martin Smith Sep 23 '11 at 09:23
0

For a start, I would simplify the query as specified by @niktrs. Even though the execution plan seems to be ignoring the sub-queries, it makes it more human friendly and thus easier to manipulate and understand.

Then, you have a INNER JOIN which seems to me like it could go away. Is there a 'real' need for INNER JOIN LogMessage to LogMessageCategory? You can do a quick check by using the following..

SELECT LM.CategoryID AS FromLogMessage, LMC.CategoryID AS FromLogMessageCategory
FROM dbo.LogMessage AS LM
     FULL OUTER JOIN dbo.LogMessageCategory AS LMC ON LMC.CategoryID = LM.CategoryID
WHERE LM.CategoryID IS NULL OR LMC.CategoryID IS NULL
DanielM
  • 939
  • 6
  • 4
-1

How does it run if you do this ?

Select * 
FROM
 (your whole scary framework query with the escape N) a
LIMIT 1000 
(or the mssql alternative if mssql does not support the correct syntax -- )

Because if that rolls .. there's a chance you could keep on using that framework and get decent performance out of really bad sql (like ... this would imply you create the full rs and then only select 1k from it ... ).

Morg.
  • 697
  • 5
  • 7