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.


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]

 

CREATE TABLE [dbo].[capture_stpandwaits_data](
    [event_data] 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) = 'C:\Program Files\Microsoft SQL Server\MSSQL13.SQL2016\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:

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]
Select * from PowerBITrace.dbo.batch_completed

 

 

 
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'

-- 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]

 

---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=.\\SQL2014");
           
      
         
            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();
        }
    }
}

 

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