Making a Statement: How to retrieve the T-SQL statement that caused an event

If you’ve done any troubleshooting of T-SQL, you know that sooner or later, probably sooner, you’re going to want to take a look at the actual statements you’re dealing with. In extended events we offer an action (See the BOL topic that covers Extended Events Objects for a description of actions) named sql_text that seems like it is just the ticket. Well…not always – sounds like a good reason for a blog post.

When is a statement not THE statement?

The sql_text action returns the same information that is returned from DBCC INPUTBUFFER, which may or may not be what you want. For example, if you execute a stored procedure, the sql_text action will return something along the lines of “EXEC sp_notwhatiwanted” assuming that is the statement you sent from the client. Often times folks would like something more specific, like the actual statements that are being run from within the stored procedure or batch.

Enter the stack

Extended events offers another action, this one with the descriptive name of tsql_stack, that includes the sql_handle and offset information about the statements being run when an event occurs. With the sql_handle and offset values you can retrieve the specific statement you seek using the DMV dm_exec_sql_text. The BOL topic for dm_exec_sql_text provides an example for how to extract this information, so I’ll cover the gymnastics required to get the sql_handle and offset values out of the tsql_stack data collected by the action.

I’m the first to admit that this isn’t pretty, but this is what we have in SQL Server 2008 and 2008 R2. We will be making it easier to get statement level information in the next major release of SQL Server.

The sample code

For this example I have a stored procedure that includes multiple statements and I have a need to differentiate between those two statements in my tracing. I’m going to track two events: module_end tracks the completion of the stored procedure execution and sp_statement_completed tracks the execution of each statement within a stored procedure. I’m adding the tsql_stack events (since that’s the topic of this post) and the sql_text action for comparison sake. (If you have questions about creating event sessions, check out Pedro’s post Introduction to Extended Events.)

USE AdventureWorks2008
GO

-- Test SP
CREATE PROCEDURE sp_multiple_statements
AS
SELECT 'This is the first statement'
SELECT 'this is the second statement'
GO

-- Create a session to look at the sp
CREATE EVENT SESSION track_sprocs ON SERVER
ADD EVENT sqlserver.module_end (ACTION (sqlserver.tsql_stack, sqlserver.sql_text)),
ADD EVENT sqlserver.sp_statement_completed (ACTION (sqlserver.tsql_stack, sqlserver.sql_text))
ADD TARGET package0.ring_buffer
WITH (MAX_DISPATCH_LATENCY = 1 SECONDS)
GO

-- Start the session
ALTER EVENT SESSION track_sprocs ON SERVER
STATE = START
GO

-- Run the test procedure
EXEC sp_multiple_statements
GO

-- Stop collection of events but maintain ring buffer
ALTER EVENT SESSION track_sprocs ON SERVER
DROP EVENT sqlserver.module_end,
DROP EVENT sqlserver.sp_statement_completed
GO

Now that we’ve collected some events related to running the stored procedure, we need to do some processing of the data. I’m going to do this in multiple steps using temporary tables so you can see what’s going on; kind of like having to “show your work” on a math test. The first step is to just cast the target data into XML so I can work with it. After that you can pull out the interesting columns, for our purposes I’m going to limit the output to just the event name, object name, stack and sql text. You can see that I’ve don a second CAST, this time of the tsql_stack column, so that I can further process this data.

-- Store the XML data to a temp table
SELECT CAST( t.target_data AS XML) xml_data
INTO #xml_event_data
FROM sys.dm_xe_sessions s INNER JOIN sys.dm_xe_session_targets t
    ON s.address = t.event_session_address
WHERE s.name = 'track_sprocs'

SELECT * FROM #xml_event_data

-- Parse the column data out of the XML block
SELECT
    event_xml.value('(./@name)', 'varchar(100)') as [event_name],
    event_xml.value('(./data[@name="object_name"]/value)[1]', 'varchar(255)') as [object_name],
    CAST(event_xml.value('(./action[@name="tsql_stack"]/value)[1]','varchar(MAX)') as XML) as [stack_xml],
    event_xml.value('(./action[@name="sql_text"]/value)[1]', 'varchar(max)') as [sql_text]
INTO #event_data
FROM #xml_event_data
    CROSS APPLY xml_data.nodes('//event') n (event_xml)

SELECT * FROM #event_data

After parsing the columns it’s easier to see what is recorded. You can see that I got back two sp_statement_completed events, which makes sense given the test procedure I’m running, and I got back a single module_end for the entire statement. As described, the sql_text isn’t telling me what I really want to know for the first two events so a little extra effort is required.

-- Parse the tsql stack information into columns
SELECT
    event_name,
    object_name,
    frame_xml.value('(./@level)', 'int') as [frame_level],
    frame_xml.value('(./@handle)', 'varchar(MAX)') as [sql_handle],
    frame_xml.value('(./@offsetStart)', 'int') as [offset_start],
    frame_xml.value('(./@offsetEnd)', 'int') as [offset_end]
INTO #stack_data   
FROM #event_data   
    CROSS APPLY    stack_xml.nodes('//frame') n (frame_xml)   

SELECT * from #stack_data

Parsing out the stack information doubles the fun and I get two rows for each event. If you examine the stack from the previous table, you can see that each stack has two frames and my query is parsing each event into frames, so this is expected. There is nothing magic about the two frames, that’s just how many I get for this example, it could be fewer or more depending on your statements. The key point here is that I now have a sql_handle and the offset values for those handles, so I can use dm_exec_sql_text to get the actual statement. Just a reminder, this DMV can only return what is in the cache – if you have old data it’s possible your statements have been ejected from the cache. “Old” is a relative term when talking about caches and can be impacted by server load and how often your statement is actually used. As with most things in life, your mileage may vary.

SELECT
    qs.*,
    SUBSTRING(st.text, (qs.offset_start/2)+1,
        ((CASE qs.offset_end
          WHEN -1 THEN DATALENGTH(st.text)
         ELSE qs.offset_end
         END - qs.offset_start)/2) + 1) AS statement_text
FROM #stack_data AS qs
CROSS APPLY sys.dm_exec_sql_text(CONVERT(varbinary(max),sql_handle,1)) AS st

Now that looks more like what we were after, the statement_text field is showing the actual statement being run when the sp_statement_completed event occurs. You’ll notice that it’s back down to one row per event, what happened to frame 2? The short answer is, “I don’t know.” In SQL Server 2008 nothing is returned from dm_exec_sql_text for the second frame and I believe this to be a bug; this behavior has changed in the next major release and I see the actual statement run from the client in frame 2. (In other words I see the same statement that is returned by the sql_text action  or DBCC INPUTBUFFER) There is also something odd going on with frame 1 returned from the module_end event; you can see that the offset values are both 0 and only the first letter of the statement is returned. It seems like the offset_end should actually be –1 in this case and I’m not sure why it’s not returning this correctly. This behavior is being investigated and will hopefully be corrected in the next major version. You can workaround this final oddity by ignoring the offsets and just returning the entire cached statement.

SELECT
    event_name,
    sql_handle,
    ts.text
FROM #stack_data
    CROSS APPLY sys.dm_exec_sql_text(CONVERT(varbinary(max),sql_handle,1)) as ts

Obviously this gives more than you want for the sp_statement_completed events, but it’s the right information for module_end. I leave it to you to determine when this information is needed and use the workaround when appropriate.

Happy Eventing
- Mike