info@techdevops.com | 437-991-3573 | Data Engineering Services
TechDevOps.com
Resources Tools
Experts in Microsoft SQL Server on Windows, Linux, Containers | Clusters, Always On, FCI | Migrations, Cloud, Performance



Capture Slow Stored Procedure Calls in Microsoft SQL Server using Extended Events
by BF (Principal Consultant; Architecture; Engineering)
2016-06-22








Solution:


Create Permanent Table for Logging

CREATE TABLE [dbo].[LOG_SLOW_SQL](
[LogID] [int] IDENTITY(1,1) NOT NULL,
[DB_Name] [varchar](25) NULL,
[Client_App_Name] [varchar](25) NULL,
[Client_HostName] [varchar](25) NULL,
[End_Time] [datetime] NULL,
[Duration] [int] NULL,
[CPU] [int] NULL,
[Logical_Reads] [int] NULL,
[Writes] [int] NULL,
[Row_Count] [int] NULL,
[RPC] [varchar](max) NULL,
[InsertedDate] [datetime] NULL CONSTRAINT [DF_LOG_SLOW_SQL_InsertedDate] DEFAULT (getdate()),
CONSTRAINT [PK_LOG_SLOW_SQL] PRIMARY KEY CLUSTERED
(
[LogID] ASC
)WITH (PAD_INDEX = OFF, STATISTICS_NORECOMPUTE = OFF, IGNORE_DUP_KEY = OFF, ALLOW_ROW_LOCKS = ON, ALLOW_PAGE_LOCKS = ON) ON [PRIMARY]
) ON [PRIMARY] TEXTIMAGE_ON [PRIMARY]

GO


Create a SQL Job and place the below code in it
- Note: As we have a very busy public website that generates millions of RPC calls per hour, I set this to run only hourly.


Create Extended Events Session

CREATE EVENT SESSION XEvent ON SERVER
ADD EVENT sqlserver.rpc_completed
(
ACTION (
sqlserver.database_id,
sqlserver.session_id,
sqlserver.client_app_name,
sqlserver.client_hostname,
sqlserver.username,
sqlserver.sql_text,
sqlserver.tsql_stack
)
WHERE
[statement] not like N'%exec sp_reset_connection%'
AND
[duration] > 1000000 --Greater that 1 sec
)
ADD TARGET package0.asynchronous_file_target
(
SET FILENAME = 'G:\XEvents\XEvent.xet', metadatafile = 'G:\XEvents\XEvent.xem'
)
WITH (MAX_DISPATCH_LATENCY=15SECONDS) --15 sec


MAX_DISPATCH_LATENCY: Specifies the amount of time that events will be buffered in memory before being dispatched to event
session targets.


Start Extended Events Session
ALTER EVENT SESSION XEvent ON SERVER STATE = START


Allow time flush of buffer cache to target file<
WAITFOR DELAY '00:00:20';


Stop Extended Events Session
ALTER EVENT SESSION XEvent ON SERVER STATE = STOP


Log Extended Events data collected
SET QUOTED_IDENTIFIER OFF
Insert into OPS.dbo.LOG_SLOW_SQL
([DB_Name],[Client_App_Name],[Client_HostName],[End_Time],[Duration],[CPU],[Logical_Reads],[Writes],[Row_Count],[RPC])
SELECT
[db_name] = DB_NAME(x.value('(event/action[@name="database_id"])[1]', 'INT'))
, client_app_name = x.value('(event/action[@name="client_app_name"])[1]', 'NVARCHAR(100)')
, client_hostname = x.value('(event/action[@name="client_hostname"])[1]', 'NVARCHAR(100)')
, end_time = dateadd(hh,-4,x.value('(event/@timestamp)[1]', 'DATETIME'))
, duration_ms = x.value('(event/data[@name="duration"])[1]', 'INT') / 1000 --miliseconds
, cputime_ms = x.value('(event/data[@name="cpu_time"])[1]', 'INT') / 1000 --miliseconds
, logical_reads = x.value('(event/data[@name="logical_reads"])[1]', 'INT')
, writes = x.value('(event/data[@name="writes"])[1]', 'INT')
, row_count = x.value('(event/data[@name="row_count"])[1]', 'INT')
, rpc = x.value('(event/data[@name="statement"])[1]', 'NVARCHAR(MAX)')
FROM (
SELECT x = CAST(event_data AS XML).query('.')
FROM sys.fn_xe_file_target_read_file('G:\XEvents\XEvent*.xet','G:\XEvents\XEvent*.xem', NULL, NULL)
) t
--order by duration_ms desc
SET QUOTED_IDENTIFIER ON


Drop Extended Events Session
DROP EVENT SESSION XEvent ON SERVER


Clean up Extended Events Target File
Create Table #tmpdir (directoryinfo varchar(500))
Insert into #tmpdir exec master.dbo.xp_cmdshell 'dir G:\XEvents\'
If exists (Select 1 from #tmpdir where directoryinfo like '%xet%')
Begin
exec master..xp_cmdshell 'Del /Q G:\XEvents\*.*';
End
Drop Table #tmpdir