Extended Events in SQL Server

Extended Events in SQL Server

Introduction-

Extended Events (XEvents) is a highly scalable and adaptable event-driven monitoring system that debuted with SQL Server 2008. It is intended to assist database administrators (DBAs) and developers in gathering extensive information on SQL Server behavior, such as performance issues, query execution, and system diagnostics. Extended Events' architecture provides for minimum performance effect, making it appropriate for use in production applications.

 

Let us break down the word "Extended Events" and explain each component:

 

Extended-

The name indicates that this feature goes beyond typical monitoring and tracing tools such as SQL Trace and SQL Server Profiler. It has more events, targets, and configuration choices, making it more adaptable and comprehensive.

Events-

Events are locations of interest within the SQL Server engine where activities take place. Examples include query execution, login attempts, and failures. When an event occurs, the Extended Events system can collect it, along with any pertinent data.

Extended Events are based on several fundamental components:

Events-

These are the happenings in SQL Server that you want to track. Each event is assigned a unique name and contains detailed data about the occurrence.

Event Sessions-

To gather data, you must create an event session. An event session specifies which events to monitor, what data to gather, and how to store the data.

Targets-

The locations where the information gathered during an event session is kept are known as targets. Targets include things like event files, which write the data to disk files, ring buffers, which store the data in memory, and histograms, which aggregate the data according to predetermined standards.

Actions-

Further components, such as the SQL Server process ID or the execution time, can be appended to session events in order to gather further context.

Predicates-

Predicates let you filter occurrences according to particular standards, ensuring that you only gather the information you're interested in. This lessens the effect on system performance and helps to reduce the amount of data that is gathered.

Create Extended Events in SQL Server-

Let us create an Event for 5 seconds. Which query takes 5 seconds to finish will be tracked by this event.

 

IF EXISTS (SELECT 1 FROM sys.server_event_sessions WHERE name = 'DurationOver5Sec')

       DROP EVENT SESSION [DurationOver5Sec] ON SERVER;

GO

CREATE EVENT SESSION [DurationOver5Sec]

ON SERVER

 

ADD EVENT sqlserver.rpc_completed(

       ACTION

       (

               sqlserver.client_app_name -- ApplicationName from SQLTrace

             , sqlserver.client_hostname -- HostName from SQLTrace

             , sqlserver.client_pid     -- ClientProcessID from SQLTrace

             , sqlserver.database_id     -- DatabaseID from SQLTrace

             , sqlserver.request_id     -- RequestID from SQLTrace

             , sqlserver.server_principal_name  -- LoginName from SQLTrace

             , sqlserver.session_id     -- SPID from SQLTrace

       )

       WHERE

       (

                    duration >= 5000000

       )

),

ADD EVENT sqlserver.sql_batch_completed(

       ACTION

       (

               sqlserver.client_app_name -- ApplicationName from SQLTrace

             , sqlserver.client_hostname -- HostName from SQLTrace

             , sqlserver.client_pid     -- ClientProcessID from SQLTrace

             , sqlserver.database_id     -- DatabaseID from SQLTrace

             , sqlserver.request_id     -- RequestID from SQLTrace

             , sqlserver.server_principal_name  -- LoginName from SQLTrace

             , sqlserver.session_id     -- SPID from SQLTrace

       )

       WHERE

       (

             duration >= 5000000

       )

),

ADD EVENT sqlos.wait_info(

       ACTION

       (

               sqlserver.client_app_name -- ApplicationName from SQLTrace

             , sqlserver.client_hostname -- HostName from SQLTrace

             , sqlserver.client_pid     -- ClientProcessID from SQLTrace

             , sqlserver.database_id     -- DatabaseID from SQLTrace

             , sqlserver.request_id     -- RequestID from SQLTrace

             , sqlserver.server_principal_name  -- LoginName from SQLTrace

             , sqlserver.session_id     -- SPID from SQLTrace

       )

       WHERE

       (

             duration > 5000 --This one is in milliseconds, and I'm not happy about that

            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

       --OR (wait_type = 195) -- WAITFOR

                )

       )

)

ADD TARGET package0.event_file

(

       SET filename = 'DurationOver5Sec.xel',

             max_file_size = 10,

             max_rollover_files = 5

)

WITH

(

       MAX_MEMORY = 10MB

       , MAX_EVENT_SIZE = 10MB

       , STARTUP_STATE = ON

       , MAX_DISPATCH_LATENCY = 5 SECONDS

       , EVENT_RETENTION_MODE = ALLOW_MULTIPLE_EVENT_LOSS

);

 

ALTER EVENT SESSION DurationOver5Sec

ON SERVER

STATE = START;

How to Check the server for events-

This query allows us to simply check the query.

 

 

DECLARE

       @SessionName SysName

       , @TopCount Int = 1000

 

--SELECT @SessionName = 'UserErrors'

SELECT @SessionName = 'DurationOver5Sec'

--SELECT @SessionName = 'system_health'

/*

SELECT * FROM sys.traces

 

SELECT  Session_Name = s.name, s.blocked_event_fire_time, s.dropped_buffer_count, s.dropped_event_count, s.pending_buffers

FROM sys.dm_xe_session_targets t

       INNER JOIN sys.dm_xe_sessions s ON s.address = t.event_session_address

WHERE target_name = 'event_file'

--*/

 

SET STATISTICS IO, TIME ON

 

IF OBJECT_ID('tempdb..#Events') IS NOT NULL BEGIN

       DROP TABLE #Events

END

 

IF OBJECT_ID('tempdb..#Queries') IS NOT NULL BEGIN

       DROP TABLE #Queries

END

 

DECLARE @Target_File NVarChar(1000)

       , @Target_Dir NVarChar(1000)

       , @Target_File_WildCard NVarChar(1000)

 

SELECT @Target_File = CAST(t.target_data as XML).value('EventFileTarget[1]/File[1]/@name', 'NVARCHAR(256)')

FROM sys.dm_xe_session_targets t

       INNER JOIN sys.dm_xe_sessions s ON s.address = t.event_session_address

WHERE s.name = @SessionName

       AND t.target_name = 'event_file'

 

SELECT @Target_Dir = LEFT(@Target_File, Len(@Target_File) - CHARINDEX('\', REVERSE(@Target_File)))

 

SELECT @Target_File_WildCard = @Target_Dir + '\'  + @SessionName + '_*.xel'

 

--SELECT @Target_File_WildCard

 

SELECT TOP (@TopCount) CAST(event_data AS XML) AS event_data_XML

INTO #Events

FROM sys.fn_xe_file_target_read_file(@Target_File_WildCard, null, null, null) AS F

ORDER BY File_name DESC

       , file_offset DESC

 

SELECT  EventType = event_data_XML.value('(event/@name)[1]', 'varchar(50)')

       , Duration_sec = CAST(event_data_XML.value ('(/event/data[@name=''duration'']/value)[1]', 'BIGINT')/CASE WHEN event_data_XML.value('(event/@name)[1]', 'varchar(50)') LIKE 'wait%' THEN 1000.0 ELSE 1000000.0 END as DEC(20,3))

       , CPU_sec = CAST(event_data_XML.value ('(/event/data[@name=''cpu_time'']/value)[1]', 'BIGINT')/1000000.0 as DEC(20,3))

       , physical_reads_k = CAST(event_data_XML.value ('(/event/data  [@name=''physical_reads'']/value)[1]', 'BIGINT')/1000.0 as DEC(20,3))

       , logical_reads_k = CAST(event_data_XML.value ('(/event/data  [@name=''logical_reads'']/value)[1]', 'BIGINT') /1000.0 as DEC(20,3))

       , writes_k = CAST(event_data_XML.value ('(/event/data  [@name=''writes'']/value)[1]', 'BIGINT')/1000.0 as DEC(20,3))

       , row_count = event_data_XML.value ('(/event/data  [@name=''row_count'']/value)[1]', 'BIGINT')

       , Statement_Text = ISNULL(event_data_XML.value ('(/event/data  [@name=''statement'']/value)[1]', 'NVARCHAR(4000)'), event_data_XML.value ('(/event/data  [@name=''batch_text''     ]/value)[1]', 'NVARCHAR(4000)'))

       , TimeStamp = DateAdd(Hour, DateDiff(Hour, GetUTCDate(), GetDate()) , CAST(event_data_XML.value('(event/@timestamp)[1]', 'varchar(50)') as DateTime2))

       , SPID = event_data_XML.value ('(/event/action  [@name=''session_id'']/value)[1]', 'BIGINT')

       , Username = event_data_XML.value ('(/event/action  [@name=''server_principal_name'']/value)[1]', 'NVARCHAR(256)')

       , Database_Name = DB_Name(event_data_XML.value ('(/event/action  [@name=''database_id'']/value)[1]', 'BIGINT'))

       , client_app_name = event_data_XML.value ('(/event/action  [@name=''client_app_name'']/value)[1]', 'NVARCHAR(256)')

       , client_hostname = event_data_XML.value ('(/event/action  [@name=''client_hostname'']/value)[1]', 'NVARCHAR(256)')

       , result = ISNULL(event_data_XML.value('(/event/data  [@name=''result'']/text)[1]', 'NVARCHAR(256)'),event_data_XML.value('(/event/data  [@name=''message'']/value)[1]', 'NVARCHAR(256)'))

       , Error = event_data_XML.value ('(/event/data  [@name=''error_number'']/value)[1]', 'BIGINT')

       , Severity = event_data_XML.value ('(/event/data  [@name=''severity'']/value)[1]', 'BIGINT')

       , EventDetails = event_data_XML

INTO #Queries

FROM #Events

 

SELECT q.EventType

       , q.Duration_sec

       , q.CPU_sec

       , q.physical_reads_k

       , q.logical_reads_k

       , q.writes_k

       , q.row_count

       , q.Statement_Text

       , q.TimeStamp

       , q.SPID

       , q.Username

       , q.Database_Name

       , client_app_name = CASE LEFT(q.client_app_name, 29)

                                 WHEN 'SQLAgent - TSQL JobStep (Job '

                                        THEN 'SQLAgent Job: ' + (SELECT name FROM msdb..sysjobs sj WHERE substring(q.client_app_name,32,32)=(substring(sys.fn_varbintohexstr(sj.job_id),3,100))) + ' - ' + SUBSTRING(q.client_app_name, 67, len(q.client_app_name)-67)

                                 ELSE q.client_app_name

                                 END 

       , q.client_hostname

       , q.result

       , q.Error

       , q.Severity

       , q.EventDetails

FROM #Queries q

--WHERE eventtype NOT IN /*rather typical filtering*/ ('security_error_ring_buffer_recorded', 'sp_server_diagnostics_component_result', 'scheduler_monitor_system_health_ring_buffer_record')

       --AND eventtype NOT IN /*specific troubleshooting filtering*/ ('connectivity_ring_buffer_recorded', 'wait_info')

ORDER BY TimeStamp DESC