Jul 02 2012

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.

4 Comments

  • By Brian Winder, July 9, 2012 @ 7:06 am

    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.

  • By ahperez, July 9, 2012 @ 11:02 am

    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.

  • By Robert L Davis, July 12, 2012 @ 11:11 am

    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;

  • By Robert L Davis, July 12, 2012 @ 11:49 am

    To be clear, on my laptop, your solution using the text query plan runs in 3 seconds, so the exist() method is only slightly faster.

Other Links to this Post

RSS feed for comments on this post. TrackBack URI

Leave a comment