Thursday 1 September 2022

SQL Server : Capture expensive queries using Server side trace


You can follow the below steps to capture the expensive queries by creating the trace and also from SQL cache plan DMV's :

1. Create Server Side trace: by defining a trace, its the events and columns to captured, and add the filter condition.

You can use the below Script to create the trace:

-- Create Server-side trace
-- Create a Queue
DECLARE @rc int
DECLARE @TraceID int
DECLARE @maxfilesize bigint
set @maxfilesize = 2048

-- Please replace the text InsertFileNameHere, with an appropriate
-- filename prefixed by a path, e.g., c:\MyFolder\MyTrace. 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

DECLARE @MyFileName nvarchar(256)
SELECT @MyFileName='D:\RDSDBDATA\Log\RDSSQLTrace_' + CONVERT(nvarchar(10),GetDate(),121) + '_' + REPLACE(CONVERT(nvarchar(10),GetDate(),108),':','-')


exec @rc = sp_trace_create @TraceID output, 0, @MyFileName, @maxfilesize, NULL
if (@rc != 0) goto error

-- Client side File and Table cannot be scripted
-- Set the events
DECLARE @on bit
set @on = 1 --sp_trace_setevent @traceid ,@eventid ,@columnid,@on

-- Capturing the RPC:Completed event

EXEC sp_trace_setevent @TraceID, 10, 16, @on
EXEC sp_trace_setevent @TraceID, 10, 1, @on
EXEC sp_trace_setevent @TraceID, 10, 17, @on
EXEC sp_trace_setevent @TraceID, 10, 14, @on
EXEC sp_trace_setevent @TraceID, 10, 18, @on
EXEC sp_trace_setevent @TraceID, 10, 12, @on
EXEC sp_trace_setevent @TraceID, 10, 13, @on
EXEC sp_trace_setevent @TraceID, 10, 8, @on
EXEC sp_trace_setevent @TraceID, 10, 10, @on
EXEC sp_trace_setevent @TraceID, 10, 11, @on
EXEC sp_trace_setevent @TraceID, 10, 35, @on

--Capturing the SQL:BatchCompleted event

EXEC sp_trace_setevent @TraceID, 12, 16, @on
EXEC sp_trace_setevent @TraceID, 12, 1, @on
EXEC sp_trace_setevent @TraceID, 12, 17, @on
EXEC sp_trace_setevent @TraceID, 12, 14, @on
EXEC sp_trace_setevent @TraceID, 12, 18, @on
EXEC sp_trace_setevent @TraceID, 12, 12, @on
EXEC sp_trace_setevent @TraceID, 12, 13, @on
EXEC sp_trace_setevent @TraceID, 12, 8, @on
EXEC sp_trace_setevent @TraceID, 12, 10, @on
EXEC sp_trace_setevent @TraceID, 12, 11, @on
EXEC sp_trace_setevent @TraceID, 12, 35, @on

-- Set the Filters
EXEC sp_trace_setfilter @TraceID,11,0,7,N'%NT AUTHORITY%' --SQL login
EXEC sp_trace_setfilter @TraceID, 10, 0, 7, N'RdsAdminService'

-- Set the trace status to start
EXEC sp_trace_setstatus @TraceID, 1

-- display trace id and file name, Note these details for future references
SELECT @TraceID,@MyFileName

goto finish

error:
select ErrorCode=@rc

finish:
go

2. Start the Trace using below command :

-- To Start the trace (Please update the trace_id as you may recived at the time of creation)
Exec sp_trace_setstatus @traceid = 2 , @on = 1 -- start

3. Start the application test run

4. Once test run is completed, Stop the trace using below command:

-- To Stop the trace (Please update the trace_id as you may recived at the time of creation)

Exec sp_trace_setstatus @traceid = 2 , @on = 0 -- stop
-- To Delete the trace, once application test is completed.
--Exec sp_trace_setstatus @traceid = 2 , @on = 0 -- Delete definition from server

5. Insert the trace output in dummy table, this helps to get the data in easy to read format.

USE [DB_name]
GO
SELECT * INTO RDSSQLTrace_20210722_1215 FROM ::fn_trace_gettable ('D:\RDSDBDATA\Log\RDSSQLTrace_2021-07-22_12-15-19.trc', default)
6. Capture the output of below commands and update the output in the attached excel sheet template in the TraceData sheet (File Name : Capture_ExpensiveQueries_Template.xlsx)

--To collect queries based on max Duration 
SELECT TOP 10 StartTime,EndTime,Reads, Writes, 
Duration/1000000 DurationSec,CPU, TextData,RowCounts,sqlHandle,[DatabaseName],
SPID,LoginName,EventClass FROM [gptst].[dbo].[RDSSQLTrace_20210722] 
ORDER BY Duration DESC

--To collect queries based on max CPU utilization
SELECT TOP 10 StartTime,EndTime,Reads, Writes, 
Duration/1000000 DurationMs,CPU, TextData,RowCounts,sqlHandle,[DatabaseName],
SPID,LoginName,EventClass FROM [gptst].[dbo].[RDSSQLTrace_20210722] 
ORDER BY CPU DESC

--To collect queries based on max Reads,Writes
SELECT TOP 10 StartTime,EndTime,Reads, Writes, 
Duration/1000000 DurationSec,CPU, TextData,RowCounts,sqlHandle,[DatabaseName],
SPID,LoginName,EventClass FROM [gptst].[dbo].[RDSSQLTrace_20210722]
ORDER BY Reads,Writes DESC
7. Also, capture the output of the below scripts as well and update the same in the attached excel sheet template in the CacheData sheet (File Name : Capture_ExpensiveQueries_Template.xlsx)
--TOP 10 Queries by Duration (Avg Sec) from system dmv's		
			
SELECT TOP 10 DB_NAME(qt.dbid) AS DBName,
o.name AS ObjectName,
qs.total_worker_time / 1000000 / qs.execution_count As Avg_CPU_time_sec,
qs.total_worker_time / 1000000 as Total_CPU_time_sec,
qs.total_elapsed_time / qs.execution_count / 1000000.0 AS Average_Seconds,
qs.total_elapsed_time / 1000000.0 AS Total_Seconds,
'',
qs.execution_count as Count,
qs.last_execution_time as Time,
SUBSTRING (qt.text,qs.statement_start_offset/2,
(CASE WHEN qs.statement_end_offset = -1
THEN LEN(CONVERT(NVARCHAR(MAX), qt.text)) * 2
ELSE qs.statement_end_offset END - qs.statement_start_offset)/2) AS Query
--,qt.text [MainQuenry]
--,qp.query_plan
FROM sys.dm_exec_query_stats qs
CROSS APPLY sys.dm_exec_sql_text(qs.sql_handle) as qt
CROSS APPLY sys.dm_exec_query_plan(qs.plan_handle) AS qp
LEFT OUTER JOIN sys.objects o ON qt.objectid = o.object_id
where qs.execution_count>5 and DB_NAME(qt.dbid) not in ( 'master','msdb','model')
--and DB_NAME(qt.dbid) is not null
ORDER BY average_seconds DESC
--TOP 10 Queries by CPU (Avg CPU time) from system dmv's
SELECT TOP 10 DB_NAME(qt.dbid) as DBName,
	qs.total_worker_time / 1000000 / qs.execution_count AS Avg_CPU_time_sec,
	qs.total_worker_time / 1000000 As Total_CPU_time_sec,
	qs.total_elapsed_time / 1000000 / qs.execution_count As Average_Seconds,
	qs.total_elapsed_time / 1000000 As Total_Seconds,
    (total_logical_reads + total_logical_writes) / qs.execution_count as Average_IO,
	total_logical_reads + total_logical_writes as Total_IO,	
    qs.execution_count as Count,
    qs.last_execution_time as Time,
	SUBSTRING(qt.[text], (qs.statement_start_offset / 2) + 1,
		(
			(
				CASE qs.statement_end_offset
					WHEN -1 THEN DATALENGTH(qt.[text])
					ELSE qs.statement_end_offset
				END - qs.statement_start_offset
			) / 2
		) + 1
	) as Query
   ,qt.text
	,qp.query_plan
FROM sys.dm_exec_query_stats AS qs
CROSS APPLY sys.dm_exec_sql_text(qs.[sql_handle]) AS qt
CROSS APPLY sys.dm_exec_query_plan(qs.plan_handle) AS qp
LEFT OUTER JOIN sys.objects o ON qt.objectid = o.object_id
where 
DB_NAME(qt.dbid) not in ( 'master','msdb','model')
ORDER BY Avg_CPU_time_sec DESC

-- Top 10 query by IO (Avg IO) from system dmv's

SELECT TOP 10 DB_NAME(qt.dbid) AS DBName,
o.name AS ObjectName,
qs.total_elapsed_time / 1000000 / qs.execution_count As Average_Seconds,
qs.total_elapsed_time / 1000000 As Total_Seconds,
(total_logical_reads + total_logical_writes ) / qs.execution_count AS Average_IO,
(total_logical_reads + total_logical_writes ) AS Total_IO,
'',
qs.execution_count AS Count,
last_execution_time As Time,
SUBSTRING (qt.text,qs.statement_start_offset/2,
(CASE WHEN qs.statement_end_offset = -1
THEN LEN(CONVERT(NVARCHAR(MAX), qt.text)) * 2
ELSE qs.statement_end_offset END - qs.statement_start_offset)/2) AS Query
--,qt.text
--,qp.query_plan
FROM sys.dm_exec_query_stats qs
CROSS APPLY sys.dm_exec_sql_text(qs.sql_handle) as qt
CROSS APPLY sys.dm_exec_query_plan(qs.plan_handle) AS qp
LEFT OUTER JOIN sys.objects o ON qt.objectid = o.object_id
where last_execution_time > getdate()-1 
and DB_NAME(qt.dbid) not in ( 'master','msdb','model')
--and DB_NAME(qt.dbid) is not null
and qs.execution_count > 5 
ORDER BY average_IO DESC
Note : Please do capture the output after each run if running the test multiple times, to compare the result set.

No comments:

Post a Comment