THE SQL Server Blog Spot on the Web

Welcome to SQLblog.com - The SQL Server blog spot on the web Sign in | |
in Search

Davide Mauri

A place for my thoughts and experiences the Microsoft Data Platform

Extended Events did it again: monitoring Stored Procedures performance

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.

Published Tuesday, March 19, 2013 7:14 PM by Davide Mauri

Comment Notification

If you would like to receive an email when updates are made to this post, please register here

Subscribe to this post's comments using RSS

Comments

 

Jonathan Kehayias said:

I'm curious why you add so many actions to the events that you aren't actually using in the results?  Each action has to execute code inside the engine, so ideally you'd restrict the list of actions to only the ones that provide data that is going to be used.

April 15, 2013 2:15 PM
 

Andreas Wolter said:

Hey Davide,

Just a tip for an optimization: You can as well just use the object_id instead of the name (unless there is the possibility of Drop - Re-Creates happening)

April 15, 2013 2:29 PM

Leave a Comment

(required) 
(required) 
Submit

About Davide Mauri

Director of Software Development & Cloud Infrastructure @ Sensoria, an innovative smart garments and wearable company. After more than 15 year playing with the Microsoft Data Platform, with a specific focus on High Performance databases, Business Intelligence, Data Science and Data Architectures, he's now applying all his skills to IoT, defining architectures to crunch numbers, create nice user experiences and provide meaningful insights, all leveraging Microsoft Azure cloud. MVP on Data Platform since 2006 he has a very strong background development and love both the ER model and OO principles. He is also a fan of Agile Methodology and Automation, which he tries to apply everywhere he can, to make sure that "people think, machines do".

This Blog

Syndication

Privacy Statement