Around 2010, I have performed SQL Server queries performance investigations for a client of mine.
I have found recently the article I have written about this topic but since I do not have anymore the work I have created at that time, I have decided to re-create it again.
Describing the problem
The client asked me to investigate the performance of their application at the database level: sometimes the queries executed were taking a significant amount of time.
I needed a tool to monitor the application's stored procedures execution and identify which procedures were taking the most time to execute.
Once I had this information, I needed to find out what were the long-running statements inside these stored procedures.
The stored procedures were huge: pages after pages of complex T-SQL, creating table variables and/or temporary tables to hold intermediate steps of logic.
Investigation
I have devised a test and investigated how the application behaves with 1 user versus 4 concurrent users.
In the case of 4 concurrent users, the database connection timed out.
Step 1
Wouldn't be nice if I can start a trace on a server and collect the data during the peak time of the application's execution?
Wouldn't be nice if this trace can show me all the stored procedures taking more time to execute than a given duration, say, 10 seconds?
Long-running stored procedure identified and monitored.
Wouldn't be nice if this trace can show me that a particular statement inside the stored procedure takes 80% of its execution's time?
TSQL statement from inside the stored procedure that creates the bottleneck, identified
The process of creating and using a SQL Server Trace Template described below does all of these things.
Step 2
Once I was able to identify the stored procedure that stalls the application's execution and the particular statement that creates the bottleneck, I have investigated the stored procedure's execution plan.
The screens from below show some of the work I have done at that time to understand the stored procedures execution plan and why SQL Server Optimizer decided to create it this way.
Solution
I will not go into too many details about that particular problem; enough to say that I had to force a different execution plan to make it more efficient,
The conclusion I had reached at the end of the article from 2010 is presented below:
SQL cannot build statistics against a table variable, as it does against temporary tables. This means that the execution plan for table variables will always treat the table as if it has 1 row therefore not using the best execution plan.
It is very helpful when analyzing a T-SQL statement execution to create the estimated execution plan and the actual statement execution plan. If those plans differ substantially in terms of rows estimated versus rows executed and if the statement execution time is high (after all the data pages have been cleaned up from the SQL Cache – DBBC DROPCLEANBUFFERS ) the user should try re-writing the statement to obtain a more efficient execution plan. In doing so, query hints may help force the Query Optimizer to choose the desired execution plan.
Particular attention should be given to the order in which the tables are joined, making sure that joins that produce less number of rows are done first.
Re-creating the work / Using SQL Server Trace Templates to your advantage
Create a long-running stored procedure for performing the test
create procedure IAP.TestPerformance
AS
BEGIN
DECLARE @DelayLength1 char(8)= '00:00:10'
DECLARE @DelayLength2 char(8)= '00:00:05'
SELECT 'EXECUTION STEP 1'
select * from [IAP].[IWA_Promo_Code]
SELECT 'EXECUTION STEP 2'
WAITFOR DELAY @DelayLength1
SELECT 'EXECUTION STEP 4'
select * from [IAP].[IWA_Config]
WAITFOR DELAY @DelayLength2
SELECT 'EXECUTION STEP 5'
END2. Create the SQL Server Trace template
/*
drop procedure sp_EnableTrace
*/
create procedure sp_EnableTrace
@databaseName nvarchar(256),
@storedProcedureName nvarchar(256),
@traceFileName nvarchar(256),
@duration bigint
AS
BEGIN
-- Declare variables
DECLARE @rc INT
DECLARE @TraceID INT
DECLARE @maxFileSize bigint
DECLARE @fileName NVARCHAR(128)
DECLARE @likeSPName nvarchar(256)
DECLARE @likeDBName nvarchar(256)
DECLARE @on bit
-- Set values
SET @maxFileSize = 5
SET @fileName = N'C:\Users\Public\work_sql_trace\' + @traceFileName
SET @on = 1
-- Create trace
EXEC @rc = sp_trace_create @TraceID output, 0, @fileName, @maxFileSize, NULL
-- If error end process
IF (@rc != 0) GOTO error
-- Set the events and data to collect
EXEC sp_trace_setevent @TraceID, 40, 1, @on
EXEC sp_trace_setevent @TraceID, 40, 5, @on
EXEC sp_trace_setevent @TraceID, 40, 12, @on
EXEC sp_trace_setevent @TraceID, 40, 13, @on
EXEC sp_trace_setevent @TraceID, 40, 14, @on
EXEC sp_trace_setevent @TraceID, 40, 15, @on
EXEC sp_trace_setevent @TraceID, 40, 16, @on
EXEC sp_trace_setevent @TraceID, 40, 17, @on
EXEC sp_trace_setevent @TraceID, 41, 1, @on
EXEC sp_trace_setevent @TraceID, 41, 5, @on
EXEC sp_trace_setevent @TraceID, 41, 12, @on
EXEC sp_trace_setevent @TraceID, 41, 13, @on
EXEC sp_trace_setevent @TraceID, 41, 14, @on
EXEC sp_trace_setevent @TraceID, 41, 15, @on
EXEC sp_trace_setevent @TraceID, 41, 16, @on
EXEC sp_trace_setevent @TraceID, 41, 17, @on
EXEC sp_trace_setevent @TraceID, 44, 1, @on
EXEC sp_trace_setevent @TraceID, 44, 5, @on
EXEC sp_trace_setevent @TraceID, 44, 12, @on
EXEC sp_trace_setevent @TraceID, 44, 13, @on
EXEC sp_trace_setevent @TraceID, 44, 14, @on
EXEC sp_trace_setevent @TraceID, 44, 15, @on
EXEC sp_trace_setevent @TraceID, 44, 16, @on
EXEC sp_trace_setevent @TraceID, 44, 17, @on
EXEC sp_trace_setevent @TraceID, 45, 1, @on
EXEC sp_trace_setevent @TraceID, 45, 5, @on
EXEC sp_trace_setevent @TraceID, 45, 12, @on
EXEC sp_trace_setevent @TraceID, 45, 13, @on
EXEC sp_trace_setevent @TraceID, 45, 14, @on
EXEC sp_trace_setevent @TraceID, 45, 15, @on
EXEC sp_trace_setevent @TraceID, 45, 16, @on
EXEC sp_trace_setevent @TraceID, 45, 17, @on
-- Set Filters
-- filter1 include databaseId = 6
--EXEC sp_trace_setfilter @TraceID, 3, 1, 0, 6
SET @likeDBName = '%' + LTRIM(RTRIM(@databaseName)) + '%'
--filter2 include databaseName = 6
EXEC sp_trace_setfilter @TraceID, 35, 0, 6, @likeDBName
SET @likeSPName = '%' + LTRIM(RTRIM(@storedProcedureName)) + '%'
EXEC sp_trace_setfilter @TraceID, 1, 1, 6, @likeSPName
EXEC sp_trace_setfilter @TraceID, 13, 1, 2, @duration
-- filter2 exclude application SQL Profiler
EXEC sp_trace_setfilter @TraceID, 10, 0, 7, N'SQL Profiler'
-- Start the trace
EXEC sp_trace_setstatus @TraceID, 1
-- display trace id for future references
SELECT TraceID=@TraceID
GOTO finish
-- error trap
error:
SELECT ErrorCode=@rc
-- exit
finish:
END
GO
3. Execute the statement from below to enable the trace for listening and make note of the return traceID value (in my case a value of 2)
execute sp_EnableTrace 'IAP-DEV-SQL', 'IAP.TestPerformance', 'TraceFile15', 10000
(Pass as parameters: the database name, the stored procedure name to monitor, the name of the trace file to store the result, the duration for stored procedure execution - the trace will identify the stored procedure that takes longer to execute and display it in the result set)
4. Execute your stored procedure to create the long-running queries
execute IAP.TestPerformance
5. Run this command to stop the trace and see the result.
execute sp_StopTrace 2, 'IAP.TestPerformance','TraceFile15', NULL
6. The trace results are placed into a file on your local machine and read from there for the final report.
/*
drop procedure sp_StopTrace
*/
CREATE PROCEDURE sp_StopTrace
@processID INT,
@storedProcedureName nvarchar(256),
@traceFileName nvarchar(256),
@spID int = null
AS
BEGIN
DECLARE @likeSPName nvarchar(256)
SET @likeSPName = '%execute ' + LTRIM(RTRIM(@storedProcedureName)) + '%'
IF @spID IS NULL
BEGIN
EXEC sp_trace_setstatus @processID, 0
EXEC sp_trace_setstatus @processID, 2
END
DECLARE @fileName NVARCHAR(128)
SET @fileName = N'C:\Users\Public\work_sql_trace\' + LTRIM(RTRIM(@traceFileName)) + '.trc'
delete sqlTableToLoad
--Load into an existing table
INSERT INTO sqlTableToLoad
SELECT * FROM ::fn_trace_gettable(@fileName, DEFAULT)
IF @spID IS NULL
BEGIN
SET @spID = (SELECT DISTINCT SPID FROM sqlTableToLoad WHERE TextData Like @likeSPName)
END
SELECT datediff(second, StartTime,EndTime) as ElapsedTime, Duration as Duration,
* FROM sqlTableToLoad
where EndTime IS NOT NULL
AND SPID = @spID
AND EventClass = 45 OR (EventClass = 41)
AND TextData NOT LIKE '%SELECT @@SPID%'
AND TextData NOT LIKE '%sp_Enable%'
order by LineNumber desc
END
The stored procedure that takes 15 seconds to execute is displayed above together with every internal statement and its corresponding duration.
##
Comments