In the last days I had to work quite a lot with extended events in order to deeply monitor SQL Server performance. One interesting request that came out while implementing the monitoring infrastructure, was the possibility to monitor the performance of a set of stored procedures, vital for the correct handling of an online booking procedure.
The challenge was to give a sort of real-time monitor of procedure performances so that one can then create alert and/or do some stream-analysis to keep response time always under the desired amount of time.
Here’s how you can do it using Extended Events, monitoring, for example, the execution of procedure uspGetManagerEmployees in AdventureWorks2012:
CREATE EVENT SESSION [monitor_procedure_performance] ON SERVER
ADD EVENT sqlserver.rpc_completed
(
ACTION (package0.collect_system_time,package0.process_id,sqlserver.client_app_name,sqlserver.client_connection_id,sqlserver.client_hostname,sqlserver.client_pid,sqlserver.database_id,sqlserver.database_name,sqlserver.nt_username,sqlserver.request_id,sqlserver.session_id,sqlserver.session_nt_username,sqlserver.sql_text,sqlserver.transaction_id,sqlserver.transaction_sequence,sqlserver.username)
WHERE ([object_name]=N'uspGetManagerEmployees')
),
ADD EVENT sqlserver.module_end
(
ACTION (package0.collect_system_time,package0.process_id,sqlserver.client_app_name,sqlserver.client_connection_id,sqlserver.client_hostname,sqlserver.client_pid,sqlserver.database_id,sqlserver.database_name,sqlserver.nt_username,sqlserver.request_id,sqlserver.session_id,sqlserver.session_nt_username,sqlserver.sql_text,sqlserver.transaction_id,sqlserver.transaction_sequence,sqlserver.username)
WHERE ([object_name]=N'uspGetManagerEmployees')
)
ADD TARGET package0.ring_buffer
WITH
(
STARTUP_STATE=OFF
)
GO
Once done, it’s all about decoding the XML that Extended Events returns:
/*
Analyze XEvent data
*/
IF (OBJECT_ID('tempdb..#t') IS NOT NULL) DROP TABLE #t
IF (OBJECT_ID('tempdb..#r') IS NOT NULL) DROP TABLE #r
go
select
cast(target_data as xml) xdoc
into
#t
from
sys.dm_xe_sessions s
inner join
sys.dm_xe_session_targets t on t.event_session_address = s.address
where
s.name = 'monitor_procedure_performance'
;
with cte as
(
select
event_number = ROW_NUMBER() over (order by T.x),
event_timestamp = T.x.value('@timestamp', 'datetimeoffset'),
T.x.query('.') as event_data
from
#t
cross apply
xdoc.nodes('/RingBufferTarget/event') T(x)
),
cte2 as (
select
c.event_number,
c.event_timestamp,
--data_field = T2.x.value('local-name(.)', 'varchar(100)'),
data_name = T2.x.value('@name', 'varchar(100)'),
data_value = T2.x.value('value[1]', 'varchar(100)'),
data_text = T2.x.value('text[1]', 'varchar(max)')
from
cte c
cross apply
c.event_data.nodes('event/*') T2(x)
),
cte3 as (
select
*
from
cte2
where
data_name in ('collect_system_time', 'object_name', 'cpu_time', 'duration', 'logical_reads', 'row_count', 'database_name', 'database_id')
)
select
*
into
#r
from
cte3
pivot
(max(data_value) for data_name in (database_id, database_name, object_name, cpu_time, duration, logical_reads, row_count)) T
go
--SELECT * FROM #t
SELECT * FROM #r
go
select
execution_date = cast(event_timestamp as date),
execution_hour = datepart(hour, event_timestamp),
execution_minute = datepart(minute, event_timestamp),
[object_name],
duration_msec = avg(cast(duration as int)) / 1000.
from
#r
group by
cast(event_timestamp as date), datepart(hour, event_timestamp), datepart(minute, event_timestamp), [object_name]
That’s it. You can now keep monitored execution times of your procedure.