Querying Information from the Plan Cache, Simplified

Home / SQL Server 2005 / Querying Information from the Plan Cache, Simplified

One of the great things about the Dynamic Management Objects (DMOs) that expose the information in plan cache is that, by their very nature, they can be queried. The plans exposed are in XML format, so you can run XQuery against them to pull out interesting information.

For example, what if you wanted to see all the plans in cache that had a Timeout as the reason for early termination from the optimizer? It’d be great way to see which of your plans were less than reliable. You could so like this:

WITH XMLNAMESPACES(DEFAULT N'http://schemas.microsoft.com/sqlserver/2004/07/showplan'),  QueryPlans 
AS  ( 
SELECT  RelOp.pln.value(N'@StatementOptmEarlyAbortReason', N'varchar(50)') AS TerminationReason, 
        RelOp.pln.value(N'@StatementOptmLevel', N'varchar(50)') AS OptimizationLevel, 
        --dest.text, 
        SUBSTRING(dest.text, (deqs.statement_start_offset / 2) + 1, 
                  (deqs.statement_end_offset - deqs.statement_start_offset) 
                  / 2 + 1) AS StatementText, 
        deqp.query_plan, 
        deqp.dbid, 
        deqs.execution_count, 
        deqs.total_elapsed_time, 
        deqs.total_logical_reads, 
        deqs.total_logical_writes 
FROM    sys.dm_exec_query_stats AS deqs 
        CROSS APPLY sys.dm_exec_sql_text(deqs.sql_handle) AS dest 
        CROSS APPLY sys.dm_exec_query_plan(deqs.plan_handle) AS deqp 
        CROSS APPLY deqp.query_plan.nodes(N'//StmtSimple') RelOp (pln) 
WHERE   deqs.statement_end_offset > -1        
)   
SELECT  DB_NAME(qp.dbid), 
        * 
FROM    QueryPlans AS qp 
WHERE   qp.TerminationReason = 'Timeout' 
ORDER BY qp.execution_count DESC ;

 

I posted a similar version of this query once before (although, I think that one is a little broken). It works fine… But…

This query takes 25 seconds. A big chunk of that is parsing the XML. What if, for a simple query like there, where I’m not doing a lot of conversion & processing with the XML, we ignored it and went instead to something like this:

SELECT  DB_NAME(deqp.dbid), 
        SUBSTRING(dest.text, (deqs.statement_start_offset / 2) + 1, 
                  (CASE deqs.statement_end_offset 
                     WHEN -1 THEN DATALENGTH(dest.text) 
                     ELSE deqs.statement_end_offset 
                   END - deqs.statement_start_offset) / 2 + 1) AS StatementText, 
        deqs.statement_end_offset, 
        deqs.statement_start_offset, 
        deqp.query_plan, 
        deqs.execution_count, 
        deqs.total_elapsed_time, 
        deqs.total_logical_reads, 
        deqs.total_logical_writes 
FROM    sys.dm_exec_query_stats AS deqs 
        CROSS APPLY sys.dm_exec_query_plan(deqs.plan_handle) AS deqp 
        CROSS APPLY sys.dm_exec_sql_text(deqs.sql_handle) AS dest 
WHERE   CAST(deqp.query_plan AS NVARCHAR(MAX)) LIKE '%StatementOptmEarlyAbortReason="TimeOut"%';

 

Now, we’re no longer hooked into getting the XML parsed. But, surprisingly, performance is not much better, sometimes worse in my tests. It probably has something to do with performing a function on a column, the CAST of the query_plan column from XML to NVARCHAR(MAX). What can you do?

Well, there is one other place where execution plans are kept, sys.dm_exec_text_query_plan. Things are a little different in there. Instead of a plan with multiple statements in it, each of these plans is for an individual statement. This is why you must pass in the start & end offsets to call the query. That changes the result sets, a little. You get fewer rows back, but, you also get a lot less duplication, and, we don’t have to cast anything in the WHERE clause. Let’s check it out:

SELECT  DB_NAME(detqp.dbid), 
        SUBSTRING(dest.text, (deqs.statement_start_offset / 2) + 1, 
                  (CASE deqs.statement_end_offset 
                     WHEN -1 THEN DATALENGTH(dest.text) 
                     ELSE deqs.statement_end_offset 
                   END - deqs.statement_start_offset) / 2 + 1) AS StatementText, 
        CAST(detqp.query_plan AS XML), 
        deqs.execution_count, 
        deqs.total_elapsed_time, 
        deqs.total_logical_reads, 
        deqs.total_logical_writes 
FROM    sys.dm_exec_query_stats AS deqs 
        CROSS APPLY sys.dm_exec_text_query_plan(deqs.plan_handle, 
                                                deqs.statement_start_offset, 
                                                deqs.statement_end_offset) AS detqp 
        CROSS APPLY sys.dm_exec_sql_text(deqs.sql_handle) AS dest 
WHERE   detqp.query_plan LIKE '%StatementOptmEarlyAbortReason="TimeOut"%';

 

Performance on my system dropped from 30 seconds on average to 8 seconds on average. That’s a win by any measure. If you worked on a way to eliminate that wild card LIKE search, it would be even better. Note line 7 above. To be able to click on the query_plan column and see a pretty graphical execution plan, I just have to CAST the text to XML, but that’s not adding to the overhead of the query.

If you’re looking to search within your query plans, you’re still likely to be better off using XQuery to get sophisticated searches on the data, but for really simple stuff, using the sys.dm_exec_text_query_plan may offer you a faster alternative.

12 Comments

  • Brian Winder

    More info here: http://www.sqlservercentral.com/articles/Performance+Tuning/66729/

    Get Performance Tips Directly From SQL Server
    By Ian Stirk, 2012/06/22 (first published: 2009/06/11)

    Introduction
    When SQL is compiled, an ‘optimal’ plan is created and stored in the plan cache, the plan contains details of table and index access. To produce this plan, the optimiser uses information from various sources, including indexes, statistics and row counts.

    If the optimiser would like to use certain information but can’t find it, it adds details of what it wanted to use to the plan. Inspecting the plans for these details will help us improve the performance of our SQL.

    For example, if a certain index could have been useful for a given SQL statement, the optimiser looks for that index, if that index is not found, the missing index’s details are stored together with the plan.

    There are various performance related items we can search for including: missing indexes, columns with no statistics, and the occurrence of table scans.

    This utility makes use of Dynamic Management Views (DMVs) and Dynamic Management Functions (DMFs), so can be used by SQL Server 2005 or greater.

  • ahperez

    What a great way to peek at the plan cache for poorly performing queries. Lets me see how to tune queries my more-programmer-than-DBA colleague is running.

  • This version takes about 2 seconds on my laptop and is a purely XML solution:

    WITH XMLNAMESPACES (‘http://schemas.microsoft.com/sqlserver/2004/07/showplan’ AS sqlx)
    SELECT DB_NAME(deqp.dbid),
    SUBSTRING(dest.text, (deqs.statement_start_offset / 2) + 1,
    (CASE deqs.statement_end_offset
    WHEN -1 THEN DATALENGTH(dest.text)
    ELSE deqs.statement_end_offset
    END – deqs.statement_start_offset) / 2 + 1) AS StatementText,
    deqs.statement_end_offset,
    deqs.statement_start_offset,
    deqp.query_plan,
    deqs.execution_count,
    deqs.total_elapsed_time,
    deqs.total_logical_reads,
    deqs.total_logical_writes
    FROM sys.dm_exec_query_stats AS deqs
    CROSS APPLY sys.dm_exec_query_plan(deqs.plan_handle) AS deqp
    CROSS APPLY sys.dm_exec_sql_text(deqs.sql_handle) AS dest
    WHERE deqp.query_plan.exist(‘//sqlx:StmtSimple[@StatementOptmEarlyAbortReason=”TimeOut”]’) = 1;

  • Grant

    When i run the above query i get this error how we can fix this so that i can get the result

    Msg 6335, Level 16, State 102, Line 1
    XML datatype instance has too many levels of nested nodes. Maximum allowed depth is 128 levels.

  • That happens during the CAST of the XML. It means you have a very large execution plan. Take the CAST off the query and it will work. You’ll need to save the XML out to a .SQLPLAN file to be able to open it.

  • Marcelo Moraes

    Hi Grant.

    I received a task here to develop a scheduled job to look inside plan cache to find plans with Index/Table Scan.

    I took a look at the web in order to try to learn and understand if it is possible and, if so, how to do it.

    I’m not familiar with this kind of advanced code, so I found one and tried to make some customs.

    The final script does work and return what I need, but it is running for sometimes more than 5 minutes.

    Could you or anyone on this thread, help me to otimize or re-write this code to get a better performance?

    This is the script:

    CREATE TABLE #TEMPTABLE
    (
    [NAME] NVARCHAR(128),
    [ROWS] CHAR(11),
    RESERVED VARCHAR(18),
    DATA VARCHAR(18),
    INDEX_SIZE VARCHAR(18),
    UNUSED VARCHAR(18)
    )
    INSERT #TEMPTABLE EXEC SP_MSFOREACHTABLE ‘EXEC SP_SPACEUSED ”?”’
    SELECT REPLACE([NAME],'[dbo].’,”) AS [NAME], [ROWS],
    CAST(REPLACE(RESERVED, ‘ KB’,”) AS INT) AS RESERVED,
    CAST(REPLACE(DATA, ‘ KB’,”) AS INT) AS DATA,
    CAST(REPLACE(INDEX_SIZE, ‘ KB’,”) AS INT) AS INDEX_SIZE,
    CAST(REPLACE(UNUSED, ‘ KB’,”) AS INT) AS UNUSED
    INTO #FINALTABLE
    FROM #TEMPTABLE
    — INDEXING TEMP TABLE
    CREATE NONCLUSTERED INDEX IX_TMP ON #FINALTABLE ([NAME]) INCLUDE (RESERVED)
    — MAIN CTE
    WITH XMLNAMESPACES(DEFAULT N’http://schemas.microsoft.com/sqlserver/2004/07/showplan’),
    CachedPlans
    (DatabaseName,SchemaName,ObjectName,PhysicalOperator, LogicalOperator, QueryText,QueryPlan, CacheObjectType, ObjectType, ExecutionCount
    ,MinGrant_MB,MaxGrant_MB,LastExecutionTime,LastElapsedTimeSec,MaxElapsedTimeSec,MinElapsedTimeSec,AVGElapsedTimeSec,LastLogicalReads
    ,MaxLogicalReads,MinLogicalReads,LastLogicalWrites,MaxLogicalWrites,MinLogicalWrites)
    AS
    (
    SELECT
    Coalesce(RelOp.op.value(N’TableScan[1]/Object[1]/@Database’, N’varchar(50)’) ,
    RelOp.op.value(N’OutputList[1]/ColumnReference[1]/@Database’, N’varchar(50)’) ,
    RelOp.op.value(N’IndexScan[1]/Object[1]/@Database’, N’varchar(50)’) ,
    ‘Unknown’
    )
    as DatabaseName,
    Coalesce(
    RelOp.op.value(N’TableScan[1]/Object[1]/@Schema’, N’varchar(50)’) ,
    RelOp.op.value(N’OutputList[1]/ColumnReference[1]/@Schema’, N’varchar(50)’) ,
    RelOp.op.value(N’IndexScan[1]/Object[1]/@Schema’, N’varchar(50)’) ,
    ‘Unknown’
    )
    as SchemaName,
    Coalesce(
    RelOp.op.value(N’TableScan[1]/Object[1]/@Table’, N’varchar(50)’) ,
    RelOp.op.value(N’OutputList[1]/ColumnReference[1]/@Table’, N’varchar(50)’) ,
    RelOp.op.value(N’IndexScan[1]/Object[1]/@Table’, N’varchar(50)’) ,
    ‘Unknown’
    )
    as ObjectName,
    RelOp.op.value(N’@PhysicalOp’, N’varchar(50)’) as PhysicalOperator,
    RelOp.op.value(N’@LogicalOp’, N’varchar(50)’) as LogicalOperator,
    st.text as QueryText,
    qp.query_plan as QueryPlan,
    cp.cacheobjtype as CacheObjectType,
    cp.objtype as ObjectType,
    qs.execution_count,
    (qs.min_grant_kb)/1024,
    (qs.max_grant_kb)/1024,
    qs.last_execution_time,
    qs.last_elapsed_time / 1000000,
    qs.max_elapsed_time / 1000000,
    qs.min_elapsed_time / 1000000,
    (qs.total_elapsed_time / qs.execution_count) / 1000000,
    qs.last_logical_reads,
    qs.max_logical_reads,
    qs.min_logical_reads,
    qs.last_logical_writes,
    qs.max_logical_writes,
    qs.min_logical_writes
    FROM
    sys.dm_exec_cached_plans cp
    CROSS APPLY sys.dm_exec_sql_text(cp.plan_handle) st
    CROSS APPLY sys.dm_exec_query_plan(cp.plan_handle) qp
    CROSS APPLY qp.query_plan.nodes(N’//RelOp’) RelOp (op)
    JOIN sys.dm_exec_query_stats qs on cp.plan_handle = qs.plan_handle
    )
    SELECT
    DatabaseName,SchemaName,ObjectName,PhysicalOperator, LogicalOperator, QueryText,CacheObjectType, ObjectType, QueryPlan,ExecutionCount
    ,MinGrant_MB,MaxGrant_MB,LastExecutionTime,LastElapsedTimeSec,MaxElapsedTimeSec,MinElapsedTimeSec,AVGElapsedTimeSec,LastLogicalReads
    ,MaxLogicalReads,MinLogicalReads,LastLogicalWrites,MaxLogicalWrites,MinLogicalWrites
    FROM
    CachedPlans
    INNER JOIN #FINALTABLE FT ON CachedPlans.ObjectName = FT.NAME
    WHERE
    CachedPlans.ObjectType in (‘Adhoc’,’Prepared’)
    AND CacheObjectType = N’Compiled Plan’
    AND (PhysicalOperator = ‘Clustered Index Scan’ or PhysicalOperator = ‘Table Scan’ or PhysicalOperator = ‘Index Scan’)
    AND ExecutionCount > 1000 — MIN QTD EXECUTIONS
    AND LastExecutionTime BETWEEN dateadd(minute, -5, getdate()) AND GETDATE() — WINDOW TO COLLECT
    AND FT.RESERVED > 10240 — SIZE IN MB
    ORDER BY FT.RESERVED DESC
    DROP TABLE #FINALTABLE
    DROP TABLE #TEMPTABLE

  • First blush, quick suggestion, toss all the XML queries and see if you can do a LIKE search in the sys.dm_exec_text_query_plan. Here’s the documentation: https://docs.microsoft.com/en-us/sql/relational-databases/system-dynamic-management-views/sys-dm-exec-text-query-plan-transact-sql

    I’m neck deep in some stuff (and this is a holiday weekend, off to the in-laws), so it’ll be a while before I can try tuning anything myself. This is my best short-term advice.

    • Marcelo Moraes

      Thank you so much for the advice. I’ll try to implemente something following your suggestion and I’ll let you know the results!

OK, fine, but what do you think?