Advanced SQL Server 2008 Extended Events with Examples

By Mladen Prajdić on 25 May 2009 | Tags: Administration , Performance Monitors , SQL Server 2008 Features

In the previous article we learned about SQL Server 2008 Extended Events terminology, components and took a look at a simple example. In this article we'll take a deeper look with some more complex examples.

Performance Considerations

As with all performance reporting tools we have to have some common sense when using Extended Events. Here are some performance points to consider when using them.

Asynchronous or synchronous target

The choice of a target type is crucial to the well being of the system. When using synchronous targets the code has to wait for the event to be fully created and consumed by the target. If the event is overly complex this has a negative impact.

On the other hand the asynchronous target doesn't have that problem. They have a problem with buffer size and event loss. The buffer is size is set with MAX_MEMORY event session option and it is a FIFO queue that stores events that have been fired but not yet consumed by the target. If the system has a high event fire frequency this buffer might get full fast. When that happens the event session has to know what to do with other events that can't be put into the buffer. This is why the session has an EVENT_RETENTION_MODE setting which has one of 3 values: ALLOW_SINGLE_EVENT_LOSS, ALLOW_MULTIPLE_EVENT_LOSS and NO_EVENT_LOSS. What each option does is self explanatory from its name but beware of the NO_EVENT_LOSS. Using it can bring SQL Server performance down really fast. Although the target is asynchronous the code inside SQL Server can't continue until the event has been successfully consumed by the target. If the buffer that holds the data before it's sent to the asynchronous target is full, SQL Server will wait until there's some free space in the buffer before continuing. With the other two setting this can't happen because SQL Server simply discards the events.

The choice of the target type is also important. For example using the synchronous classic ETW target is the only way to correlate data from other system parts like IIS. On the other had if you just want to count the number of times an event has fired it's best to use the synchronous event counter target.

Predicate short circuiting

Unlike SQL WHERE statement the Extended Events provide full support for short circuiting. This means that you should always put small and fast predicates first. For example you should put (sqlserver.database_id = 8) before (sqlserver.sql_text = 'someReallyLongSQLStatement') because the database_id check is faster. This is important because predicates are evaluated before the event is actually sent to the consumer, but after the event payload has been created. Also this operation is of course synchronous and it should be fast.

Small actions

Actions are collected after the event has fired and are executed synchronously so keep then as small as possible. For example adding a heavy duty action like tsql_stack to a lock_released event on an even moderately busy system is very likely to bring your system down.

Examples

In these examples we'll use the ring_buffer target which can be replaced by any other if needed. All queries will be run in the AdventureWorks database whose database ID is 8 as is evident by the WHERE predicates of all event sessions.

In all examples we collect the tsql_stack action. However note that this action is heavy weight and should not always be included. Include it only when you really need it. In the target XML data the tsql_stack action's node looks like code below. Note that the handle values and offsets will vary for your tries. A tsql_stack looks like this (Editor: text wrapped for readability):

<action name="tsql_stack" package="sqlserver"> 
      <type name="unicode_string" package="package0" /> 
      <value>
	<frame level='1' handle='0x020000003AE0580FE1F8B6F993AB883E115A3C29DA3E50A2' 
		line='1' offsetStart='0' offsetEnd='-1'/> 
	<frame level='2' handle='0x02000000CE095F247634DD4687A0D25637CBCD2BCB17AB29' 
		line='1' offsetStart='0' offsetEnd='-1'/>
      </value> 
      <text /> 
</action>

The level tells us how far down the stack a particular SQL Statement is. Level 1 is the latest statement. offsetStart and offsetEnd can be used to get the exact statement in the returned text if it contains more than one SQL statement. The hex handle values in the upper <value> node are handles to SQL statement's text that can be retrieved with these statements:

SELECT * FROM sys.dm_exec_sql_text(0x020000003AE0580FE1F8B6F993AB883E115A3C29DA3E50A2)
SELECT * FROM sys.dm_exec_sql_text(0x02000000CE095F247634DD4687A0D25637CBCD2BCB17AB29)

Since we've seen how to process the entire Extended Events session cycle in the previous article here we'll just take a look at the CREATE EVENT SESSION part of the code.

On to our examples!

SQL trigger execution tracing with Transaction ID

Sometimes we'd like to trace which statements caused which trigger to execute or how many triggers fired because of an update or something similar. We can do this by tracing sp_statement_completed event with transaction_id and tsql_stack actions. The tsql_stack shows us nicely which triggers have been fired due to our statement execution. We group the statements by the transaction ID so we know which ones go together. This is the CREATE EVENT SESSION that does this:

CREATE EVENT SESSION RingBufferExampleSession ON SERVER 
    ADD EVENT sqlserver.sp_statement_completed 
    (
        ACTION (sqlserver.sql_text, sqlserver.tsql_stack, sqlserver.transaction_id, 
		sqlserver.database_id, sqlserver.username)
        WHERE sqlserver.database_id = 8
    )  
    ADD TARGET package0.ring_buffer    
        (SET max_memory = 4096) 
WITH (max_dispatch_latency = 1 seconds)

Knowing which statements have been run in which Resource Governor pool and their IO cost

Resource governor is a new addition to SQL Server. It allows us to split CPU and memory workload into pools. Then we can assign every statement into a different pool. By knowing which SQL statement ran in which resource governor pool we can get its IO cost thus getting some overview of the resource governor pool IO use. The sqlserver.sql_statement_completed has reads and writes values for the event. By summing those values for each resource governor pool we can get the exact IO cost they use. This is the CREATE EVENT SESSION that does this:

CREATE EVENT SESSION RingBufferExampleSession ON SERVER
    ADD EVENT sqlserver.sql_statement_completed
    ( 
        ACTION (sqlserver.session_resource_pool_id, sqlserver.sql_text, 
		sqlserver.tsql_stack, sqlserver.username) 
        WHERE sqlserver.database_id = 8 
    ) 
    ADD TARGET package0.ring_buffer
        (SET max_memory = 4096) 
WITH (max_dispatch_latency = 1 seconds)

Part of the returned XML from the ring buffer target:

<data name="reads"> 
    <type name="uint64" package="package0" /> 
    <value>2</value> 
    <text /> 
</data> 
<data name="writes"> 
    <type name="uint64" package="package0" /> 
    <value>0</value> 
    <text /> 
</data> 
<action name="session_resource_pool_id" package="sqlserver"> 
    <type name="uint32" package="package0" /> 
    <value>2</value> 
    <text /> 
</action>

We can see the reads and writes event data and session_resource_pool_id action.

Counting index page splits

Yes it's exactly what the title says. This event fires for every page split. This is good. And bad. The good part being that you can get some sense of how many splits your getting. The bad part being that you only get the file_id and page_id in the event data. There's no information about which index or which page in the index caused this. I guess you could make some correlations between the output of DBCC IND and the occurrences of these events. But for now this one is useful only as general information on page splits. Hopefully more data will be added to this event in the future so that it becomes really useful.

CREATE EVENT SESSION RingBufferExampleSession ON SERVER
    ADD EVENT sqlserver.page_split 
    ( 
        ACTION (sqlserver.sql_text, sqlserver.tsql_stack, sqlserver.username) 
        WHERE sqlserver.database_id = 8 
    )
    ADD TARGET package0.ring_buffer    
        (SET max_memory = 4096) 
WITH (max_dispatch_latency = 1 seconds)

Tracing SQL statements that error out

Here's a common scenario I hear: The system runs fine but once every month an SQL error happens in the system. How to trace this? Until now you could only use Profiler or SQL Trace to capture "SQL:StmtStarting", "SQL:StmtCompleted", "Errors and Warnings:Exception" and "Errors and Warnings:User Error Message" events and then find out which statement failed. However this had the potential to impact performance since we still collected every "SQL:StmtStarting" and "SQL:StmtCompleted" event that happened. With Extended event this is easily achieved with "error_reported" event. When this event happens we simply collect the offending SQL Statement. Here is the CREATE EVENT SESSION that does this:

CREATE EVENT SESSION RingBufferExampleSession ON SERVER 
    ADD EVENT sqlserver.error_reported            
    -- collect failed SQL statement, the SQL stack that led to the error, 
    -- the database id in which the error happened and the username that ran the statement 
    (
        ACTION (sqlserver.sql_text, sqlserver.tsql_stack, sqlserver.database_id, 
			sqlserver.username)
        WHERE sqlserver.database_id = 8
    )  
    ADD TARGET package0.ring_buffer    
        (SET max_memory = 4096) 
WITH (max_dispatch_latency = 1 seconds)

Run the SQL that will fail:

SELECT * FROM Person.Contact WHERE ModifiedDate = '2005-05-16 16:33:g3.060'

This is how part of the collected event data looks like:

<action name="sql_text" package="sqlserver"> 
    <type name="unicode_string" package="package0" /> 
    <value>select * from Person.Contact where ModifiedDate = '2005-05-16 16:33:g3.060'</value> 
    <text /> 
</action> 
<action name="tsql_stack" package="sqlserver"> 
    <type name="unicode_string" package="package0" /> 
    <value>
      <frame level='1' handle='0x020000003AE0580FE1F8B6F993AB883E115A3C29DA3E50A2' 
		line='1' offsetStart='0' offsetEnd='-1'/> 
      <frame level='2' handle='0x02000000CE095F247634DD4687A0D25637CBCD2BCB17AB29' 
		line='1' offsetStart='0' offsetEnd='-1'/>
    </value> 
    <text /> 
</action>

By looking at the sql_text action node we can see the offending statement and since we've also collected the tsql_stack action we can look at the all SQL statements that led caused the error.

Tracing deadlocks, locking and blocking

Deadlock problems have been around as long as databases have been around. They are logical design problems that should be resolved. That's why deadlock detection has seen quite a boom. You can detect them by setting Trace flags, analyzing a profiler trace or using asynchronous Event Notifications of which I am a big fan of and still prefer using. So no example would be complete without showing that too. The advantage Extended Events provide over other methods is in the collection of other relevant system data with the use of actions and precise tracking with predicates. Here is the CREATE EVENT SESSION that does this:

CREATE EVENT SESSION RingBufferExampleSession 
ON SERVER     
    ADD EVENT sqlserver.lock_deadlock 
    ( 
            ACTION (sqlserver.sql_text, sqlserver.tsql_stack, sqlserver.username, 
			sqlserver.session_id, sqlserver.request_id) 
            WHERE sqlserver.database_id = 8 
    )
    -- this is an optional part if we want to also collect other lock events.       
    -- ADD EVENT sqlserver.locks_lock_timeouts 
    -- ( 
    --        ACTION   (sqlserver.sql_text, sqlserver.tsql_stack, sqlserver.username, 
    --				sqlserver.session_id, sqlserver.request_id) 
    --        WHERE    sqlserver.database_id = 8 
    -- ), 
    -- ADD EVENT sqlserver.locks_lock_waits 
    -- ( 
    --        ACTION   (sqlserver.sql_text, sqlserver.tsql_stack, sqlserver.username, 
    --				sqlserver.session_id, sqlserver.request_id) 
    --        WHERE    sqlserver.database_id = 8 
    -- )   
    ADD TARGET package0.ring_buffer    
        (SET max_memory = 4096) 
WITH (max_dispatch_latency = 1 seconds)

This info can also be retrieved from the built-in system_health session so we don't have to make it ourselves.

Tracing long running queries

This is also a common performance troubleshooting technique. You can use SQL Profiler to trace for those but this is a way to do it with Extended events. Notice that we use the sql_statement_completed.duration to get only queries executing longer than 500 ms. The duration is measured in microseconds thus we have to use the value 500 000 to get half a second. Here is the CREATE EVENT SESSION that does this:

CREATE EVENT SESSION RingBufferExampleSession 
ON SERVER 
    ADD EVENT sqlserver.sql_statement_completed 
        ( 
            ACTION (sqlserver.sql_text, sqlserver.tsql_stack, sqlserver.username) 
            WHERE sqlserver.database_id = 8 
		AND sqlserver.sql_statement_completed.duration > 500000 
        ) 
    ADD TARGET package0.ring_buffer    
        (SET max_memory = 4096) 
WITH (max_dispatch_latency = 1 seconds) 

Report all event occurrences greater/smaller than N

Sometimes we want to only report events after/before they have been fired number of times. This hasn't been possible before the introduction of Extended events. With the use of package0.counter > N predicate we can collect data for every occurrence greater than N. In other words if N is 3 than every 4th, 5th,… Nth occurrence of an event will be collected. Of course the opposite goes for package0.counter < N.

In this example we're collecting data about every detected long IO after they have fired 10 times. Depending on your system this can mean that you have IO problems. On a non-busy system this won't produce any events so it's hard to show it in action. However it's useful to know it exists. Of course in this example N is completely random and not based on any benchmark. Here is the CREATE EVENT SESSION with N = 10 that does this:

CREATE EVENT SESSION RingBufferExampleSession ON SERVER 
    ADD EVENT sqlserver.long_io_detected
        ( 
            ACTION (sqlserver.sql_text, sqlserver.tsql_stack, sqlserver.username) 
            WHERE sqlserver.database_id = 8 and package0.counter > 10 
        ) 
    ADD TARGET package0.ring_buffer    
        (SET max_memory = 4096) 
WITH (max_dispatch_latency = 1 seconds) 

Extended Events How To's in Books Online

Books Online have a few examples of Extended Events use. Note that "resource_0" column in those examples is actually the object ID of the accompanying object like object_id, index ID, page ID, etc..

Hopefully all these examples have shown you the potential that SQL Server Extended Events have when troubleshooting and monitoring performance. The full working code for the examples can be found in the accompanying file.