Analyzing Statements with Extended Events (Extended Events Part II)

Clas Hortien offers us another great article as next part of his series on XEvents. Great work Clas

In my previous post I shortly described how to examine the trace information from the built-in Extended Event session system_health. Today I want to show you, how to setup your own session to collect information about long running and expensive statements.

We start with a cleanup to ensure that there is no existing session with the same name.

IF EXISTS(SELECT * FROM sys.server_event_sessions WHERE name='Expensive_Queries')
DROP EVENT SESSION [Expensive_Queries] ON SERVER;
GO

We create the session ‘Expensive_Queries’ on the server with the CREATE EVENT SESSION command:

CREATE EVENT SESSION [Expensive_Queries] ON SERVER
ADD EVENT sqlserver.sql_statement_completed(
ACTION (sqlserver.database_id,
sqlserver.plan_handle,
sqlserver.session_id,
sqlserver.sql_text)
WHERE (([reads]>(100)) or [cpu] >(50) or [duration] > (1000)))
ADD TARGET package0.ring_buffer(SET max_memory=2048),
ADD TARGET package0.asynchronous_bucketizer(
SET filtering_event_name='sqlserver.sql_statement_completed',
source='sqlserver.sql_text')
WITH (MAX_MEMORY = 4096KB,
EVENT_RETENTION_MODE = ALLOW_SINGLE_EVENT_LOSS,
MAX_DISPATCH_LATENCY = 10 SECONDS,
MAX_EVENT_SIZE = 0KB,
MEMORY_PARTITION_MODE = NONE,
TRACK_CAUSALITY = OFF,
STARTUP_STATE = OFF)
GO

The create statement consists of multiple parts. As the first step we add the event the session has to react on. In our case we want to act, when the SQL statement is completed (sqlserver.sql_statement_completed). With this event, we will get information about the object_id, the object_type, the CPU usage consumed by the statement, as well as the duration and the reads and writes issued. This information is collected by default for this event. As additional information (actions) we want to collect the database_id, the plan_handle of the generated SQL plan, the session_id of the executing session and the SQL text.

As we are looking for expensive and long running statements, we added a predicate on the event, which will limit the events to events with more than 100 reads or with a duration longer than a second or with more than 50 ms CPU consumption. These thresholds can be set higher/lower, depending on your system and workload. The given thresholds should be interpreted only as an idea or example.

As the main target we are using a ring buffer with a size of two megabyte. If the ring buffer is too small, the generated XML data will be truncated.

As a second target we are using a asynchronous bucketizer, which will collect the SQL text of the statements. This bucketizer target will only collect the SQL Text and how often this exact statement was executed. It will give us some sort of summary over the expensive statements, agregated by execution count.

The last section sets the session options all to their default settings. If you want to fiddle around with the session to test, you might want to set the MAX_DISPATCH_LATENCY to 1 second, as then the events will be faster pushed from the session buffer to the target, where you can retrieve them.

When you execute the statement above, the session just gets created, but is not running. To start the session we have to execute:

ALTER EVENT SESSION [Expensive_Queries] ON SERVER STATE = START
GO

 After successful execution, the session is running and the events are collected. To retrieve the data, we have to query and parse the XML of the target. To get the raw XML of the targets, you can query sys.dm_xe_session_targets with:

SELECT CAST(target_data as xml) as Bucket
FROM sys.dm_xe_session_targets st join
sys.dm_xe_sessions s on s.address = st.event_session_address
WHERE name = 'Expensive_Queries'

In our case you will get a two line output, one for each target:

When you click on the XML links in the results, you will get the XML of the target in a new SSMS windows.

To get a more readable and useful output, we will parse the XML of the target. First we query the ring buffer to see the latest statements, ordered by the duration of the runtime of the statement:

 SELECT
Slots.value('(data/value)[4]', 'BIGINT') as cpu,
Slots.value('(data/value)[5]', 'BIGINT') as duration,
Slots.value('(data/value)[6]', 'BIGINT') as reads,
Slots.value('(data/value)[7]', 'BIGINT') as writes,
db_name(Slots.value('(action/value)[1]', 'INT')) as database_id,
qp.query_plan,
Slots.value('(action/value)[3]', 'INT') as session_id,
Slots.value('(action/value)[4]', 'nvarchar(max)') as sql_text
FROM
(SELECT CAST(target_data as xml) as Bucket
FROM sys.dm_xe_session_targets st join
sys.dm_xe_sessions s on s.address = st.event_session_address
WHERE name = 'Expensive_Queries') AS Buckets
CROSS APPLY Bucket.nodes ('//RingBufferTarget/event') AS XE(Slots)
CROSS APPLY sys.dm_exec_query_plan(convert(varbinary(max),
    substring(Slots.value('(action/value)[2]',
'nvarchar(max)'),15,50),1)) as qp
WHERE Slots.value(<'@name'>, 'varchar(4000)') = 'sql_statement_completed'
ORDER BY Slots.value('(data/value)[5]', 'BIGINT') desc -- Order by Duration
 

For the SQL plan we applied sys.dm_exec_query_plan, to get a clickable result to view the plan. The results will look like:

 This output only represents the latest statements that fulfill the thresholds of the event session and which are not were overwritten in the ring buffer. Remember that in a ring buffer target the buffer has a fixed size (2 MB as specified in the event session) and when more events are collected, old events will be overwritten. Therefore the target will only show the last 2 MB of expensive statements.

To get additional information, we added the bucketizer target. The query to get the data out of it, looks very similar to the query for the ring buffer, except the bucketizer target stores only 2 needed columns and is sorted by the bucket count by default:

SELECT
bucket_count=Slots.value(<'@count'>, 'bigint' ),
sql_text = Slots.value('.', 'nvarchar(4000)')
FROM (SELECT cast(xest.target_data as xml) as Bucket
FROM sys.dm_xe_session_targets xest join sys.dm_xe_sessions xes on
xes.address = xest.event_session_address
WHERE xest.target_name = 'asynchronous_bucketizer' and
xes.name = 'Expensive_Queries') as Buckets
CROSS APPLY Bucket.nodes('//BucketizerTarget/Slot') as XE(Slots)

The query will give us a result like this:

 All the queries fulfill the thresholds of the event session. The bucket_count columns shows how often this exact query was executed, since the event session was started. As the used system is only a test system, the list shows mainly maintenance tasks.

So even when the ring buffer does not show the query anymore, because events got overwritten, you still can see them here. In our example the ‘select top 1 name from sysobjects’ was no longer in the ring buffer target, but still showed up in the bucketizer target, as it was run so often. Btw, this statement was caused by an SGEN run on my system.

With this outline, you should be able to setup your own first session to collect information of long running or expensive statements. We are currently discussing how the functionality of extended events can be utilized by the SAP database monitor in the future. Expect requests from SAP support for extended events output in the future, as this tool will give more in depth information of the underlying SQL Server and can help to analyze uncommon system states easily.

The next blog about Extended Events will show how to get more information about still running statements.

Regards    Clas