Fotia Ltd

Fotia Ltd

Thursday, 29 June 2006

Dynamic Management Views Part II

posted by Stefan Delmarco

In this instalment we'll be looking at a single DMV. This DMV provides such a wealth of information that it will take quite a few passes to cover it in depth. If anything, this DMV will make detecting and troubleshooting poorly performing queries something that can be easily done rather than requiring specialised, and potentially performance damaging tools like Profiler. The problem with Profiler is that it is great for debugging and dissecting SQL Server requests in a controlled environment (such as your development or test environment). It isn't good at running perpetually in a production environment, logging every single query that is executed, with its query plan and runtime statistics. Firstly, the amount of data it would generate for even a modest enterprise-level application would be unmanageable. Secondly, depending on what events are being captured and their frequency, the performance of SQL Server could be adversely affected. I'm not saying that SQL Profiler shouldn't be used in a production environment to assist with investigating and diagnosing a specific issue. Rather, it can't be used by the DBA's to monitor the overall performance of SQL Server, so that they can look for potentially troublesome queries, and be proactive in the detection of performance issues. This task normally falls on the middle-tier / application code to log execution times or update custom performance counters. Even then, it is normally support engineers that look at these logs rather than the DBAs.

In SQL Server 2005 we now have the sys.dm_exec_query_stats DMV. This view contains a row for each query plan in SQL Server's query plan cache. SQL Server is built on the principle that you prepare a query plan once and execute it many times. Caching of the query plan is central to the architecture of SQL Server. Exposing this core part of the internal architecture really means that there are no more secrets!

So, what can we see in this DMV? Firstly, we can obtain a handle to the query plan's TSQL text. In SQL Server 2000 we had to use DBCC INPUTBUFFER or the ::fn_get_sql function (which has now been marked as to-be-deprecated) to be able to see what TSQL a session was executing.

Even then DBCC INPUTBUFFER just showed the last statement executed and ::fn_get_sql only returned the TSQL as it was executing. Neither provided any kind of insight into the actual content of the query plan cache. The only way I knew of was to take a crash dump of the SQL Server process and dissect the dump using Microsoft PSS tools that understood SQL Server's memory layout.

To have a look at every TSQL statement in the query plan cache, execute the following query over the sys.dm_exec_query_stats DMV:

select db_name(sql_text.dbid) as [Database],
    case db_id()
        when sql_text.dbid then object_name(sql_text.objectid)
        else cast(sql_text.objectid as sysname) end as [Object],
    sql_text.text as [TSQL]
from sys.dm_exec_query_stats
    cross apply sys.dm_exec_sql_text(sql_handle) as sql_text;

If you don't see any rows returned, execute this query twice and you'll see the query above appear in the cache! If you see too many rows use DBCC FREEPROCCACHE to empty out the query plan cache.

There are a couple of things in this query you might not have seen before. For example, the APPLY operator is new. We'll look at it in detail in another article but for now just think of it as an inner join from a query to a table-valued function. The table-valued function will be invoked for each row in the query. If the table valued function returns multiple rows a query row, the query row will be returned multiple times (as you'd expect from an inner join).

The CROSS APPLY is taking each sql_handle in the sys.dm_exec_query_stats DMV and uses the sys.dm_exec_sql_text function to return the database, object id and text of the query plan. The case logic is there just to turn the objectid into its object name if the current database is the same as object's database.

OK, so this is all very interesting, but how does this help me see what the performance of these queries is like? Well, for each query plan, SQL Server will maintain an aggregate of:

  • The number of times query plan has been recompiled (find all your SPs containing temp tables here!)
  • A handle to the query plan (we'll look at this in depth later).
  • The last time the query was executed.
  • The number of times it has been executed (how easy is it to spot the most used queries now?!).
  • The total amount of the following resources consumed by all invocations of the query plan as well as the least and greatest amount of CPU consumed by a single invocation of the query plan:
    • CPU
    • Physical Reads
    • Logical Writes
    • Logical Reads
    • CLR Time (if you use CLR in SQL you'd be able to easily spot a performance problem with it!)
    • Elapsed Time

Wow! Christmas definitely came early this year! This mind boggles at the variety of queries that could be constructed to slice and dice this aggregated data. When digging into the TSQL note that the query plan may only be for a fragment of the TSQL text. You need to use the statement_start_offset and statement_end_offset values to find the chunk. Use this helper function to extract the TSQL fragment:

create function dbo.GetTSQLFragment (
    @tsql nvarchar(max),
    @start_offset int,
    @end_offset int) returns nvarchar(max)
with execute as caller
as begin
    declare @len int;
    set @len = (case
        when @end_offset = -1 then len(@tsql) * 2
        else @end_offset end - @start_offset) / 2;

    declare @TSQLFragment nvarchar(max);
    set @TSQLFragment = substring(@tsql, @start_offset / 2 + 1, @len);
    return @TSQLFragment;
end;

The query now becomes:

select db_name(sql_text.dbid) as [Database],
    case db_id()
        when sql_text.dbid then object_name(sql_text.objectid)
        else cast(sql_text.objectid as sysname) end as [Object],
    sql_text.text as [AllTSQL],
    dbo.GetTSQLFragment(
        sql_text.text,
        statement_start_offset,
        statement_end_offset) as [FragmentTSQL]
from sys.dm_exec_query_stats stats
    cross apply sys.dm_exec_sql_text(sql_handle) as sql_text;

To see the fragments in action, run the following query and then have another look at the query plan cache using the above query:

select * from Production.Culture;
select * from Production.Product;
select * from Production.Location;

You'll see the above query repeated three times with each select statement in its own TSQL fragment and will therefore have its own query plan. However, note the presence of the plan_handle column. This can be used to group query plans together as they were submitted as part of the same batch. Include plan_handle in the SELECT from sys.dm_exec_query_stats, execute variations of the triple-select batch statement above (just reordering is sufficient) and observe how the query plans for the same SELECT statements multiply. For example, run the following batches:

select * from Production.Location;
select * from Production.Culture;
select * from Production.Product;
go

select * from Production.Culture;
select * from Production.Location;
select * from Production.Product;
go

select * from Production.Location;
select * from Production.Product;
select * from Production.Culture;
go

It's not hard too see why ad-hoc TSQL is bad when you see what it does to your query plan cache. For stored procedures, no matter how large or complex the stored procedure is, there will only ever be one query plan for it. However, unfortunately there is some fine print. Query plans that use different SET (environment) options cannot be shared. More on this later.

Execute the following batch and have a look at the query plan cache. There is only one query plan for the stored procedure, irrespective of the ordering and parameters:

exec dbo.uspGetBillOfMaterials 800, '2003/01/01';
exec dbo.uspGetBillOfMaterials 801, '2005/01/01';
exec dbo.uspGetBillOfMaterials 800, '2004/02/08';
exec dbo.uspGetBillOfMaterials 800, '2001/02/08';
go

exec dbo.uspGetBillOfMaterials 799, '2004/02/08';
exec dbo.uspGetBillOfMaterials 800, '2003/01/01';
go

exec dbo.uspGetBillOfMaterials 780, '2004/02/08';
exec dbo.uspGetBillOfMaterials 721, '2001/02/08';
go

Now for the fine print. There are a number of factors that affect the optimiser's ability to re-use query plans. It is important to be aware of the factors as query plan re-use == performance (compiling query plans can be expensive). One of the most prominent factors is the SET (environment) options of the connection executing the query. For a query plan to be re-used, the environment options of the cached query plan needs to be the same as the query being executed. Query optimisation and query plan re-use is an enormous topic that we'll cover over the course of the 'Discover SQL Server 2005' articles. However, for now, note that executing the following query results in two different query plans being cached for the same stored procedure. Execute the query then have a look in the cache using the above DMV query:

set ansi_warnings on
exec
dbo.uspGetBillOfMaterials 721, '2001/02/08';
go

set ansi_warnings off
exec
dbo.uspGetBillOfMaterials 721, '2001/02/08';
go

More often than not environment options are a non-issue as all connections to an application's database will be instantiated by some common data access layer code, so all application connections inherently use the same environment options.

Lastly, to illustrate the power of this DMV, look at this. Want to know which are the 50 most CPU intensive queries in your database? This is all that you need:

select top 50 db_name(dbid) as [Database],
    case db_id()
        when sql_text.dbid then object_name(sql_text.objectid)
        else cast(sql_text.objectid as sysname) end as [Object],
    sql_text.text as [AllTSQL],
    dbo.GetTSQLFragment(
        sql_text.text,
        statement_start_offset,
        statement_end_offset) as [FragmentTSQL],
    plan_handle,
    total_worker_time
from sys.dm_exec_query_stats
    cross apply sys.dm_exec_sql_text(sql_handle) as sql_text
order by total_worker_time desc;

We'll be visiting many more DMVs and sample queries off the DMVs in future articles.

Labels: ,

Previous Posts