SQL Server 2012/2014 Extended Events for Developers – Part 1

By Jeffry Schwartz | Expert

Jan 28

— By Jeffry Schwartz

Microsoft introduced Extended Events, a.k.a. XEvents, in SQL Server 2008 to aid in the analysis of performance problems. Both the capabilities and syntax were changed significantly on SQL Server 2012, and new (and very important) features were added in SQL Server 2014. Therefore, the focus of this document will be on XEvent usage with SQL Server 2012 and 2014. Specifically, it will concentrate on how developers can use XEvents to evaluate the performance of their queries and stored procedures regardless of how they are invoked, e.g., from a user interface.

Creating and Starting an XEvent Session

The first action is to define and create an XEvent session. One can think of a session as a definition of the events that will be captured along with any filtering that may be appropriate for each event. Once defined, an analyst can simply start and stop the session without specifying anything else. This makes it ideal for developers in a shared environment because they can establish a tailored definition once and then use it repeatedly for arbitrary periods. The code below deletes a pre-existing session named DevPerformanceMonitoring, and establishes a new session definition.

USE master

GO

IF EXISTS(SELECT * FROM sys.server_event_sessions WHERE name=‘DevPerformanceMonitoring’)

DROP EVENT SESSION DevPerformanceMonitoring ON SERVER

GO

CREATE EVENT SESSION DevPerformanceMonitoring ON SERVER

ADD EVENT sqlserver.rpc_completed(

SET collect_statement=(1)

ACTION(sqlserver.database_id, sqlserver.database_name, sqlserver.sql_text, sqlserver.tsql_frame, sqlserver.tsql_stack, sqlserver.server_principal_name, sqlserver.query_hash, sqlserver.query_plan_hash)

WHERE ([duration]>(10000) AND database_id = 9) — SQL won’t tolerate a variable in here…ugh!

),

ADD EVENT sqlserver.sp_statement_completed(

SET collect_statement=(1), collect_object_name=(1)

ACTION(sqlserver.database_id, sqlserver.database_name, sqlserver.sql_text, sqlserver.tsql_frame, sqlserver.tsql_stack, sqlserver.server_principal_name, sqlserver.query_hash, sqlserver.query_plan_hash)

WHERE ([duration]>(10000) AND database_id = 9)

),

ADD EVENT sqlserver.sql_batch_completed(

ACTION(sqlserver.database_id, sqlserver.database_name, sqlserver.sql_text, sqlserver.tsql_frame, sqlserver.tsql_stack, sqlserver.server_principal_name, sqlserver.query_hash, sqlserver.query_plan_hash)

WHERE ([duration]>(10000) AND database_id = 9)

),

ADD EVENT sqlserver.sql_statement_completed(

SET collect_statement=(1)

ACTION(sqlserver.database_id, sqlserver.database_name, sqlserver.sql_text, sqlserver.tsql_frame, sqlserver.tsql_stack, sqlserver.server_principal_name, sqlserver.query_hash, sqlserver.query_plan_hash)

WHERE ([duration]>(10000) AND database_id = 9)

)

ADD TARGET package0.event_file(SET FILENAME= N’D:\SQLRx\SQLScriptOutput\DevPerf.xel’)

WITH (MAX_MEMORY=4096 KB, EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS, MAX_DISPATCH_LATENCY=30 SECONDS, MAX_EVENT_SIZE=0 KB, MEMORY_PARTITION_MODE=NONE, TRACK_CAUSALITY=OFF, STARTUP_STATE=OFF

 

This session monitors RPC completed, SP statement completed, SQL batch completed, and SQL statement completed events whose duration is longer than ten milliseconds (10,000 microseconds) and whose database ID is 9. It stores the information in a file that will reside in the D:\SQLRx\SQLScriptOutput directory, and has the DevPerf prefix as well as the .XEL extension. Note: This directory MUST exist before starting the session or it will fail. Note: Unfortunately, as noted in the comments for the rpc_completed event (and still true as of SQL Server 2014 SP1), variables cannot be used in WHERE clauses. This causes the repetitive filtering code shown above. Should one desire filtering based upon user login, this should be specified as one of the filters in the where clauses, e.g., server_principal_name = (‘<instance>\<login>).

To start this session, the user must issue the following command: ALTER EVENT SESSION DevPerformanceMonitoring ON SERVER STATE = START

To stop the session, the user must issue the following command: ALTER EVENT SESSION DevPerformanceMonitoring ON SERVER STATE = STOP

The actual file names will be DevPerf<large integer value>.xel where <large integer value> is the number of milliseconds between the date and time that the file is created and January 1, 1600 as shown below:

Blog_20160128_1

Obtaining Performance Data Directly from an XEvent XEL File

SSMS Method

Once the events have been captured to a file by starting and then stopping a session, the next step is to query the data. One can use two methods for this: open the XEL file directly from SSMS or use a T-SQL query to read it. The first method is a bit limited because the developer cannot perform searches easily and its output is shown below. Note: times are in microseconds.

Blog_20160128_2

T-SQL Method

The second method is a bit daunting at first, but once a developer has an example from which to work, the task is reasonable, and with practice, relatively easy. The following script illustrates how to navigate the XEL file DIRECTLY using the sys.fn_xe_file_target_read_file function and begin extracting the information, for which XML format is used. The first query lists the event names along with their associated timestamps and XML. It uses the cross apply operator to gain access to the event_data XML column so the event’s name and timestamp can be extracted. This query illustrates the method by which someone new to the process can understand what is contained within the event_data XML, and it also demonstrates how to extract single data elements from the XML.

The handling of the @timestamp node merits further discussion. Event_data timestamps are expressed in UTC time, so one needs to adjust them to understand exactly when things happened. The code in the script that makes it time zone agnostic and automatically determines what the adjustment from UTC time should be in order to be correct for the current time zone.

The second query uses the same mechanism to summarize the number and names of all the events contained within a particular file. The output for both select statements immediately follows the script. The developer can click on the xml_event_data within SSMS and view the entire XML data set.

DECLARE @TraceDir varchar(512)

DECLARE @XeventsTraceName varchar(512) = ‘DevPerf_0_130966819185620000.xel’

SET @TraceDir = ‘D:\SQLRx\SQLScriptOutput\’

— dump entire XEL file so we can see what nodes are present

SELECT event_xml.value(‘(./@name)’, ‘varchar(128)’) AS EventName,

DATEADD(hh,

DATEDIFF(hh, GETUTCDATE(), CURRENT_TIMESTAMP),

event_xml.value(‘(./@timestamp)[1]’, ‘datetime2’)

) AS PostedTimestamp,

xml_event_data

FROM

(SELECT CAST(event_data AS XML) AS xml_event_data

FROM sys.fn_xe_file_target_read_file(@TraceDir + @XeventsTraceName, null, null, null)

) AS event_table

CROSS APPLY xml_event_data.nodes(‘//event’) EventDataNodes (event_xml);

— dump entire XEL file summarizing by event name so we can be sure we have reported all the ones that have been captured

WITH EventDetails AS (

SELECT event_xml.value(‘(./@name)’, ‘varchar(128)’) AS EventName

FROM

(SELECT CAST(event_data AS XML) AS xml_event_data

FROM sys.fn_xe_file_target_read_file(@TraceDir + @XeventsTraceName, null, null, null)

) AS event_table

CROSS APPLY xml_event_data.nodes(‘//event’) EventDataNodes (event_xml)

)

SELECT EventName, COUNT(*) AS [Count]

FROM EventDetails

GROUP BY EventName

ORDER BY EventName

 

Blog_20160128_3

Obtaining XEvent Record Details

The next script uses the same method as the previous one. The primary differences are that it extracts more data from the XML and uses a common table expression to simplify the inclusion of certain events and the exclusion of certain SQL statements in which we are not interested. The where EventName in (@EventNameToBeSearchedFor1, @EventNameToBeSearchedFor2, @EventNameToBeSearchedFor3, @EventNameToBeSearchedFor4) and SQLStatement not like ‘%DefaultFileStreamFileGroup%’ and SQLStatement not like ‘%CollationVersion%’ portion accomplishes this filtering. The output appears below the script and lists the events along with their duration, CPU time, last row count, physical reads, logical reads, writes, and the text of the SQL statement.

The reader should note the action and data references that are highlighted in the code below. Action items are generally included with every XEvent record (sometimes referred to as global columns), whereas data items contain information specific to an event, e.g., sp_statement_completed. In order to augment the script below, one must understand the differences between actions and data items.

Not all events utilize the same keywords, so the “case when” code below handles the differences to extract the SQL statement from the appropriate node. Another reason for using the common table expression was to make the NOT LIKE operator function simply and as desired. When the NOT LIKE operator was used in a where clause directly with the XML, the code was very clumsy and difficult to achieve the desired results. Placing the XML portion in a common table expression with the where clause on the outside greatly simplified the code and enabled it to operate correctly.

DECLARE @EventNameToBeSearchedFor1 VARCHAR(40)

DECLARE @EventNameToBeSearchedFor2 VARCHAR(40)

DECLARE @EventNameToBeSearchedFor3 VARCHAR(40)

DECLARE @EventNameToBeSearchedFor4 VARCHAR(40)

DECLARE @TraceDir VARCHAR(512)

DECLARE @NumMinutesUTCDiff INT = DATEPART(tz,SYSDATETIMEOFFSET())

DECLARE @XeventsTraceName VARCHAR(512) = ‘DevPerf_0_130966819185620000.xel’

 

SET @TraceDir = ‘D:\SQLRx\SQLScriptOutput’

SET @TraceDir = @TraceDir + ‘\’

SET @EventNameToBeSearchedFor1 = ‘sp_statement_completed’

SET @EventNameToBeSearchedFor2 = ‘sql_statement_completed’

SET @EventNameToBeSearchedFor3 = ‘sql_batch_completed’

SET @EventNameToBeSearchedFor4 = ‘rpc_completed’

— Parse XML from the file to show column-wise output

— use CTE to simplify the where clause like conditions

;

WITH ParsedXMLData AS (

SELECT

event_xml.value(‘(./@name)’, ‘varchar(128)’) AS EventName,

DATEADD(hh, @NumMinutesUTCDiff, event_xml.value(‘(./@timestamp)’, ‘datetime’)) AS PostedTimestamp,

event_xml.value(‘(./action[@name=”database_name”]/value)[1]’, ‘varchar(128)’) AS DatabaseName,

OBJECT_NAME(CAST(event_xml.value(‘(./data[@name=”object_id”]/value)[1]’, ‘int’) AS INT), CAST(event_xml.value(‘(./data[@name=”source_database_id”]/value)[1]’, ‘int’) AS INT)) AS ObjectName,

event_xml.value(‘(./data[@name=”object_type”]/text)[1]’, ‘varchar(25)’) AS ObjectType,

CAST(event_xml.value(‘(./data[@name=”duration”]/value)[1]’, ‘bigint’) AS BIGINT)/1000000.0 AS DurationSecs,

CAST(event_xml.value(‘(./data[@name=”cpu_time”]/value)[1]’, ‘bigint’) AS BIGINT)/1000000.0 AS CPUTimeSecs,

event_xml.value(‘(./data[@name=”row_count”]/value)[1]’, ‘int’) AS [RowCount],

event_xml.value(‘(./data[@name=”last_row_count”]/value)[1]’, ‘int’) AS LastRowCount,

event_xml.value(‘(./data[@name=”physical_reads”]/value)[1]’, ‘bigint’) AS PhysicalReads,

event_xml.value(‘(./data[@name=”logical_reads”]/value)[1]’, ‘bigint’) AS LogicalReads,

event_xml.value(‘(./data[@name=”writes”]/value)[1]’, ‘bigint’) AS Writes,

event_xml.value(‘(./data[@name=”nest_level”]/value)[1]’, ‘int’) AS NestLevel,

CASE WHEN event_xml.value(‘(./data[@name=”statement”]/value)[1]’, ‘varchar(max)’) IS NULL THEN

event_xml.value(‘(./data[@name=”batch_text”]/value)[1]’, ‘varchar(max)’) ELSE

event_xml.value(‘(./data[@name=”statement”]/value)[1]’, ‘varchar(max)’) END AS SQLStatement,

event_xml.value(‘(./action[@name=”sql_text”]/value)[1]’, ‘varchar(max)’) AS SQLText,

event_xml.value(‘(./data[@name=”source_database_id”]/value)[1]’, ‘int’) AS source_database_id,

event_xml.value(‘(./data[@name=”object_id”]/value)[1]’, ‘int‘) as object_id,

event_xml.value(‘(./data[@name=”object_type”]/value)[1]’, ‘varchar(25)’) AS object_type

FROM

(SELECT CAST(event_data AS XML) AS xml_event_data

FROM sys.fn_xe_file_target_read_file(@TraceDir + @XeventsTraceName, null, null, null)

) AS event_table

CROSS APPLY xml_event_data.nodes(‘//event’) EventDataNodes (event_xml)

)

SELECT *

FROM ParsedXMLData

WHERE EventName IN (@EventNameToBeSearchedFor1, @EventNameToBeSearchedFor2, @EventNameToBeSearchedFor3, @EventNameToBeSearchedFor4)

AND SQLStatement NOT LIKE ‘%DefaultFileStreamFileGroup%’

AND SQLStatement NOT LIKE ‘%CollationVersion%’

 

Blog_20160128_4

Summary

This article covered how to create, start, and stop XEvents sessions using T-SQL and report the output using either SSMS or T-SQL. SSMS provides a convenient method for viewing the data quickly, but is difficult to use for searches of any kind or any additional filtering. T-SQL appears to be difficult at first because of the XQuery language, but once one becomes accustomed to the XML layout, obtaining specific pieces of data is reasonably easy. More advanced subjects such as collecting query_post_execution_showplan events and connecting these plans to other completed events will be covered in subsequent articles.

About the Author

>