Use Power BI to trace SQL Server RPC Calls and correlate them with Wait_info
The following code creates an extended event session that correlates wait_info and stored procedure (RPC calls) and allows you to analyze the data using Power BI.
Make sure to configure your right logfile path (where the Extended Event file is written)
Also enable xp_cmdshell to allow the script to cleanup the logfiles after the trace is done.
Update 7.6.2016 DatabaseID of the Database that should be traced can be added as a parameter, LogfilePath can be set as parameter in the script.
Update 20.3.2018 Added Support for SQL Server 2017
USE [master]
GO
Alter Database PowerBITrace set single_user with rollback immediate
Drop Database [PowerBITrace]
CREATE DATABASE [PowerBITrace]
GO
USE [PowerBITrace]
GO
CREATE TABLE [dbo].[ProcedureExecutionTime](
[timestamp] [datetime2](7) NULL,
[cpu_time] [int] NULL,
[duration_in_microseconds] [int] NULL,
[physical_reads] [int] NULL,
[logical_reads] [int] NULL,
[writes] [int] NULL,
[row_count] [int] NULL,
[SqlText] [nvarchar](512) NULL,
[Correlation] [uniqueidentifier] NULL,
[Sequence] [int] NULL,
[Minute] [int] NULL,
[Second] [int] NULL,
[Millisecond] [int] NULL,
[Szenario] [varchar](50) NULL,
TransactionID int
) ON [PRIMARY]
GO
CREATE TABLE [dbo].[WaitInfo](
[timestamp] [datetime2](7) NULL,
[wait_type] [varchar](25) NULL,
[wait_type_duration_ms] [int] NULL,
[wait_type_signal_duration_ms] [int] NULL,
[Correlation] [uniqueidentifier] NULL,
[Sequence] [int] NULL,
[Minute] [int] NULL,
[Second] [int] NULL,
[Millisecond] [int] NULL,
[Szenario] [varchar](50) NULL,
TransactionID int
) ON [PRIMARY]
GO
CREATE TABLE [dbo].[Transactions](
[timestamp] [datetime2](7) NULL,
[duration_in_microseconds] [int] NULL,
[Correlation] [varchar](36) NULL,
[Sequence] [varchar](8000) NULL,
[object_name] [varchar](512) NULL,
[transaction_state] [varchar](512) NULL,
[transaction_type] [varchar](512) NULL,
[transaction_id] int NULL,
[Minute] [int] NULL,
[Second] [int] NULL,
[Millisecond] [int] NULL,
[Szenario] [varchar](50) NULL
) ON [PRIMARY]
GO
CREATE TABLE [dbo].[commit_tran_completed](
[timestamp] [datetime2](7) NULL,
[Correlation] [varchar](36) NULL,
[Sequence] [varchar](8000) NULL,
[transaction_id] [int] NULL,
[Minute] [int] NULL,
[Second] [int] NULL,
[Millisecond] [int] NULL,
[Szenario] [varchar](255) NULL
) ON [PRIMARY]
GO
CREATE TABLE [dbo].[commit_tran_starting](
[timestamp] [datetime2](7) NULL,
[Correlation] [varchar](36) NULL,
[Sequence] [varchar](8000) NULL,
[transaction_id] [int] NULL,
[Minute] [int] NULL,
[Second] [int] NULL,
[Millisecond] [int] NULL,
[Szenario] [varchar](255) NULL
) ON [PRIMARY]
CREATE TABLE [dbo].[batch_completed](
[timestamp] [datetime2](7) NULL,
[cpu_time] [int] NULL,
[duration_in_microseconds] [int] NULL,
[physical_reads] [int] NULL,
[logical_reads] [int] NULL,
[writes] [int] NULL,
[row_count] [int] NULL,
[SqlText] [nvarchar](max) NULL,
[Correlation] [varchar](512) NULL,
[transaction_id] [int] NULL,
[SzenarioID] [varchar](255) NOT NULL,
[Minute] [int] NULL,
[Second] [int] NULL,
[Millisecond] [int] NULL
) ON [PRIMARY]
GO
CREATE TABLE [dbo].[capture_stpandwaits_data](
[event_data] XML NULL
) ON [PRIMARY] TEXTIMAGE_ON [PRIMARY]
GO
CREATE Procedure [dbo].[StpandWaitTrace] (@duration varchar(10), @szenario varchar(50), @databaseid int)
as
begin
–Author Lukas Steindl
–Script um Waitinfo Trace zu machen
declare @logfilepath varchar(128)
set @logfilepath = ‘C:\Program Files\Microsoft SQL Server\MSSQL14.SQL2017\MSSQL\Log\’
–Schritt 1) TRACE ANLEGEN:
IF EXISTS(SELECT * FROM sys.server_event_sessions WHERE name = ‘StoredProcedureAndWaitstats’)
DROP EVENT SESSION [StoredProcedureAndWaitstats] ON SERVER
waitfor delay ’00:00:02′
–CLEANUP FIRST:
–Truncate Table [dbo].[ProcedureExecutionTime]
–Truncate Table [dbo].[WaitInfo]
–Anpassen:
sp_configure ‘show advanced options’,1
reconfigure
sp_configure ‘xp_cmdshell’,1
reconfigure
–DB ID und Log pfad (wichtig SQL Server zugang zum Log drive! )
declare @deletecmd nvarchar(4000)= CONCAT(‘DEL /F “‘,@logfilepath, ‘StoredProcedureAndWaitstats*”‘)
exec xp_cmdshell @deletecmd
declare @cmd nvarchar(4000) = CONCAT(‘
CREATE EVENT SESSION [StoredProcedureAndWaitstats] ON SERVER
ADD EVENT sqlos.wait_info(
ACTION(sqlserver.transaction_id)
WHERE ([package0].[equal_uint64]([sqlserver].[database_id],(‘,@databaseid,’)) AND [duration]>(0) AND [package0].[not_equal_uint64]([wait_type],(109)) AND [package0].[not_equal_uint64]([wait_type],(96)) AND [package0].[not_equal_uint64]([wait_type],(798)))),
ADD EVENT sqlserver.commit_tran_completed(
ACTION(sqlserver.transaction_id)
WHERE ([sqlserver].[database_id]=(‘,@databaseid,’))),
ADD EVENT sqlserver.commit_tran_starting(
ACTION(sqlserver.transaction_id)
WHERE ([sqlserver].[database_id]=(‘,@databaseid,’))),
ADD EVENT sqlserver.rpc_completed(SET collect_statement=(1)
ACTION(sqlserver.transaction_id)
WHERE ([package0].[equal_uint64]([sqlserver].[database_id],(‘,@databaseid,’)) AND [package0].[not_equal_unicode_string]([statement],N”exec sp_reset_connection”))),
ADD EVENT sqlserver.sql_batch_completed(SET collect_batch_text=(1)
WHERE ([sqlserver].[database_id]=(‘,@databaseid,’))),
ADD EVENT sqlserver.sql_transaction(
ACTION(sqlserver.transaction_id)
WHERE ([sqlserver].[database_id]=(‘,@databaseid,’)))
ADD TARGET package0.event_file(SET filename=N”’,@logfilepath,’StoredProcedureAndWaitstats.xel”)
WITH (MAX_MEMORY=4096 KB,EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,MAX_DISPATCH_LATENCY=30 SECONDS,MAX_EVENT_SIZE=0 KB,MEMORY_PARTITION_MODE=NONE,TRACK_CAUSALITY=ON,STARTUP_STATE=OFF)’)
exec sp_executesql @cmd
–Schritt 2) TRACE STARTEN:
ALTER EVENT SESSION StoredProcedureAndWaitstats
ON SERVER
STATE = start;
waitfor delay @duration –’00:00:02′
–Schritt 3)
ALTER EVENT SESSION StoredProcedureAndWaitstats
ON SERVER
STATE = stop;
waitfor delay ’00:00:10′ –flushen!
–in temptable kopieren:
Truncate table [dbo].[capture_stpandwaits_data]
declare @parsecmd nvarchar(4000) = CONCAT(‘Insert Into [capture_stpandwaits_data] Select CAST(event_data as xml) AS event_data
from sys.fn_xe_file_target_read_file(”’, @logfilepath ,’StoredProcedureAndWaitstats*.xel”,null,null,null)’)
–print @parsecmd
exec sp_executesql @parsecmd
–Schritt 5) AUSWERTEN
—Transaction Commit auswerten:
–Select * from #capture_stpandwaits_data
— declare @szenario varchar(255) = ‘ABC’
Insert Into commit_tran_completed
Select [timestamp],
LEFT(Correlation,36) as ‘Correlation’,
REPLACE(RIGHT(Correlation,2),’-‘,”) as ‘Sequence’, transaction_id
,datepart(Minute,timestamp) as [Minute],datepart(second,timestamp) as [Second],datepart(MILLISECOND,timestamp) as [Millisecond],’test’ –@szenario as Szenario
— into commit_tran_completed
from (
SELECT
n.value(‘(@timestamp)[1]’, ‘datetime2’) AS [timestamp],
n.value(‘(action[@name=”attach_activity_id”]/value)[1]’, ‘varchar(512)’) AS Correlation,
n.value(‘(action[@name=”transaction_id”]/value)[1]’, ‘int’) AS transaction_id
FROM
capture_stpandwaits_data
CROSS APPLY event_data.nodes(‘event’)as q(n)
where n.value(‘(@name)[1]’, ‘varchar(64)’) = ‘commit_tran_completed’
)x
— declare @szenario varchar(255) = ‘ABC’
Insert Into commit_tran_starting
Select [timestamp],
LEFT(Correlation,36) as ‘Correlation’,
REPLACE(RIGHT(Correlation,2),’-‘,”) as ‘Sequence’, transaction_id
,datepart(Minute,timestamp) as [Minute],datepart(second,timestamp) as [Second],datepart(MILLISECOND,timestamp) as [Millisecond],@szenario as Szenario
— into commit_tran_starting
from (
SELECT
n.value(‘(@timestamp)[1]’, ‘datetime2’) AS [timestamp],
n.value(‘(action[@name=”attach_activity_id”]/value)[1]’, ‘varchar(512)’) AS Correlation,
n.value(‘(action[@name=”transaction_id”]/value)[1]’, ‘int’) AS transaction_id
FROM
capture_stpandwaits_data
CROSS APPLY event_data.nodes(‘event’)as q(n)
where n.value(‘(@name)[1]’, ‘varchar(64)’) = ‘commit_tran_starting’
)x
——————-
Insert into ProcedureExecutionTime
Select [timestamp], cpu_time, duration_in_microseconds, physical_reads, logical_reads, writes, row_count, SqlText,
LEFT(Correlation,36) as ‘Correlation’,
REPLACE(RIGHT(Correlation,2),’-‘,”) as ‘Sequence’
,datepart(Minute,timestamp) as [Minute],datepart(second,timestamp) as [Second],datepart(MILLISECOND,timestamp) as [Millisecond],@szenario
,transaction_id
from (
SELECT
n.value(‘(@timestamp)[1]’, ‘datetime2’) AS [timestamp],
n.value(‘(data[@name=”cpu_time”]/value)[1]’, ‘int’) AS cpu_time,
n.value(‘(data[@name=”duration”]/value)[1]’, ‘int’) AS duration_in_microseconds,
n.value(‘(data[@name=”physical_reads”]/value)[1]’, ‘int’) AS physical_reads,
n.value(‘(data[@name=”logical_reads”]/value)[1]’, ‘int’) AS logical_reads,
n.value(‘(data[@name=”writes”]/value)[1]’, ‘int’) AS writes,
n.value(‘(data[@name=”row_count”]/value)[1]’, ‘int’) AS row_count,
n.value(‘(data[@name=”statement”]/value)[1]’, ‘nvarchar(512)’) AS SqlText,
n.value(‘(action[@name=”attach_activity_id”]/value)[1]’, ‘varchar(512)’) AS Correlation,
n.value(‘(action[@name=”transaction_id”]/value)[1]’, ‘int’) AS transaction_id
FROM
capture_stpandwaits_data
CROSS APPLY event_data.nodes(‘event’)as q(n)
where n.value(‘(@name)[1]’, ‘varchar(64)’) = ‘rpc_completed’
)x
—Batch Completed Parser
INSERT INTO batch_completed Select [timestamp], cpu_time, duration_in_microseconds, physical_reads, logical_reads, writes, row_count, SqlText,
LEFT(Correlation,36) as ‘Correlation’,transaction_id,@szenario
,datepart(Minute,timestamp) as [Minute],datepart(second,timestamp) as [Second],datepart(MILLISECOND,timestamp) as [Millisecond] –,
from (
SELECT
n.value(‘(@timestamp)[1]’, ‘datetime2’) AS [timestamp],
n.value(‘(data[@name=”cpu_time”]/value)[1]’, ‘int’) AS cpu_time,
n.value(‘(data[@name=”duration”]/value)[1]’, ‘int’) AS duration_in_microseconds,
n.value(‘(data[@name=”physical_reads”]/value)[1]’, ‘int’) AS physical_reads,
n.value(‘(data[@name=”logical_reads”]/value)[1]’, ‘int’) AS logical_reads,
n.value(‘(data[@name=”writes”]/value)[1]’, ‘int’) AS writes,
n.value(‘(data[@name=”row_count”]/value)[1]’, ‘int’) AS row_count,
n.value(‘(data[@name=”batch_text”]/value)[1]’, ‘nvarchar(512)’) AS SqlText,
n.value(‘(action[@name=”attach_activity_id”]/value)[1]’, ‘varchar(512)’) AS Correlation,
n.value(‘(action[@name=”transaction_id”]/value)[1]’, ‘int’) AS transaction_id, @szenario as SzenarioID
FROM
capture_stpandwaits_data
CROSS APPLY event_data.nodes(‘event’)as q(n)
where n.value(‘(@name)[1]’, ‘varchar(64)’) = ‘sql_batch_completed’
)x
——————-
–declare @szenario varchar(255) = ‘ABC’
Insert Into WaitInfo
Select
[timestamp], wait_type, wait_type_duration_ms, wait_type_signal_duration_ms, LEFT(Correlation,36) as ‘Correlation’,
REPLACE(RIGHT(Correlation,2),’-‘,”) as ‘Sequence’,
datepart(Minute,timestamp) as [Minute],datepart(second,timestamp) as [Second],
datepart(MILLISECOND,timestamp) as [Millisecond],’test’,transaction_id
from (
SELECT n.value(‘(@timestamp)[1]’, ‘datetime2’) AS [timestamp],
n.value(‘(data[@name=”wait_type”]/text)[1]’, ‘varchar(25)’) AS wait_type,
n.value(‘(data[@name=”duration”]/value)[1]’, ‘int’) AS wait_type_duration_ms,
n.value(‘(data[@name=”signal_duration”]/value)[1]’, ‘int’) AS wait_type_signal_duration_ms,
n.value(‘(action[@name=”attach_activity_id”]/value)[1]’, ‘varchar(512)’) AS Correlation,
n.value(‘(action[@name=”transaction_id”]/value)[1]’, ‘int’) AS transaction_id
FROM
capture_stpandwaits_data
CROSS APPLY event_data.nodes(‘event’)as q(n)
where n.value(‘(@name)[1]’, ‘varchar(64)’) = ‘wait_info’
)x
end
GO
/****** Object: Table [dbo].[ProcedureExecutionTime] Script Date: 12/1/2015 4:02:16 PM ******/
–Run the trace for the duration specified:
use [PowerBITrace]
declare @db_id int = DB_ID(‘Master’)
print @db_id
exec [StpandWaitTrace] ’00:00:05′, ‘Beladung 3’, @db_id
— Use power bi to analyze the storedprocedures and the waits now.
–Use these two statements:
GO
/****** Object: Table [dbo].[ProcedureExecutionTime] Script Date: 12/1/2015 4:02:16 PM ******/
–Run the trace for the duration specified:
use [PowerBITrace]
exec [StpandWaitTrace] ’00:00:10′, ‘Trace5’,6
Select DB_ID(‘AdventureWorks’)
— Use power bi to analyze the storedprocedures and the waits now.
–Use these two statements:
Select * from PowerBITrace.dbo.ProcedureExecutionTime
Select * from PowerBITrace.dbo.WaitInfo
Select * from PowerBITrace.dbo.Transactions
Select * from PowerBITrace.[dbo].[commit_tran_completed]
Select * from PowerBITrace.[dbo].[commit_tran_starting]
—DEMO DATABASE TO TRACE:
Use AdventureWorks
go
Create or Alter procedure test
as
begin
waitfor delay ’00:00:01′
select 1
end
exec test
–DEMO RPC CALL
—Important don’t forget that it will only trace your RPC Calls! so to test the script you could use the following C# Program:
using System;
using System.Collections.Generic;
using System.Data.SqlClient;
using System.Linq;
using System.Text;
using System.Threading.Tasks;
namespace PowerBITraceDemo
{
class Program
{
static void Main(string[] args)
{
SqlConnection conn = new SqlConnection(“Integrated Security=SSPI;Persist Security Info=False;Initial Catalog=AdventureWorks;Data Source=.\\SQL2017”);
conn.Open();
SqlTransaction tran = conn.BeginTransaction(“hellow”);
SqlCommand cmd = new SqlCommand(“test”, conn, tran);
cmd.CommandType = System.Data.CommandType.StoredProcedure;
cmd.ExecuteNonQuery();
tran.Commit();
conn.Close();
Console.WriteLine(“Done!”);
Console.ReadLine();
}
}
}
It might happen that the rpc trace returns multiple rows with the same correlation id. in this case you have to run the following cleanup step:
Delete from ProcedureExecutionTime where Correlation in (
Select Correlation from ProcedureExecutionTime group by Correlation having COUNT(*) > 1)
Super Sache =)
Moved this project to https://github.com/LukasSteindl/SQLPB