SQL Server 2012 Denali: Discussion On Usage Scenario for “Extended Events” (Part-1)

SQL Server 2008 introduces Extended Events – A light weight performance monitoring system that uses very few performance resources. Read more about Extended Events if you have not explored it yet.

With the release of SQL Server 2012 (aka “Denali”) CTP3 it gets even better. Now, it has two graphical user interfaces (the New Session Wizard or New Session UI) to easily and quickly create, modify, display, and analyse your session data. Not only that, it now includes an Extended Events Reader to View the Target Data . These new additions make use of Extended Events very easy as you will see later in this post.

As Microsoft has announced deprecation of SQL Profiler Trace to be replaced with Extended Events in the next major release, I thought this is the time to have a good hands-on on Extended Events. Especially because I deal with SQL Profiler frequently to troubleshoot SQL Server Performance and other issues. Be advised, Extended Events is not limited to troubleshoot only the SQL Server performance issues. Check the section Scenarios for Using Extended Events to get a glimpse of some scenarios where Extended Events can be used.

In this blog, I am going to demonstrate how we can use the wait event category sqlos.wait_info* to track the wait resources the queries running in a particular session undergo. I know we can do this in prior versions as well. However, It becomes challenging if we have to find the wait types, duration etc. about a query or multiple queries running in a particular session when it completes quickly e.g. less than 1 sec or 500 ms. In such case diagnostics using Extended Events is quite useful. This is why this blog.

P.S: All the demo is based on SQL Server 2012 CTP3 (aka Denali) which is subject to change in the RTM release.

Create an Extended Events Session to track the wait resources the queries running in a particular session undergo:

1. Launch SSMS to navigate through the all new Extended Events user interface under Management folder. Right click on the New Session… under Sessions folder. A picture is worth thousand words so here is the pictorial tutorial.

2. Now we are at the General Page of New Session dialog box. Give it a a new Session name say WaitsSingleSession. Read Creating and modifying event sessions to know the description of each of the option in this dialog box.

3. Let’s take a look at the Events page now. This is the most important page. This page has couple of parts – Events selection and Events configuration. First we need to select the events to be configured later. I am going to select two events sqlos.wait_info and sqlos.wait_info_external by searching wait_info in the Event Library field.

Why these two wait events?

Well, let’s first look at the description we have in sys.dm_xe_objects about these two waits events. You may run the query below to get this:

select name, object_type, description
from sys.dm_xe_objects
WHERE name LIKE ‘wait_info%’

Bit more on wait_info:

As it says, wait_info is a wait on a SQLOS controlled resource. Essentially we may use this event to troubleshoot any type of wait on such resources. This includes a comprehensive list of waits from sys.dm_os_wait_stats. Note that this wait event gives information about the state of a worker thread when the particular wait has completed. The most common predicate expression to use for wait_info is wait_type.

The same stands true for wait_info_external as well:

Ok, so what is wait_info_external now?

During the execution, a worker may have to switch to the pre-emptive mode to call a windows API. Wait_info_external corresponds to such kind of pre-emptive waits. To see a list of all such pre-emptive waits you may run a query like this:

select * from sys.dm_xe_map_values
where name = ‘wait_types’
and map_value like ‘%PREEMPTIVE%’

4. Now let’s select these two events:

5. Once we have the events selected let’s configure the selected events. Click on button to get the below dialog box:

6. On the left pane, select wait_external_info . Under Event configurations options > Global Fields (Action) check all of these:

database_id
plan_handle
session_id
sql_text

7. Click on the Filter (Predicate) tab to apply a filer on the sqlserver.session_id. Remember we are creating this extended event session to track all the wait resources for queries running in a particular session. The session id 53 is an example in my case. You need to put the session id which you want to track.

Tip:

You may apply filters on the applicable

Events Field
for the selected event category viz. a filter on wait_type or on duration column e.g. wait_type =187 means CXPACKET waits. Jonathan Kehayias has written such a query on his blog (as below) to see the list:

SELECT map_key, map_value
FROM sys.dm_xe_map_values
WHERE name = ‘wait_types’
  AND ((map_key > 0 AND map_key < 22) — LCK_ waits
            OR (map_key > 31 AND map_key < 38) — LATCH_ waits
            OR (map_key > 47 AND map_key < 54) — PAGELATCH_ waits
            OR (map_key > 63 AND map_key < 70) — PAGEIOLATCH_ waits
            OR (map_key > 96 AND map_key < 100) — IO (Disk/Network) waits
            OR (map_key = 107) — RESOURCE_SEMAPHORE waits
            OR (map_key = 113) — SOS_WORKER waits
            OR (map_key = 120) — SOS_SCHEDULER_YIELD waits
            OR (map_key = 178) — WRITELOG waits
            OR (map_key > 174 AND map_key < 177) — FCB_REPLICA_ waits
            OR (map_key = 186) — CMEMTHREAD waits
            OR (map_key = 187) — CXPACKET waits
            OR (map_key = 207) — TRACEWRITE waits
            OR (map_key = 269) — RESOURCE_SEMAPHORE_MUTEX waits
            OR (map_key = 283) — RESOURCE_SEMAPHORE_QUERY_COMPILE waits
            OR (map_key = 284) — RESOURCE_SEMAPHORE_SMALL_QUERY waits
        )

If you want to track all the waits which were more than 5 secs you may apply the filter duration>5000 (in milliseconds)

8. Now click on the Data Storage page. Select the type Event File

Select the obvious options to let the wizard know where to create the output file:

9. Now click on the Advanced page

See Set Advanced Configuration Properties for more details on the above options. Here is a quick info about Maximum dispatch latency:

To specify the Maximum dispatch latency options for the event session, do the following:
a. In seconds. Select this option to prolong or shorten the maximum dispatch latency. Use the up and down arrows to specify the maximum dispatch latency in seconds.
b. Unlimited. Select this option if you want the events dispatched only when the buffer is full.

10. Now click on “OK”. The Extended Event session named WaitsSingleSession is created and should appear under the Extended Events section in SSMS now.

Note that the session is currently stopped. Let’s start this session now.

11. Right click and start your extended events session.

12. Now go to the session (session id 53) and run the queries for which you want to track the wait resources. Once the execution completed, stop the extended events session.

13. To read the log file go to the place where you saved the output and right click open

=

14. This will open up a new window as this picture shows. Alternatively you can just drag and drop this file in SSMS too to open.

15. This log viewer lets you customize the log file for further examination. Start by choosing the relevant columns first:

16. There is much more you can do here to narrow down the data e.g. Group by column(s). aggregate or sum etc. I am not going to explain all of them. I will let you explore rest of them rather ?

Still not it… Time for the reverse engineering.

Well if you prefer to do the things from User Interface you may stop reading this post now ? But if you happen to like T-SQL and can make yourself familiar with packages, events etc. of extended events here is a quick way to do this using T-SQL.

Just script out the Extended Events session we created:

..and there we go. Just run this script in SSMS and out extended events session is ready for use.

CREATE EVENT SESSION [WaitsSingleSession] ON SERVER
ADD EVENT sqlos.wait_info,
ADD EVENT sqlos.wait_info_external(
    ACTION(sqlserver.database_id,sqlserver.plan_handle,sqlserver.session_id,sqlserver.sql_text)
    WHERE ([sqlserver].[session_id]=(53)))
ADD TARGET package0.event_file(SET filename=N’D:\WaitsSingleSession.xel’,max_file_size=(250))
WITH (MAX_MEMORY=4096 KB,EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,MAX_DISPATCH_LATENCY=1 SECONDS,MAX_EVENT_SIZE=0 KB,MEMORY_PARTITION_MODE=NONE,TRACK_CAUSALITY=OFF,STARTUP_STATE=OFF)
GO

Also, to read the log file thus created, you may follow the aforementioned steps (13-16). Alternatively T-SQL again to import the files into a temp table first:

— Replace the .xel filename here
select * into #xe_waits
from sys.fn_xe_file_target_read_file ( ‘D:\WaitsSingleSession_0_129662550954090000.xel’,null,null, null ) as t

Once the file is imported into the temp table (#xe_waits in this case) run the following script to display the data:

WITH xmldata ([object_name] , event_data) AS
(
select [object_name], convert(xml, event_data) from #xe_waits
)
select
event_data.value(‘(/event/@name)[1]’, ‘varchar(40)’) as EventName,
event_data.value (‘(/event/@timestamp)[1]’, ‘datetime’) as EventTime,
event_data.value ( ‘(/event/data/text)[1]’, ‘varchar(32)’ ) as WaitType,
event_data.value ( ‘(/event/data/text)[2]’, ‘varchar(16)’ ) as OpCode,
event_data.value ( ‘(/event/data/value)[3]’, ‘int’ ) as Duration,
event_data.value ( ‘(/event/data/value)[5]’, ‘int’ ) as Total_Duration
from xmldata

That is it for now. But, as the post says Part-1 watch out for some more posts on Extended Events usage scenarios. Stay tuned!