An XEvent a Day (30 of 31) – Tracking Session and Statement Level Waits

While attending PASS Summit this year, I got the opportunity to hang out with Brent Ozar (Blog|Twitter) one afternoon while he did some work for Yanni Robel (Blog|Twitter).  After looking at the wait stats information, Brent pointed out some potential problem points, and based on that information I pulled up my code for my PASS session the next day on Wait Statistics and Extended Events and made some changes to one of the demo’s so that the Event Session only focused on those potentially problematic waits that had been identified, and sent Brent the DDL so that he could give Extended Events a shot.  Within a few minutes, we were able track down to the statement level in a couple of stored procedures, the causes of those waits, and after some analysis Brent was able to offer some suggestions to Yanni about how to reduce the waits.

Understanding how SQL Server waits to continue execution can be key to improving performance since time spent waiting is time lost during the execution of a SQL Statement.  I love looking at wait statistics and the chapter that I wrote for SQL Server 2008 Internals and Troubleshooting was SQL Server Waits and Extended Events.  Information about wait statistics has been available in SQL Server for a long time, and many of the vendors that develop monitoring applications for SQL Server have polling methods that query sys.dm_os_waiting_tasks or sys.sysprocesses to capture wait information about the tasks that are currently active in the system.  However one of the shortcomings of a polling method is that it misses a lot of the wait information because it is a point in time snapshot only.  If the polling interval is every second, only the active waits that exist at that second are captured, and any waits that occur between the polling interval is missed.  This information is still accumulated in sys.dm_os_wait_stats, but it is impossible to track it back to the statement level from that DMV.

Extended Events offers us the ability to capture information about waits without missing any of the information.  Already in this series we’ve seen how to use Extended Events with the Bucketizer Target to count the occurrences of waits by type.  This isn’t really a great use of Extended Events since sys.dm_os_wait_stats counts the occurrences of the wait types already, and a differential analysis of the information contained in sys.dm_os_wait_stats can provide this information.  The purpose of that example was to discuss the bug that existed in the RTM release of SQL Server 2008 more than it was to provide a sensible use for the target.  However, if we wanted to break our waits down by database, we could bucket on the database_id, and begin to understand which database had the most waits associated with it, but not by the individual wait type.  To get to that level of information, we need to collect all of the waits and the associated information for them to do further analysis.

There are two Events in Extended Events associated with wait types; sqlos.wait_info and sqlos.wait_info_external.  Looking at the description of the Events in the Metadata DMV’s we can get an idea of when each Event will fire.

SELECT name, description 
FROM sys.dm_xe_objects
WHERE name LIKE 'wait_info%'

The sqlos.wait_info_external Event will fire for wait types that begin with PREEMPTIVE_ in the name, and the sqlos.wait_info Event will fire for the other wait types that occur on the server.  Glenn Alan Berry (Blog|Twitter) has a great script that filters queries sys.dm_os_wait_stats and filters out common waits that are not generally problematic.  You can find his script on his blog post Updated SQL 2005 and 2008 Diagnostic Queries.  You can use this script to identify the most common waits on a server, and then use that information to build an Event Session that captures the session and statement information for those individual wait types.  In SQL Server 2008, there are 484 wait types listed in sys.dm_os_wait_stats and there are 599 map_value’s for the wait_types Map in sys.dm_xe_map_values.  The reason this is different is that the Map was created from the header file for the wait types and there are padded values that exist in the Map that don’t really correspond to wait types that exist in SQL Server.  However, there are also a couple of Maps for the wait_types that don’t match the wait type in sys.dm_os_wait_stats, the most notable being the ASYNC_NETWORK_IO to NETWORK_IO.

To build the Event Session, we just need to query sys.dm_map_values for our wait_types and use the map_key’s in the Predicate definition of the sqlos.wait_info or sqlos.wait_info_external Event as appropriate.  We can also do the same thing to build a generic Event Session that tracks the most common resource related waits.

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
        )

Once we have the list of map_key’s defined, we can do a replace in SSMS and change map_key to wait_type and define the predicate for the sqlos.wait_info Event for our Event Session.

CREATE EVENT SESSION [TrackResourceWaits] ON SERVER 
ADD EVENT  sqlos.wait_info
(    -- Capture the database_id, session_id, plan_handle, and sql_text
    ACTION(sqlserver.database_id,sqlserver.session_id,sqlserver.sql_text,sqlserver.plan_handle)
    WHERE
        (opcode = 1 --End Events Only
            AND duration > 100 -- had to accumulate 100ms of time
            AND ((wait_type > 0 AND wait_type < 22) -- LCK_ waits
                    OR (wait_type > 31 AND wait_type < 38) -- LATCH_ waits
                    OR (wait_type > 47 AND wait_type < 54) -- PAGELATCH_ waits
                    OR (wait_type > 63 AND wait_type < 70) -- PAGEIOLATCH_ waits
                    OR (wait_type > 96 AND wait_type < 100) -- IO (Disk/Network) waits
                    OR (wait_type = 107) -- RESOURCE_SEMAPHORE waits
                    OR (wait_type = 113) -- SOS_WORKER waits
                    OR (wait_type = 120) -- SOS_SCHEDULER_YIELD waits
                    OR (wait_type = 178) -- WRITELOG waits
                    OR (wait_type > 174 AND wait_type < 177) -- FCB_REPLICA_ waits
                    OR (wait_type = 186) -- CMEMTHREAD waits
                    OR (wait_type = 187) -- CXPACKET waits
                    OR (wait_type = 207) -- TRACEWRITE waits
                    OR (wait_type = 269) -- RESOURCE_SEMAPHORE_MUTEX waits
                    OR (wait_type = 283) -- RESOURCE_SEMAPHORE_QUERY_COMPILE waits
                    OR (wait_type = 284) -- RESOURCE_SEMAPHORE_SMALL_QUERY waits
                )
        )
)
ADD TARGET package0.ring_buffer(SET max_memory=4096)
WITH (EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,
      MAX_DISPATCH_LATENCY=5 SECONDS)
GO

Now that we have the Event Session defined, we can start it as needed to collect the resource wait information for our system.  The only concern with this Event Session is the Target being used.  If the Event Session is going to run for a long period of time, or if the waits on the server being monitored occur in large quantities, the Target should be changed away from the ring_buffer to the asynchronous_file_target.  I configured this session to only collect waits that exceed 100ms in duration.  If you want waits that have shorter durations this can easily be changed.  If you set the duration to be > 0 a lot of 1-5ms waits will be collected that aren’t generally interesting.  To query the wait information from this Event Session using the ring_buffer:

-- Extract the Event information from the Event Session 
SELECT 
    event_data.value('(event/@name)[1]', 'varchar(50)') AS event_name,
    DATEADD(hh, 
        DATEDIFF(hh, GETUTCDATE(), CURRENT_TIMESTAMP), 
        event_data.value('(event/@timestamp)[1]', 'datetime2')) AS [timestamp],
    COALESCE(event_data.value('(event/data[@name="database_id"]/value)[1]', 'int'), 
        event_data.value('(event/action[@name="database_id"]/value)[1]', 'int')) AS database_id,
    event_data.value('(event/action[@name="session_id"]/value)[1]', 'int') AS [session_id],
    event_data.value('(event/data[@name="wait_type"]/text)[1]', 'nvarchar(4000)') AS [wait_type],
    event_data.value('(event/data[@name="opcode"]/text)[1]', 'nvarchar(4000)') AS [opcode],
    event_data.value('(event/data[@name="duration"]/value)[1]', 'bigint') AS [duration],
    event_data.value('(event/data[@name="max_duration"]/value)[1]', 'bigint') AS [max_duration],
    event_data.value('(event/data[@name="total_duration"]/value)[1]', 'bigint') AS [total_duration],
    event_data.value('(event/data[@name="signal_duration"]/value)[1]', 'bigint') AS [signal_duration],
    event_data.value('(event/data[@name="completed_count"]/value)[1]', 'bigint') AS [completed_count],
    event_data.value('(event/action[@name="plan_handle"]/value)[1]', 'nvarchar(4000)') AS [plan_handle],
    event_data.value('(event/action[@name="sql_text"]/value)[1]', 'nvarchar(4000)') AS [sql_text]
FROM 
(    SELECT XEvent.query('.') AS event_data 
    FROM 
    (    -- Cast the target_data to XML 
        SELECT CAST(target_data AS XML) AS TargetData 
        FROM sys.dm_xe_session_targets st 
        JOIN sys.dm_xe_sessions s 
            ON s.address = st.event_session_address 
        WHERE name = 'TrackResourceWaits' 
          AND target_name = 'ring_buffer'
    ) AS Data 
    -- Split out the Event Nodes 
    CROSS APPLY TargetData.nodes ('RingBufferTarget/event') AS XEventData (XEvent)   
) AS tab (event_data)

In the result set, you will notice that some of the wait_info Events do not have an associated session_id, database_id, plan_handle, or sql_text value.  Depending on where the wait actually occurs in code, this information is not available to the firing Event, for example, the NETWORK_IO Event generally does not successfully collect these Actions.

While collecting session and statement level waits like this is certainly interesting, there are some considerations that have to be made whenever you look at wait information like this.  The first consideration is that, while a specific session or statement waited on a resource, that doesn’t necessarily mean that the problem exists within that session or statement.  Take for example a query that has to wait 500ms on ASYNC_IO_COMPLETION waits.  At the same time that query is executing there are 10 DSS queries running that scan large ranges of data from the database data files and generate a lot of IO activity.  Where exactly is the problem?  The root problem is that there is a disk IO bottleneck, but not necessarily related to the query that is waiting on disk IO, it could be another query performing Table Scan that is leading to the heavy IO activity.