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.

May 25 2011

Oh ****!

ohnoDid you ever accidentally close SQL Server Management Studio? And, in closing SSMS, did you get the prompt that says “Save changes to the following items?” And did you, completely unthinkingly, with a query you had just been working on, hit Cancel? Yeah, me neither. What kind of idiot does that….

OK. I confess. I just did that. Silly thing it was, but I had just spent at least 1/2 an hour working on a query and now it was gone…. or was it? I had just run the query and had been looking at the results when I closed SSMS. Initially, I panicked and started thinking about how I could get the data back (somewhere there’s a file I’ve heard). Then it occurred to me, I had just been writing queries against the cache using DMOs. Why don’t I just pull it using the DMOs I had just been using? Worked like a charm.

[sourcecode language="sql"]SELECT  dest.text
FROM    sys.dm_exec_query_stats AS deqs
        CROSS APPLY sys.dm_exec_sql_text(deqs.sql_handle) AS dest
WHERE   deqs.last_execution_time > ’5/19/2011 11:00′
        AND dest.text LIKE ‘WITH%’;
[/sourcecode]

My query was much more complicated, but this was all I needed. I was able to filter out the junk in cache by only selecting stuff with an execution time within about 15 minutes of when I had closed SSMS, and I supplied the start of the query, a CTE. That was all I needed. I got back my query. Took a little formatting work, but it was immediately available and all was right with the world.

Just posting this in case you hit the same situation. You too can get your query back, easily and quickly. Then again, maybe I’m the only one stupid enough to do that.

May 23 2011

SQL Azure Query Tuning

SQL Azure is still SQL Server at the end of the day. This means it is entirely possible to write queries against SQL Azure that really… what’s a good word… stink. So what do you do? It’s all in the cloud. You couldn’t possibly tune the queries, right? Wrong. Many of the same tools that you have available to you, such as execution plans and dynamic management objects, are still available in SQL Azure.

Let’s talk DMOs for a second. First off, don’t make the mistake I did of trying to run these outside the context of a specific database on SQL Azure. You’ll get extremely inconsistent results, trust me on this. Anyway, I did a quick run-down on some of the most used DMOs for performance tuning, the sys.dm_exec_* set. Here’s a complete listing of those procs and whether or not they’re available to you in SQL Azure:

[sourcecode language="sql"]SELECT  *
FROM    sys.dm_exec_requests AS der
–available

SELECT  *
FROM    sys.dm_exec_requests AS der
        CROSS APPLY sys.dm_exec_query_plan(der.plan_handle)
–available

SELECT  *
FROM    sys.dm_exec_requests der
        CROSS APPLY sys.dm_exec_sql_text(der.sql_handle)
–available

SELECT  *
FROM    sys.dm_exec_query_stats AS deqs
–available

SELECT  *
FROM    sys.dm_exec_cached_plans AS decp
–invalid object

SELECT  *
FROM    sys.dm_exec_connections AS dec
–available

SELECT  *
FROM    sys.dm_exec_cursors AS dec
–invalid object

SELECT  *
FROM    sys.dm_exec_requests AS der
        CROSS APPLY sys.dm_exec_plan_attributes(der.plan_handle) AS depa
–invalid object

SELECT  *
FROM    sys.dm_exec_procedure_stats AS deps
–invalid object

SELECT  *
FROM    sys.dm_exec_query_memory_grants AS deqmg
–invalid object

SELECT  *
FROM    sys.dm_exec_query_optimizer_info AS deqoi
–invalid object

SELECT  *
FROM    sys.dm_exec_query_resource_semaphores AS deqrs
–invalid object

SELECT  *
FROM    sys.dm_exec_sessions AS des
–available

SELECT  *
FROM    sys.dm_exec_requests AS der
        CROSS APPLY sys.dm_exec_text_query_plan(der.plan_handle, 0, -1) AS detqp
–available

SELECT  *
FROM    sys.dm_exec_trigger_stats AS dets
–invalid object

SELECT  *
FROM    sys.dm_exec_xml_handles(@@SPID)
–invalid object
[/sourcecode]

The good news, most everything you need is available so you’re really going to be able to go to town on using DMOs as part of your query tuning. The bad news, “most everything” doesn’t include sys.dm_exec_query_optimizer_info is not on the list. This does take away a tool. It’s not a vital tool, but it’s one that allows you to understand some of what’s happening on the system. I’m not going to cry and rend my clothing because I don’t have it, but I will be somewhat disappointed.

This is great news! The tools you’re learning and using (and you are using DMOs, right?) will continue to be available in SQL Azure.

Jan 05 2011

Encryption and the Performance DMOs

Ever wonder what you can see in the performance oriented DMOs when stored procedures were encrypted? Me neither. But, I did get that question during my DMO presentation at the PASS Summit. I did not have an answer. I did get an answer from Johan Bijnens (twitter) from the audience, which I repeated without entirely knowing what I was saying. I decided that I ought to actually know the answer to that question, so here’s a little experiment.

I’m going to create a simple stored procedure:

[sourcecode language="sql"]CREATE PROCEDURE dbo.GetSalesDetails (@SalesOrderId INT)
AS
SELECT soh.AccountNumber,
sod.LineTotal
FROM Sales.SalesOrderHeader AS soh
JOIN Sales.SalesOrderDetail AS sod
ON soh.SalesOrderID = sod.SalesOrderID
WHERE soh.SalesOrderID = @SalesOrderID[/sourcecode]

When I create this procedure and run it, you can see the general performance of the query being run by pulling data from the sys.dm_exec_procedure_stats DMO like this:
[sourcecode language="sql"]SELECT deps.type_desc,
deps.last_execution_time,
deps.execution_count,
deps.total_logical_reads,
dest.encrypted AS EncryptedText,
dest.text,
deqp.query_plan,
deqp.encrypted AS EncryptedPlan
FROM sys.dm_exec_procedure_stats AS deps
CROSS APPLY sys.dm_exec_sql_text(deps.sql_handle) AS dest
CROSS APPLY sys.dm_exec_query_plan(deps.plan_handle) as deqp
WHERE dest.text LIKE ‘CREATE PROCEDURE dbo.GetSalesDetails%’[/sourcecode]

Now, to modify the procedure so that it’s encrypted I’m going to recreate it with a slight modifcation:
[sourcecode language="sql"]CREATE PROCEDURE dbo.GetSalesDetails (@SalesOrderId INT)
WITH ENCRYPTION…[/sourcecode]

Now, if I execute the procedure and rerun the select statement against the DMO, I won’t get any data. Why? Because of the WHERE clause. The text of the procedure is no longer available in the sys.dm_exec_procedures_stats DMO. Encryption has worked. I can’t see the SQL and I can’t see the execution plan. I will however, see values in the EncryptedText and EncryptePlan columns, showing that despite the encryption, rows for the procedure in question do exist in the appropriate DMOs.

There’s the answer to the question.

EDIT: Fixed the spelling of Johan’s name. Sorry Johan!

Mar 18 2010

Undocumented Virtual Column: %%lockres%

One of my development teams needed a mechanism for identifying the value of a key that was part of a lock (don’t ask). I’d never tried doing that before. Obviously if you hit the DMV sys.dm_os_tran_locks you can see the hash of the key in the resource_description column. But how to pull the value back. After some research, I first found this excellent article by the late, great, Ken Henderson (I really wish he was still around). The article outlined, among other things, the use of an undocumented “virtual” column called %%lockres%%. Some more searching then uncovered this great article by James Rowland-Jones, AKA Claypole. He described how, in a very high volume system, he used %%lockres%% to identify the source of a deadlock as the internal mechanisms that SQL Server uses to manage locks, the hash of the key. Oh, and he opened an incident on Connect, which seems to be closed, but vote on it anyway, I did. %%lockres%% is also covered in Kalen Delaney’s excellent book on SQL Server 2008 Internals and even warrants a bit of discussion in Professional SQL Server 2008, but that was written by James Rowland-Jones, so I’m not sure it counts.

In the meantime, while I was investigating this stuff, evidently the development team was looking into it on their own. They came to the same set of resources and decided to use the virtual column as part of their real-time, transactional application. Yeah, an undocumented “virtual” column going into a major application. Since I would probably be unable to do anything about this, I decided to at least look into how this thing behaves so I can be aware of what types of problems I might run into.

First, a simple query:

SELECTa.City
–,%%lockres%%
FROM Person.Address AS a
WHERE a.AddressID = 432

If you run this query and take a look at the execution plan you’ll see a nice clean clustered index seek, just as you would suspect. If you take away the comment and run it again, the execution plan is identical. On the version of AdventureWorks2008 currently installed on my machine, I get two page reads, regardless of whether or not I include %%lockres%% or not. With the comments removed, it returns the hash of the primary key: (b0004e040bc2). This looks pretty painless, free even.

If we want to see %%lockres%% in action, it’s not too difficult:

BEGIN TRAN
UPDATE Person.Address
SET City = ‘dude’
WHERE AddressID = 432;
–ROLLBACK TRAN

Obviously this will put a key lock on that row in the table. If I just select against sys.dm_os_tran_locks, the data returned looks like this:

resource_type   resource_description   resource_associated_entity_id   request_mode
KEY                       (b0004e040bc2)            72057594043564032                      X 

The original request from the development team was for a way to get the key value back when you know that a table is locked, such as the case here. I wrote this simple query to make that happen:

SELECT a.AddressID
FROM person.address(NOLOCK) AS a
JOIN sys.dm_tran_locks AS dtl
ON a.%%lockres%% = dtl.resource_description
WHERE dtl.resource_type = ‘KEY’

This query works and returns our key value of 432 just as you would want. But, take a look at the execution plan:

Yes, that’s a clustered index (or table, same thing) scan followed by a Sort followed by a merge join, processing 19614 rows to return one. But hey, it was only 341 reads. To say the least, I’m not excited about seeing this in a production system. This was explicitly cautioned in Kalen Delaney’s book. While it appears that the remote scan operator, which is how the DMV is accessed in this case, is 59% of the operation, that’s the estimated cost and has been pointed out before, isn’t the best measure of real cost in the system.

The development team went off and developed their own query, they had said they were looking for the key value, but evidently they were looking for who was holding the lock on a particular key value:

SELECT s.nt_user_name
FROM sys.dm_tran_locks l
INNER JOIN sys.dm_exec_sessions s
on l.request_session_id = s.session_id
inner join sys.partitions p on l.resource_associated_entity_id = p.hobt_id
where OBJECT_NAME(p.object_id) = ‘Address’ and
l.resource_description in (select %%lockres%%
from person.Address(NOLOCK) a WHERE a.AddressID = 432)

I actually had to adjust their query just a bit to get it to work correctly, but basically they had the right idea. Here’s the final execution plan:

This was still not terribly inspiring a thing to think about running in a production system although it only had one scan and seven reads. Whether or not putting this in a transactional system is a good idea, it certainly adds yet another tool, albeit an undocumented one, to the tool belt.

Oct 21 2009

Characters

No, I’m not talking about a Dickens novel. I’m talking about the number of characters in a string. I had a painful time recently because of the word “characters.” 

If you take a look at the dynamic management view sys.dm_exec_sql_text you can get the queries that have been run on your system that are still in the cache. It’s a great utility. Better still, you can get specific statements from the code that are actively running through sys.dm_exec_requests or ones that have run through sys.dm_exec_query_stats. To do this is very simple. Each of these DMV’s has a pair of columns, statement_start_offset and statement_end_offset. These columns, and I’m quoting directly from books online measure the “number of character” offset from the beginning of the SQL string and from the end of the SQL string. Using these values you can retrieve an individual statement out of a stored procedure that has multiple statements.

But… Here’s where things get tricky. Try this on your machine:

SELECT SUBSTRING(dest.text, (der.statement_start_offset ) + 1,
(der.statement_end_offset - der.statement_start_offset) + 1)
,LEN(dest.text) AS CharLength,
der.statement_start_offset,
der.statement_end_offset
FROM sys.dm_exec_query_stats AS der
CROSS APPLY sys.dm_exec_sql_text(der.sql_handle) AS dest
WHERE der.statement_end_offset > -1

You might get an error or you might get a bunch of really odd looking statements in the first column, starting part way into TSQL and cutting off after they’re done or before they’re over. It’ll look odd. But what’s the deal? The SUBSTRING function should work. Logically it’s configured correctly. Here’s the problem.

The [text] column in sys.dm_exec_sql_text is of the datatype NVARCHAR(MAX). Unicode. If you look at the length of the text, it’ll tell you exactly how many characters you see in the string that called to your server. But, the statement_start_offset and statement_end_offset are measuring something different. They’re not measuring characters, they’re measuring unicode characters. Try this query instead:

SELECT SUBSTRING(dest.text, (der.statement_start_offset / 2) + 1,
(der.statement_end_offset - der.statement_start_offset) / 2+ 1),
LEN(dest.text) AS CharLength,
DATALENGTH(dest.text) AS DLength,
DATALENGTH(dest.text) / 2 AS HalfDLength,
der.statement_start_offset,
der.statement_end_offset
FROM sys.dm_exec_query_stats AS der
CROSS APPLY sys.dm_exec_sql_text(der.sql_handle) AS dest
WHERE der.statement_end_offset > -1

You can see that the character length is, whatever it’s supposed to be, but the DATALENGTH is twice that much. Unicode, as we all know, includes a byte to identify the character set. That’s included in the character count in statement_start_offset and statement_end_offset.  You need to take that into account when dealing with these “characters.”

Jul 28 2009

When did this statement start?

UPDATE: This post is incorrect. Adam nailed it in the comments. I explain my mistake here.

A question came up over at SQL Server Central where someone was wondering if it was possible to know when a given statement within a batch started. Immediately I thought, oh yeah, that’s easy, use the sys.dm_exec_requests dynamic management view (DMV). Done.

Wrong. The original poster pointed out that I had assumed that the values present in the DMV represented statement level values, but they show the batch. While the DMV shows a start_time, that time is the start of the current batch, not the statement within the batch. Now the question was, where else might I get this data? I next tried sys.dm_exec_sessions because it has the last_request_start_time value. Sure enough this worked.

Don’t believe me? This time I tested it. First, I set up a batch that ran a few longish queries:

BACKUP DATABASE AdventureWorks
TO DISK = 'c:\bu\ad.bak'
WITH INIT;
DBCC CHECKALLOC(AdventureWorks);
DBCC CHECKDB(AdventureWorks);
DBCC CHECKCATALOG(AdventureWorks);
BACKUP DATABASE AdventureWorks
TO DISK = 'c:\bu\ad.bak'
WITH INIT; 

Then I wrote a little loop that would insert data from both DMV’s, once every second for a minute:

SET NOCOUNT ON;
TRUNCATE TABLE dbo.dmR;
TRUNCATE TABLE dbo.dmS;
DECLARE @CheckTime DATETIME = DATEADD(ss,60,GETDATE())
 ,@CurrTime DATETIME = GETDATE();
WHILE @CurrTime < @CheckTime
BEGIN
INSERT INTO ... SELECT ... FROM sys.dm_exec_sessions
INSERT INTO ... SELECT ... FROM sys.dm_exec_requests
WAITFOR DELAY '00:00:01';
SET @CurrTime = GETDATE();
END

Then it was a question of hitting the go button. The results are pretty clear. If you look at sys.dm_exec_requests data, you’ll see the start_time doesn’t change, but, the work being performed, visible in the command and plan_handle columns changes. You can also see the statement_start_offset and statement_end_offset changing. These values will allow you to pull data in combination with the sys.dm_exec_sql_text() dynamic management function.

 start_time             command         statement_start_offset statement_end_offset plan_handle
2009-07-28 10:42:09.447 BACKUP DATABASE 0                      138                  0x060001007D931719B8C0BF0D000000000000000000000000
2009-07-28 10:42:09.447 DBCC            140                    206                  0x060001007D931719B8C0BF0D000000000000000000000000
2009-07-28 10:42:09.447 DBCC            140                    206                  0x06000F00AF16F10FB8C04D0D000000000000000000000000
2009-07-28 10:42:09.447 DBCC            208                    268                  0x060001007D931719B8C0BF0D000000000000000000000000

But, as you can see, the start_time stays the same. Looking at the last_request_start_time and last_request_end_time in the sys.dm_exec_sessions DMV, you can see these values changing in conjunction with the changing values in sys.dm_exec_requests.

last_request_start_time last_request_end_time
2009-07-28 10:35:21.500 2009-07-28 10:35:51.170
2009-07-28 10:42:09.447 2009-07-28 10:35:51.170 

I’ll leave at as an excercise for the reader (or for another post for myself) to put together the DMV’s and DMF’s that would allow you to combine this data and show exactly which statement was being executed at which moment. The point, it is possible to determine exactly which statement is currently being executed within a batch process, and when that statement started.

Jul 20 2009

MS Field Engineer's on Performance Troubleshooting

Do you want to get a glimpse into how the Microsoft Field Engineers would go about troubleshooting performance issues on your server? Then go and read this blog entry by Denzil Ribeiro. Not only is this an excellent how-to on troubleshooting performance problems, but Mr. Ribeiro provides multiple links that describe the concepts he’s dealing with further, making it a great piece of documentation.

The MS Field Engineer blog is not terribly active, but what gets posted there is worth reading. If you don’t have it on your feed list, you should.

Feb 12 2009

Missing Index Information and Query Stats

So the goal was to find a way to pull information from sys.dm_exec_query_stats so that we could identify poor performing procedures that were in cache at the moment and combine it with missing index information from sys.dm_db_missing_index_details. We’re combining these because we’re working with a Microsoft Dynamics CRM database that is almost all ad hoc queries and lots of them are against tables with missing indexes. The hope was to identify necessary indexes merely by looking at the longest running queries.

Unfortunately there is no way to combine data from the missing indexes set of DMV’s and all the execution DMV’s that show query stats, execution plan, etc. None of the missing index tables has a plan handle or a plan hash column that would allow you to combine that data with the query data to identify which queries would directly benefit from the index if it were created.

But, if you look at the query plans in sys.dm_exec_query_plan, you can see the missing index information there. What to do? XQuery.

Since the query_plan is stored as XML, simply writing a small XQuery exist() function will do the trick:

SELECT  TOP 10 *
FROM sys.dm_exec_query_stats s
   CROSS APPLY sys.dm_exec_query_plan(s.plan_handle) AS p
WHERE  p.query_plan.exist(
‘declare default element namespace “http://schemas.microsoft.com/sqlserver/2004/07/showplan”;
/ShowPlanXML/BatchSequence/Batch/Statements/StmtSimple/QueryPlan//MissingIndexes’) = 1
ORDER BY s.total_elapsed_time DESC

This is a pretty simple example, and yes, in reality you would not want to use SELECT *.  You would want to specify those columns that you were really interested in. Also, this allows you to get performance information from queries that show a MissingIndexes element in the XML of the showplan,  but I haven’t pulled the Missing Index data out and displayed it. That can be done, but I’ll leave it as homework for you for now (and because I’m still having a hard time with XQuery).

A quick nod to Tim Ford for the advice on the DMV’s. Please finish that book soon.

Dec 18 2008

2008 Index Fragmentation

I forgot all about this, but a script I wrote on using all the new functionality of dynamic management views & functions to do index defragmentation and rebuilds got published over at SQL Server Central.

It could stand a bit of tweaking, but gets the job done on several of the systems I’ve tested it on so far.