How to use server side trace to capture running query T SQL

Capturing queries by using server side trace

In general, DBA will have a report most of time the server and application web is running slow. You have to find yourself what query is running slow and benchmark and tune it.

Profiler trace is good to capture the running code. But it is a GUI and we have to start, capture and stop it. This will also make some performance slowness to the server and you it is hard to read and store data.

The server side trace is another option and it is a lightweight and T-SQL code, we can create a stored procedure and schedule it on SQL server agent job to automate this.

Here are the steps and scripts:

Go to SQL server version — open performance tools  — SQL server profiler — File menu — New trace — Event selections — check show all events and columns — in the event selection go to SP: RPC completed, SP completed, SP stmt completed in TSQL: SQL batch completed and SQL stmt completed– Run and stop the trace.

—-======

RPC completed, SP completed, SP stmt completed

Quick test:

create proc usp_test_1
(@id int)
as

select * from [dbo].[tblAuthors] where id=@id

select * from [dbo].[tblAuthors]

Run – Exec [usp_test_1] 15 in one query window

Can see SP:StmtCompleted, SP:Completed, SQL:StmtCompleted & SQL:BatchCompleted

RPC completed -Remote procedure call
An application sends the name of the stored procedure and the parameters in binary format. The procedure can be sp_executesql, which is used for a parameterised statement.

RPC:Completed and SP:Completed events are fired when an entire RPC call or Stored Procedure is completed. Most of the the time SP:StmtCompleted should be fast.

SP:StmtCompleted shows each step in a stored procedure. StmtCompleted give you individual statements within the procedure or batch submitted

 

SQL batch completed and SQL stmt completed

select * from [dbo].[tblAuthors] where id=100 run in another query window

Can see both  SQL:StmtCompleted & SQL:BatchCompleted

SQL:StmtCompleted is when it is in an ad-hoc batch.

SQL:BatchCompleted event class indicates that the Transact-SQL batch has completed

—-======

Now go to file menu again — Export  — Script Trace Definition  — choose the version and save it — open the saved sql file in SSMS, replace it with following stored procedure (OR) go with mine, it is more or less same events.

Events we might consider:

In stored procedure — RPC completed, SP completed, SP stmt completed,

T-SQL event category – SQL BatchCompleted, SQL stmt completed.

Here are the steps:

1. Use mine or export trace template from profiler with filters
2. Create SP
3. Run SP and schedule it agent job
4. View trace data in table format
5. Analysis data

Scripts

You can get a trace file with events and filters of your own and replace it with the following SP.

From the trace export script find between ‘– Set the events’ and ‘– — Set the trace status to start’ and replace the script in the SP based the events you have selected.

Note: There are three set parameter you can change it accordingly, File name with datetime, stop time of trace 30 minutes and max file size of trace 500MB.

Since the stop time is 30 minutes, better to schedule job every 15 minutes, if the trace already running, it will not start the new trace. The main point is we should not missing any data and run.

set @File_name=@TRC_PATH + ‘AuditTrace_’+convert(varchar(20),getdate(),12)+’‘+cast(datepart(hour,getdate()) as varchar)+’‘+cast(datepart(minute,getdate()) as varchar)+’_’+cast(datepart(Second,getdate()) as varchar)

set @DateTime =dateAdd(minute,30,getdate())

set @maxfilesize = 500

In the script: you can change the max file size from 500 MB to any size and can replace the script with event and column filters like DB name etc.

Create a table, this will have a trace location, it will helpful to find the location and timeframe, you can also write a dynamic query to export the trace data into a table.

Create Table tbl_audit_log
(
ID int identity primary key,
Trc_Date Datetime,
Trc_Filename varchar(1000),
Trc_message varchar(1000),
Trc_ID Int
)

go

Create PROC [dbo].[USP_DBATRACE_Capture]

@TRC_PATH VARCHAR(1000)='D:\SQL_Trace\',
@MESSAGE varchar(1000)=NULL
AS
BEGIN

/****************************************************/
/* Created by: Muthukkumaran Kaliyamoorthy          */
/* Date: 03/13/2019  06:06:13 AM         */
/****************************************************/

if exists (select 1 from fn_trace_getinfo(default) where cast ([value] as varchar) like '%\AuditTrace_%')
Begin
goto Existing
end
else
begin

-- Create a Queue
declare @rc int
declare @TraceID int
declare @maxfilesize bigint
declare @DateTime datetime
declare @File_name nvarchar(256)
set @File_name=@TRC_PATH + 'AuditTrace_'+convert(varchar(20),getdate(),12)+'_'+cast(datepart(hour,getdate()) as varchar)+'_'+cast(datepart(minute,getdate()) as varchar)+'_'+cast(datepart(Second,getdate()) as varchar)
set @DateTime =dateAdd(minute,30,getdate())
set @maxfilesize = 500

-- Please replace the text InsertFileNameHere, with an appropriate
-- filename prefixed by a path, e.g., H:\Audit_login_Trace\. The .trc extension
-- will be appended to the filename automatically. If you are writing from
-- remote server to local drive, please use UNC path and make sure server has
-- write access to your network share

/* additional code for log

drop table tbl_audit_log

Create Table tbl_audit_log
(
ID int identity primary key,
Trc_Date Datetime,
Trc_Filename varchar(1000),
Trc_message varchar(1000),
Trc_ID Int
)

*/


exec @rc = sp_trace_create 
 @traceid =@TraceID output
,@options =0
,@tracefile=@File_name
,@maxfilesize= @maxfilesize
,@stoptime = @Datetime
,@filecount = NULL 

if (@rc != 0) goto error

-- Client side File and Table cannot be scripted

-- Set the events
declare @on bit
set @on = 1
exec sp_trace_setevent @TraceID, 121, 1, @on
exec sp_trace_setevent @TraceID, 121, 9, @on
exec sp_trace_setevent @TraceID, 121, 3, @on
exec sp_trace_setevent @TraceID, 121, 11, @on
exec sp_trace_setevent @TraceID, 121, 4, @on
exec sp_trace_setevent @TraceID, 121, 6, @on
exec sp_trace_setevent @TraceID, 121, 7, @on
exec sp_trace_setevent @TraceID, 121, 8, @on
exec sp_trace_setevent @TraceID, 121, 10, @on
exec sp_trace_setevent @TraceID, 121, 12, @on
exec sp_trace_setevent @TraceID, 121, 13, @on
exec sp_trace_setevent @TraceID, 121, 14, @on
exec sp_trace_setevent @TraceID, 121, 15, @on
exec sp_trace_setevent @TraceID, 121, 21, @on
exec sp_trace_setevent @TraceID, 121, 31, @on
exec sp_trace_setevent @TraceID, 121, 35, @on
exec sp_trace_setevent @TraceID, 121, 41, @on
exec sp_trace_setevent @TraceID, 121, 45, @on
exec sp_trace_setevent @TraceID, 121, 46, @on
exec sp_trace_setevent @TraceID, 121, 47, @on
exec sp_trace_setevent @TraceID, 121, 49, @on
exec sp_trace_setevent @TraceID, 121, 51, @on
exec sp_trace_setevent @TraceID, 121, 60, @on
exec sp_trace_setevent @TraceID, 121, 64, @on
exec sp_trace_setevent @TraceID, 121, 66, @on
exec sp_trace_setevent @TraceID, 120, 1, @on
exec sp_trace_setevent @TraceID, 120, 9, @on
exec sp_trace_setevent @TraceID, 120, 3, @on
exec sp_trace_setevent @TraceID, 120, 11, @on
exec sp_trace_setevent @TraceID, 120, 4, @on
exec sp_trace_setevent @TraceID, 120, 6, @on
exec sp_trace_setevent @TraceID, 120, 7, @on
exec sp_trace_setevent @TraceID, 120, 8, @on
exec sp_trace_setevent @TraceID, 120, 10, @on
exec sp_trace_setevent @TraceID, 120, 12, @on
exec sp_trace_setevent @TraceID, 120, 13, @on
exec sp_trace_setevent @TraceID, 120, 14, @on
exec sp_trace_setevent @TraceID, 120, 15, @on
exec sp_trace_setevent @TraceID, 120, 21, @on
exec sp_trace_setevent @TraceID, 120, 31, @on
exec sp_trace_setevent @TraceID, 120, 35, @on
exec sp_trace_setevent @TraceID, 120, 41, @on
exec sp_trace_setevent @TraceID, 120, 45, @on
exec sp_trace_setevent @TraceID, 120, 46, @on
exec sp_trace_setevent @TraceID, 120, 47, @on
exec sp_trace_setevent @TraceID, 120, 49, @on
exec sp_trace_setevent @TraceID, 120, 51, @on
exec sp_trace_setevent @TraceID, 120, 60, @on
exec sp_trace_setevent @TraceID, 120, 64, @on
exec sp_trace_setevent @TraceID, 120, 66, @on
exec sp_trace_setevent @TraceID, 28, 2, @on
exec sp_trace_setevent @TraceID, 28, 66, @on
exec sp_trace_setevent @TraceID, 28, 10, @on
exec sp_trace_setevent @TraceID, 28, 3, @on
exec sp_trace_setevent @TraceID, 28, 11, @on
exec sp_trace_setevent @TraceID, 28, 4, @on
exec sp_trace_setevent @TraceID, 28, 6, @on
exec sp_trace_setevent @TraceID, 28, 7, @on
exec sp_trace_setevent @TraceID, 28, 8, @on
exec sp_trace_setevent @TraceID, 28, 9, @on
exec sp_trace_setevent @TraceID, 28, 12, @on
exec sp_trace_setevent @TraceID, 28, 14, @on
exec sp_trace_setevent @TraceID, 28, 21, @on
exec sp_trace_setevent @TraceID, 28, 25, @on
exec sp_trace_setevent @TraceID, 28, 26, @on
exec sp_trace_setevent @TraceID, 28, 35, @on
exec sp_trace_setevent @TraceID, 28, 41, @on
exec sp_trace_setevent @TraceID, 28, 49, @on
exec sp_trace_setevent @TraceID, 28, 51, @on
exec sp_trace_setevent @TraceID, 28, 60, @on
exec sp_trace_setevent @TraceID, 28, 64, @on
exec sp_trace_setevent @TraceID, 96, 2, @on
exec sp_trace_setevent @TraceID, 96, 66, @on
exec sp_trace_setevent @TraceID, 96, 10, @on
exec sp_trace_setevent @TraceID, 96, 3, @on
exec sp_trace_setevent @TraceID, 96, 11, @on
exec sp_trace_setevent @TraceID, 96, 4, @on
exec sp_trace_setevent @TraceID, 96, 5, @on
exec sp_trace_setevent @TraceID, 96, 7, @on
exec sp_trace_setevent @TraceID, 96, 8, @on
exec sp_trace_setevent @TraceID, 96, 9, @on
exec sp_trace_setevent @TraceID, 96, 12, @on
exec sp_trace_setevent @TraceID, 96, 14, @on
exec sp_trace_setevent @TraceID, 96, 22, @on
exec sp_trace_setevent @TraceID, 96, 25, @on
exec sp_trace_setevent @TraceID, 96, 26, @on
exec sp_trace_setevent @TraceID, 96, 28, @on
exec sp_trace_setevent @TraceID, 96, 29, @on
exec sp_trace_setevent @TraceID, 96, 34, @on
exec sp_trace_setevent @TraceID, 96, 35, @on
exec sp_trace_setevent @TraceID, 96, 41, @on
exec sp_trace_setevent @TraceID, 96, 49, @on
exec sp_trace_setevent @TraceID, 96, 50, @on
exec sp_trace_setevent @TraceID, 96, 51, @on
exec sp_trace_setevent @TraceID, 96, 60, @on
exec sp_trace_setevent @TraceID, 96, 64, @on
exec sp_trace_setevent @TraceID, 17, 1, @on
exec sp_trace_setevent @TraceID, 17, 9, @on
exec sp_trace_setevent @TraceID, 17, 2, @on
exec sp_trace_setevent @TraceID, 17, 66, @on
exec sp_trace_setevent @TraceID, 17, 10, @on
exec sp_trace_setevent @TraceID, 17, 3, @on
exec sp_trace_setevent @TraceID, 17, 11, @on
exec sp_trace_setevent @TraceID, 17, 6, @on
exec sp_trace_setevent @TraceID, 17, 7, @on
exec sp_trace_setevent @TraceID, 17, 8, @on
exec sp_trace_setevent @TraceID, 17, 12, @on
exec sp_trace_setevent @TraceID, 17, 14, @on
exec sp_trace_setevent @TraceID, 17, 25, @on
exec sp_trace_setevent @TraceID, 17, 26, @on
exec sp_trace_setevent @TraceID, 17, 35, @on
exec sp_trace_setevent @TraceID, 17, 41, @on
exec sp_trace_setevent @TraceID, 17, 49, @on
exec sp_trace_setevent @TraceID, 17, 51, @on
exec sp_trace_setevent @TraceID, 17, 55, @on
exec sp_trace_setevent @TraceID, 17, 60, @on
exec sp_trace_setevent @TraceID, 17, 64, @on
exec sp_trace_setevent @TraceID, 10, 1, @on
exec sp_trace_setevent @TraceID, 10, 9, @on
exec sp_trace_setevent @TraceID, 10, 2, @on
exec sp_trace_setevent @TraceID, 10, 66, @on
exec sp_trace_setevent @TraceID, 10, 10, @on
exec sp_trace_setevent @TraceID, 10, 3, @on
exec sp_trace_setevent @TraceID, 10, 4, @on
exec sp_trace_setevent @TraceID, 10, 6, @on
exec sp_trace_setevent @TraceID, 10, 7, @on
exec sp_trace_setevent @TraceID, 10, 8, @on
exec sp_trace_setevent @TraceID, 10, 11, @on
exec sp_trace_setevent @TraceID, 10, 12, @on
exec sp_trace_setevent @TraceID, 10, 13, @on
exec sp_trace_setevent @TraceID, 10, 14, @on
exec sp_trace_setevent @TraceID, 10, 15, @on
exec sp_trace_setevent @TraceID, 10, 16, @on
exec sp_trace_setevent @TraceID, 10, 17, @on
exec sp_trace_setevent @TraceID, 10, 18, @on
exec sp_trace_setevent @TraceID, 10, 25, @on
exec sp_trace_setevent @TraceID, 10, 26, @on
exec sp_trace_setevent @TraceID, 10, 31, @on
exec sp_trace_setevent @TraceID, 10, 34, @on
exec sp_trace_setevent @TraceID, 10, 35, @on
exec sp_trace_setevent @TraceID, 10, 41, @on
exec sp_trace_setevent @TraceID, 10, 48, @on
exec sp_trace_setevent @TraceID, 10, 49, @on
exec sp_trace_setevent @TraceID, 10, 50, @on
exec sp_trace_setevent @TraceID, 10, 51, @on
exec sp_trace_setevent @TraceID, 10, 60, @on
exec sp_trace_setevent @TraceID, 10, 64, @on
exec sp_trace_setevent @TraceID, 12, 1, @on
exec sp_trace_setevent @TraceID, 12, 9, @on
exec sp_trace_setevent @TraceID, 12, 3, @on
exec sp_trace_setevent @TraceID, 12, 11, @on
exec sp_trace_setevent @TraceID, 12, 4, @on
exec sp_trace_setevent @TraceID, 12, 6, @on
exec sp_trace_setevent @TraceID, 12, 7, @on
exec sp_trace_setevent @TraceID, 12, 8, @on
exec sp_trace_setevent @TraceID, 12, 10, @on
exec sp_trace_setevent @TraceID, 12, 12, @on
exec sp_trace_setevent @TraceID, 12, 13, @on
exec sp_trace_setevent @TraceID, 12, 14, @on
exec sp_trace_setevent @TraceID, 12, 15, @on
exec sp_trace_setevent @TraceID, 12, 16, @on
exec sp_trace_setevent @TraceID, 12, 17, @on
exec sp_trace_setevent @TraceID, 12, 18, @on
exec sp_trace_setevent @TraceID, 12, 26, @on
exec sp_trace_setevent @TraceID, 12, 31, @on
exec sp_trace_setevent @TraceID, 12, 35, @on
exec sp_trace_setevent @TraceID, 12, 41, @on
exec sp_trace_setevent @TraceID, 12, 48, @on
exec sp_trace_setevent @TraceID, 12, 49, @on
exec sp_trace_setevent @TraceID, 12, 50, @on
exec sp_trace_setevent @TraceID, 12, 51, @on
exec sp_trace_setevent @TraceID, 12, 60, @on
exec sp_trace_setevent @TraceID, 12, 64, @on
exec sp_trace_setevent @TraceID, 12, 66, @on
exec sp_trace_setevent @TraceID, 13, 1, @on
exec sp_trace_setevent @TraceID, 13, 9, @on
exec sp_trace_setevent @TraceID, 13, 3, @on
exec sp_trace_setevent @TraceID, 13, 11, @on
exec sp_trace_setevent @TraceID, 13, 4, @on
exec sp_trace_setevent @TraceID, 13, 6, @on
exec sp_trace_setevent @TraceID, 13, 7, @on
exec sp_trace_setevent @TraceID, 13, 8, @on
exec sp_trace_setevent @TraceID, 13, 10, @on
exec sp_trace_setevent @TraceID, 13, 12, @on
exec sp_trace_setevent @TraceID, 13, 14, @on
exec sp_trace_setevent @TraceID, 13, 26, @on
exec sp_trace_setevent @TraceID, 13, 35, @on
exec sp_trace_setevent @TraceID, 13, 41, @on
exec sp_trace_setevent @TraceID, 13, 49, @on
exec sp_trace_setevent @TraceID, 13, 50, @on
exec sp_trace_setevent @TraceID, 13, 51, @on
exec sp_trace_setevent @TraceID, 13, 60, @on
exec sp_trace_setevent @TraceID, 13, 64, @on
exec sp_trace_setevent @TraceID, 13, 66, @on

-- Set the Filters
declare @intfilter int
declare @bigintfilter bigint

exec sp_trace_setfilter @TraceID, 10, 0, 7, N'SQL Server Profiler - f61be77a-3ee3-4104-8c4e-8a879db24354'
-- Set the trace status to start
exec sp_trace_setstatus @TraceID, 1

Insert into tbl_Audit_log
values (getdate(),@File_name,@MESSAGE,@TraceID)

-- display trace id for future references
select TraceID=@TraceID
goto finish

end
error: 
select ErrorCode=@rc
Existing:
select 'Trace already running' as Info
finish: 


END

——— Run the SP

Following is the excute code to start the trace, you can schedule it in the agent job to capture overnight and days.

exec [USP_DBATRACE_Capture] 'D:\SQL_Trace\','loginaudit'

select * from tbl_Audit_log order by trc_date desc

-- To stop trace
exec sp_trace_setstatus 2, 0 
exec sp_trace_setstatus 2, 2 

View the trace results:

select * from fn_trace_getinfo (default)

select top 100 sessionLoginname,databaseName,objectname,servername,duration,loginname,applicationname,hostname,textdata,* from fn_trace_gettable('D:\SQL_Trace\AuditTrace_191019_19_38_58.TRC',default) order by 5 desc

select top 10000 starttime AS ST,endtime as ET,
datediff(minute, starttime, endtime)as 'Code run Minute',Objectname as OB 
, 'textdata_1' = cast(textdata as varchar(4000)) 
,databaseName as DB,applicationname as App,
CPU as CP,Reads as [read] ,Writes as write , RowCounts as rows,
loginname as Login,NTUserName as NTU,
hostname as Host,sessionLoginname as S_Login,TE.name as TE_Name,* --into tbl_M_trace_all
from fn_trace_gettable('D:\SQL_Trace\AuditTrace_201129_19_47_11.trc',default) T
LEFT JOIN sys.trace_events TE ON T.EventClass = TE.trace_event_id
--where databaseName='db' and datediff(minute, starttime, endtime)>=1 
--and Objectname in ('SP Name')
order by 'Code run Minute' desc

Example – Load data dynamically one by one from all trace files.

You can add where clause to filter query runs more than 1 minutes or seconds, insert into another table to view the result.

You can uncomment the code and condition or add any condition.

Step 1 will create a dummy table .

Step 2 will load all the data between the date given with where condition.

-- Step 1 create a table

select * from dbo.tbl_Audit_log 

-- drop table tbl_M_trace_all
select top 1

' select top 1 starttime AS ST,endtime as ET,
datediff(minute, starttime, endtime)as ''Code run Minute'',Objectname as OB 
, ''textdata_1'' = cast(textdata as varchar(4000)) 
,databaseName as DB,applicationname as App,
CPU as CP,Reads as [read] ,Writes as write , RowCounts as rows,
loginname as Login,NTUserName as NTU,
hostname as Host,sessionLoginname as S_Login,TE.name as TE_Name, * into tbl_M_trace_all
from fn_trace_gettable('''+trc_filename+ '.trc'',default) T
LEFT JOIN sys.trace_events TE ON  T.EventClass = TE.trace_event_id
where databaseName=''db'' and datediff(minute, starttime, endtime)>=1 
and Objectname  in (''SP Name'')
and 1=0
order by ''Code run Minute'' desc
'
,trc_filename
from dbo.tbl_Audit_log 
where trc_date between '2017-07-18 02:05:29.000' and '2021-07-18 15:02:14.000'
order by trc_date

--Step 2

-- insert all trace file data into table which are runs more than 1 minute
-- if needed you can add db name or object name can be filtered in where condition


select 
'insert into [tbl_M_trace_all]'+
' select top 10000 starttime AS ST,endtime as ET,
datediff(minute, starttime, endtime)as ''Code run Minute'',Objectname as OB 
, ''textdata_1'' = cast(textdata as varchar(4000)) 
,databaseName as DB,applicationname as App,
CPU as CP,Reads as [read] ,Writes as write , RowCounts as rows,
loginname as Login,NTUserName as NTU,
hostname as Host,sessionLoginname as S_Login,TE.name as TE_Name,*
from fn_trace_gettable('''+trc_filename+ '.trc'',default) T
LEFT JOIN sys.trace_events TE ON  T.EventClass = TE.trace_event_id
where datediff(minute, starttime, endtime)>=1 
order by ''Code run Minute'' desc
'
,trc_filename,ID
from dbo.tbl_Audit_log 
where trc_date between '2017-07-18 02:05:29.000' and '2021-07-18 15:02:14.000'
order by trc_date

-- step 3
select * from tbl_M_trace_all order by 3 desc

 

End of script.