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)


Comments (0)

Skip to main content