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 on SQL Server, Business Intelligence and .NET

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

Davide Mauri - MCP, MCAD, MCDBA, MCT, MVP on SQL Server - has worked with SQL Server since version 6.5, and his interests cover the whole platform, from the Relational Engine to Analysis Services, from architecture definition to performance tuning. He also has a strong knowledge of XML, .NET and the Object Oriented Design principles, which allows him to have the correct vision and experience to handle development of complex business intelligence solutions. Having worked as a Microsoft Certified Teacher for many years, Davide is able to pass all his knowledge to his co-workers, allowing his team to deliver high-quality solutions. He currently works as a Mentor for SolidQ and can be found speaking in many Italian and internationals events.

This Blog

Syndication

Powered by Community Server (Commercial Edition), by Telligent Systems
  Privacy Statement