How to Tell if Execution Plans are Reused

October 4, 2010 at 8:00 am (SQL Server 2005, SQL Server 2008, SQLServerPedia Syndication, TSQL) (, , , , , )

I try to watch the search phrases that point people to the blog because sometimes, you get a sense of what problems people are running into. The latest question or phrase I’ve seen a lot lately is along the lines of “how do you know if an execution plan is being reused.”

Since compiling an execution plan can be an extremely expensive operation, it’s worth your time to understand how well a given plan is getting reused. If you’ve seen me present, I’ll frequently talk about the application that had a query with an 86 table join. Recompiles on that thing were frequent and extremely costly. The only good news was, they were recompiles. If we weren’t getting plan reuse it would have been an even worse system than it was.

There are a number of ways you can see if a plan is being reused. One of the easiest is to hit the DMOs that look into the plan cache. You can look at either sys.dm_exec_procedure_stats or sys.dm_exec_query_stats. These DMOs are somewhat different and somewhat the same. Actually, they sort of cross each other. For sys.dm_exec_procedure_stats, you get aggregate information about stored procedures. For sys.dm_exec_query_stats you get aggregate information about queries, which, may be run within stored procedures. So either or both could be useful depending on what you’re attempting to measure. However, both return a very useful counter, execution_count. Quite simply, that tells you that the plan, whether for the statement or the procedure, is being reused. To get maximum gain out using either of these, you’ll want to combine them with other DMOs. Something along these lines can show you the plans for procedures that have been running against a system, ordered by the number of times they’ve been reused:

SELECT deps.execution_count ,
OBJECT_NAME(deps.object_id, deps.database_id) 'Procedure' ,
deqp.query_plan
FROM sys.dm_exec_procedure_stats AS deps
CROSS APPLY sys.dm_exec_query_plan(deps.plan_handle) AS deqp
ORDER BY deps.execution_count DESC

The only thing wrong with using the DMO like this is that you can only see what’s currently in cache. This means no history, depending on how volatile the cache is on your system.

Another way to tell if a plan is being reused, is to set up a server side trace and capture the event for the SP:CacheMiss or SP:CacheHit. This is pretty straight forward. If the query was not in, it generates a miss event. If it was there, it generates a hit. But, this has to be running in order for you to know if you had a hit or a miss. The good news is, if it’s running, you’ve got historical information since this captures the event as it occurs.

You can also catch recompile events using SQL:StmtRecompile. Yes, you can get SP:Recompile if you’re only ever dealing with procedures, but if you’ve got any kind of ad-hoc querying going on in the system or triggers, you’ll miss recompile events. Basically, because recompiles are at the statement level starting in 2005, BOL recommends only using SQL:StmtRcompile.

That’s pretty much it. Using these methods in the appropriate place will let you know if the plan is being reused or not.

Permalink 1 Comment

Undocumented Virtual Column: %%lockres%

March 18, 2010 at 8:43 am (SQL Server 2005, SQL Server 2008, TSQL) (, , , , , , , )

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.

Permalink 3 Comments

Characters

October 21, 2009 at 2:42 pm (SCOM, SQL Server 2005, SQL Server 2008, SQLServerPedia Syndication, TSQL) (, , , , )

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.”

Permalink 1 Comment