Extended Events – As Cool as I Thought They’d Be

Last week, a front-end developer came to me with an interesting problem. He had written some code that called a stored procedure t0 insert a row in a table that included a [ScheduledOn] column that was set to NULL by the insert and return a GUID value generated in the process, then immediately called a stored procedure (on another connection) to update rows from that table WHERE [ScheduledOn] IS NULL and OUTPUT the inserted values. Unexpectedly, the just-inserted row did not appear in the results of the UPDATE stored procedure. If we ran the UPDATE stored procedure a second or two later, though, the just-inserted row turned up as expected. After verifying that the application code was not calling the UPDATE stored procedure before it received the results of the INSERT stored procedure, I was momentarily stumped and looking for a way to understand why a row inserted on one connection would not be visible to a UPDATE executed on another connection even though the INSERT seemed to be completed before the UPDATE ran.

That’s when I remembered extended events. I first learned about extended events at Grant Fritchey’s pre-conference session “Query Performance Tuning: Start to Finish” at PASS Summit 2012. I remember leaving that session very excited about the amount of information that could be collected with negligible effects on database performance and anxious for a chance to use them in my work. No such opportunity has presented itself until now, though.

I needed to determine when the transaction begun by the INSERT stored procedure committed relative to the execution of the UPDATE stored procedure. I began my research to see whether extended events could help me here, and almost immediately found Jonathan Kehayias’s excellent article “Using SQL Server 2008 Extended Events.” This article includes a script that returns a list of the available extended events, and there I found the sp_statement_starting, sp_statement_completed, database_transaction_begin, and database_transaction_end events.

I thought these events would tell me what I needed to know. With Jonathan Kehayias’s article and Books Online, I learned how to create an extended events session for these events, specify actions for each event to return additional information, apply predicates to filter the data to be collected, and direct the output to an accessible location. Using this knowledge, I created an extended events session to collect information about the four events of interest for sessions run with the developer’s credentials and store it in the ring buffer (a first-in-first-out in-memory store; data is removed when the extended events session is stopped) with this code:

CREATE EVENT SESSION transactionOverlap ON SERVER
ADD EVENT sqlserver.database_transaction_begin
(WHERE sqlserver.nt_user = 'someAppDev'),
ADD EVENT sqlserver.database_transaction_end
(WHERE sqlserver.nt_user = 'someAppDev'),
ADD EVENT sqlserver.sp_statement_starting(
ACTION (sqlserver.session_id, sqlserver.request_id, sqlserver.sql_text)
WHERE sqlserver.nt_user = 'someAppDev'),
ADD EVENT sqlserver.sp_statement_completed(
ACTION (sqlserver.session_id, sqlserver.request_id, sqlserver.sql_text)
WHERE sqlserver.nt_user = 'someAppDev')
ADD TARGET package0.ring_buffer(SET max_memory=8192)

I started the session with this code:

ALTER EVENT SESSION transactionOverlap ON SERVER STATE=START

and asked the developer to run the problematic code. After verifying that this produced the problematic result, I used this query (from Jonathan Kehayias’s article) to view the extended events data I captured as XML:

SELECT CAST(xet.target_data AS xml)
FROM sys.dm_xe_session_targets xet
INNER JOIN sys.dm_xe_sessions xe
ON (xe.address = xet.event_session_address)
WHERE xe.name = 'transactionOverlap'

then stopped the extended events session like this (removing the data from the ring buffer and making it important that I save the resulting XML I generated with the previous query):

ALTER EVENT SESSION transactionOverlap ON SERVER STATE=STOP

I was surprised to see that a few seconds of this extended events session produced over 20,000 lines of XML results. It’s possible to parse the XML into rows and columns in SQL Server using XQuery, but in my case a quick review of the extended events data revealed a database_transaction_begin node for a set of stored procedure statements on session 2 (the UPDATE stored procedure) with a timestamp that preceded the timestamp of the database_transaction_end node for a set of stored procedure statements on session 1 (the INSERT stored procedure) by a few milliseconds. Since the default isolation level on this SQL Server instance was READ_COMMITTED_SNAPSHOT, it now made perfect sense that the UPDATE stored procedure would not see the row inserted by the INSERT stored procedure – it wasn’t there at the time the UPDATE transaction began.

I’m not sure how I would have evaluated this situation otherwise, but extended events made it relatively simple. I’m still astounded by the power of extended events and looking forward to mky next chance to use them. By the way, I solved this particular issue by adding the READCOMMITTEDLOCK table hint to the UPDATE stored procedure, forcing it to wait until the INSERT stored procedure released its locks upon COMMITting its transaction.

About these ads

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

Follow

Get every new post delivered to your Inbox.

%d bloggers like this: