Tue, Jan 01, 2019

SQL Server Trace

Share

Analysing the performance of a database or database server is pretty easy with all the great tools Microsoft has built into the platform. One thing I use from time to time is a custom built database. This allows you to import the SQL Server trace files into a table. You can then slice and dice it however you want, find the top ten highest CPU stored procedures, top ten with the biggest disk IO and so on. 

1. Create a blank database of your choosing

2. Create the following table

        CREATE TABLE [dbo].[TraceResults]
(
[TextData] [varchar](max) COLLATE SQL_Latin1_General_CP1_CI_AS NULL,
[Duration] [int] NULL,
[Reads] [int] NULL,
[Writes] [int] NULL,
[CPU] [int] NULL,
[StartTime] [datetime] NULL,
[ProcedureName] [varchar](max) COLLATE SQL_Latin1_General_CP1_CI_AS NULL
) ON [PRIMARY]
    

3. Create the running traces stored procedure

        CREATE PROCEDURE [dbo].[RunningTraces] AS 
BEGIN 
SET NOCOUNT ON; 
SELECT * FROM :: fn_trace_getinfo(default) 
END
    

4. Create a stored procedure to import the data

        CREATE PROCEDURE [dbo].[ImportTraceResults] 
@TraceFile VARCHAR(8000) 
AS 
BEGIN 
SET NOCOUNT ON 
-- Import the trace results to the database 
INSERT INTO TraceResults(TextData, Duration, Reads, Writes, CPU, StartTime) SELECT TextData, Duration/1000, Reads, Writes, CPU, StartTime FROM fn_trace_gettable(@TraceFile,1) 

-- Populate the procedure name column where applicable 
UPDATE TraceResults SET ProcedureName = LEFT(RIGHT(TextData, LEN(TextData) - CHARINDEX(' ',TextData, CHARINDEX('Exec',TextData))),CHARINDEX(' ', RIGHT(TextData, LEN(TextData) - CHARINDEX(' ',TextData, CHARINDEX('Exec',TextData))) + ' ')) WHERE TextData like '%exec%' AND ProcedureName IS NULL 
END
    

5. Create a stored procedure to run a SQL Server trace

        ALTER PROCEDURE [dbo].[StartTrace] 
@OutputFileName NVARCHAR(256) = 'C:\Databases\Data\Traces\Trace', @EndTime DATETIME = NULL 
AS 
BEGIN 
-- SET NOCOUNT ON added to prevent extra result sets from— interfering with SELECT statements. 
SET NOCOUNT ON; 
-- if the endtime hasn’t been set, then get the current date plus 30 minutes. IF @EndTime IS NULL BEGIN SET @EndTime = DATEADD(mi,30,getdate()) END 
PRINT 'Ending at' 
PRINT @EndTime 
DECLARE @rc INT 
DECLARE @TraceID INT 
DECLARE @MaxFileSize BIGINT 
SET @MaxFileSize = 500 
SET @OutputFileName = @OutputFileName + CONVERT(VARCHAR(20), GETDATE(),112) + REPLACE(CONVERT(VARCHAR(20), GETDATE(),108),':','') 

-- create a trace 
exec @rc = sp_trace_create @TraceID output, 0, @OutputFileName, @MaxFileSize, @EndTime 

-- Set the events and columns, this is equivilent to the columns in sql profiler. 
declare @on bit 
set @on = 1 
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, 18, @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, 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 

-- Set the trace status to start 
exec sp_trace_setstatus @TraceID, 1 
PRINT 'TraceID' 
PRINT @TraceID 
SET @OutputFileName = @OutputFileName + '.trc' 
PRINT 'Trace File' 
PRINT @OutputFileName 
-- keep cheking the status of the trace until it has completed. 
DECLARE @Count INT 
SELECT @Count = COUNT(*) FROM :: fn_trace_getinfo(default) WHERE TraceID = @TraceID WHILE @Count > 0 BEGIN WaitFor Delay '00:00:10' SELECT @Count = COUNT(*) FROM :: fn_trace_getinfo(default) WHERE TraceID = @TraceID END -- read in the data to the table 
PRINT 'Importing Results' 
EXEC dbo.ImportTraceResults @TraceFile = @OutputFileName 
END
    

6. Create views to pull out Stored Procedures and Non Stored Procedures from results

        CREATE VIEW [dbo].[v_NonStoredProcedures] 
AS 
SELECT TextData, SUM(DURATION) AS TimeImpact, SUM(reads) AS IOImpact, SUM(CPU) AS CpuImpact, COUNT(*) AS ExecutionCount
FROM TraceResults
WHERE ProcedureName IS NULL
GROUP BY TextData, Duration

CREATE VIEW [dbo].[v_StoredProcedures] AS
SELECT ProcedureName,SUM(DURATION) AS TimeImpact,SUM(reads) AS IOImpact,SUM(CPU) AS CpuImpact,AVG(Duration) AS AverageTimeImpact,AVG(reads) AS AverageIOImpact,AVG(CPU) AS AverageCpuImpact,COUNT(*) AS ExecutionCount
FROM TraceResults
WHERE ProcedureName IS NOT NULL
GROUP BY ProcedureName
    

The system is really easy to use, you can run the process by doing the following:

-- 5 minutes of stats
 DECLARE @End DateTime
 SET @End = DateAdd(Minute, 5, GetDate())
 EXEC [dbo].[StartTrace] @EndTime = @End

You can use any amount of time you like, obviously when this is running the server will be under more load. However, you also don't want to run it out of hours because you want a true representation of the server. When the process is running you can check its status by calling [dbo].[RunningTraces]. Once complete you can analyse the results by using the views. For example SELECT * FROM dbo.V_StoredProcedures. It's pretty likely you are using .NET applications accessing the database. If so the logs will have a ton of sp_reset_connection calls. It will open a connection and keep it open as long as it thinks it's useful to do so, connection sharing. To ensure that the connections don't interfere with each other it calls sp_reset_connection. So you probably want to delete everything in the TraceResults for sp_reset_connection, as its just fluff that you don't need to worry about.

Hope you find the above useful, it's served me a bunch of times so I'm sure it will help you too.