Profiler and the SQL Server Trace

The use of sonar, or “fish finders”, has had a dramatic impact on the sport of fishing. In the past the area below the surface of the water was generally a big mystery. You could tell the depth in a specific spot by dropping an anchor or letting a jig run down to the bottom, but they gave you little idea of the depth around you. Is the bottom flat or sloping downward? Is it muck, gravel, rock, or weeds? You can even see congregations of bait-fish and the thermocline on most modern day sonar units.

I remember the first time I fished from a boat with a sonar unit. I assumed it’d be incredibly easy to start pulling in fish. The sonar would point them out, I’d drop a bait in front of their faces, and ten minutes later I’d be home with a live-well full of fish. In reality, it doesn’t work like that. While the sonar does give you a much better perspective on the environment below the surface of the water, it still takes a lot of skill and a little luck to read that environment and present some bait near some hungry fish to entice a bite.

In SQL Server, we can use a trace to look at what is going on “beneath the surface”. Up through SQL Server 2008 R2, a trace is one of the best ways to identify long running transactions, find deadlocks, measure stored procedures’ performance, and try to figure out what that third party software application is doing to your database. After 2008 R2, extended events become the preferred method to do these things, but this post will be focusing on the trace.

A SQL trace is events and data that are collected through the use of some internal SQL stored procedures. The events are specific things that happen within SQL Server, and the data is the details that are associated with those events. Through the use of filters we are able to zoom in on only the events we want to see, and only the details about those events we want to record. It is important to use the filters wisely because running a trace where many events and data are being recorded can significantly slow down the system. Care should always be taken when running a trace in a Production environment!

To get into Profiler, choose the option from the Tools menu in SQL Server Management Studio (SSMS):
20150422 Trace Profiler in SSMS
After choosing which Server Instance to run the trace on, you can choose which events and columns (the details) you want to trace. Use the “Show all events” and “Show all columns” checkboxes to display all the events and data you may want to monitor.20150422 Trace Profiler Trace Definition Clicking on the Column Filters… button will bring up a dialog box to choose the filters. You can filter on any of the columns that are selected for the trace.

20150422 Trace Filters After clicking Run, the Trace will begin. One great option for traces that you will be running often is to save your columns, filters, and events as a trace template. After starting the trace, go to File -> Save As -> Trace Template… to save this template. This allows you to simply choose the template next time you go into Profiler, instead of having to once again set up all the columns, filters, and events.
20150422 Trace Save Template One template I like to set up is for performance tuning a stored procedure. For this template I set a filter so the only login it grabs is mine. Then I choose the Stored Procedures RPC:Completed and TSQL SQL:BatchCompleted events, and make sure I have the CPU, Reads, Writes, and Duration columns selected.
20150422 Trace Performance Tuning With this setup, I can execute a stored procedure or SQL statement, see the amount of CPU, Reads, Writes, and Duration, then make a change to the SQL and execute it again. This will let me see whether the change I made to the SQL statement resulted in better performance, worse performance, or didn’t change the performance.

One last thing I strongly suggest using Trace for is to set up a lightweight trace that runs every day to capture certain events you may want to look back on for troubleshooting. This may include deadlocks, long blocks, stored procedures that take a long time to run and may need to be tuned, and sysadmin logins. If you define this trace in Profiler, you can get the SQL needed to create it by going to File -> Export -> Script Trace Definition -> For SQL Server 20XX…
20150422 Trace Save Definition This will give you the SQL needed to set up the Trace directly in TSQL:

/****************************************************/
/* Created by: SQL Server 2012  Profiler          */
/* Date: 04/22/2015  09:32:19 AM         */
/****************************************************/


-- Create a Queue
DECLARE @rc INT
DECLARE @TraceID INT
DECLARE @maxfilesize bigint
SET @maxfilesize = 5 

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

EXEC @rc = sp_trace_create @TraceID output, 0, N'InsertFileNameHere', @maxfilesize, 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, 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, 10, @on
EXEC sp_trace_setevent @TraceID, 10, 6, @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, 35, @on
EXEC sp_trace_setevent @TraceID, 12, 1, @on
EXEC sp_trace_setevent @TraceID, 12, 9, @on
EXEC sp_trace_setevent @TraceID, 12, 11, @on
EXEC sp_trace_setevent @TraceID, 12, 6, @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, 35, @on


-- Set the Filters
DECLARE @intfilter INT
DECLARE @bigintfilter bigint

EXEC sp_trace_setfilter @TraceID, 6, 0, 6, N'Gugg'
EXEC sp_trace_setfilter @TraceID, 6, 0, 1, NULL
EXEC sp_trace_setfilter @TraceID, 10, 0, 7, N'SQL Server Profiler - c3623d60-e4fd-44d6-a327-6dbb97563197'
EXEC sp_trace_setfilter @TraceID, 10, 0, 7, N'SQL Server Profiler - a2b0f7dd-70a4-45e0-a918-01abd7447cf5'
-- Set the trace status to start
EXEC sp_trace_setstatus @TraceID, 1

-- display trace id for future references
SELECT TraceID=@TraceID
GOTO finish

error: 
SELECT ErrorCode=@rc

finish: 
GO

Now you can set up a SQL Agent job to start the trace each morning, stop the trace each night, save the trace as a file, and save off any relevant results to specific tables. I like to save off deadlocks in their own table, long running blocks in their own table, and long running stored procedure in their own table.
Using this method I also get a log of trace files, so if anyone wants to know if we had any database issues 8 days ago at 11:50 AM, I can pull open the trace file from that day and take a look.
Lastly, I can set up a script to look at the current trace file and look for any unusual results. If I see a stored procedure is taking an average of seven seconds to run while historically it took just two seconds, I can ask myself what has changed with this procedure or the way it is being called as a way to troubleshoot poor performance with the entire system. Here is the script I use. It first provides a summary of the day. It then works with a table where I keep historical results called dbo.HistoricalPerformance to find stored procedures that are performing poorly compared to past performance. It assumes a trace naming convention that includes the date in the file name.

DECLARE @TraceFile NVARCHAR(255);

SELECT  @TraceFile = 'C:\SQL\Traces\Trace_' + CONVERT(CHAR(8), GETDATE(), 112)
        + 'A.trc';


IF ( SELECT OBJECT_ID('tempdb..#trace')
   ) IS NOT NULL
    DROP TABLE #trace;


IF ( SELECT OBJECT_ID('tempdb..#Results')
   ) IS NOT NULL
    DROP TABLE #Results;


SELECT  IDENTITY( INT,1,1 ) AS TraceId ,
        te.name AS EventName ,
        CAST(TEXTData AS VARCHAR(MAX)) AS TEXTData ,
        CPU ,
        Reads ,
        CAST(Duration / 1000000.0 AS DEC(7, 1)) AS Duration ,
        StartTime ,
        ISNULL(DatabaseName, d.name) AS DatabaseName ,
        RowCounts ,
        EndTime ,
        Writes ,
        ClientProcessID ,
        EventClass ,
        ApplicationName ,
        NTUserName ,
        SPID ,
        LoginName ,
        HostName ,
        t.DatabaseID
INTO    #trace
FROM    fn_trace_gettable(@TraceFile, 1) t
        JOIN sys.trace_events te ON t.EventClass = te.trace_event_id
        LEFT JOIN sys.databases d ON t.DatabaseID = d.database_id;


-- show activity --
SELECT  COUNT(*) AS [Total Trace Rows Since 7AM] ,
        [Rows per minute] = CAST(CAST(COUNT(*) AS FLOAT) / DATEDIFF(MINUTE, DATEADD(HOUR, 7, DATEADD(DAY,DATEDIFF(DAY, 0, GETDATE()), 0)), GETDATE()) AS DECIMAL(7, 1)) ,
        [Rows per minute last 5 minutes] = CAST(( SELECT    COUNT(*)
                                                  FROM      #trace
                                                  WHERE     EventName IN ( 'SQL:BatchCompleted','RPC:Completed' )
                                                            AND EndTime > DATEADD(MINUTE,-5, ( SELECT MAX(EndTime) FROM #trace))
                                                ) / 5.0 AS DECIMAL(7, 1)) ,
        [Rows in 60 seconds] = ( SELECT COUNT(*)
                                 FROM   #trace
                                 WHERE  EventName IN ( 'SQL:BatchCompleted',
                                                       'RPC:Completed' )
                                        AND EndTime > DATEADD(SECOND, -60, ( SELECT MAX(EndTime) FROM #trace))
                               ) ,
        [Query duration > 29.9] = SUM(CASE WHEN Duration >= 29.9
                                                AND TEXTData NOT LIKE 'exec sp_execute 1'
                                                AND DatabaseName NOT IN (
                                                'msdb', 'master' ) THEN 1
                                           ELSE 0
                                      END) ,
        [Blocks] = ( SELECT COUNT(*)
                     FROM   #trace
                     WHERE  EventClass = 137
                            AND EndTime > DATEADD(HOUR, 7, DATEADD(DAY, DATEDIFF(DAY, 0, GETDATE()), 0))
                   ) ,
        [Deadlocks] = ( SELECT  COUNT(*)
                        FROM    #trace
                        WHERE   EventClass = 148
                      ) ,
        [CPU / Duration] = ( SELECT CAST (SUM(CASE WHEN CPU / 1000. > Duration
                                                   THEN Duration
                                                   ELSE CPU / 1000.
                                              END) / SUM(Duration) AS DECIMAL(5, 2)) 
                             FROM   #trace
                             WHERE  EndTime > DATEADD(HOUR, 7, DATEADD(DAY, DATEDIFF(DAY, 0, GETDATE()), 0))
                                    AND CPU > 1000
                                    AND DatabaseName NOT IN ( 'Master', 'msdb' )
                                    AND EventName NOT IN ( 'Exception',
                                                           'Blocked process report' )
                           )
FROM    #trace
WHERE   EndTime > DATEADD(HOUR, 7,
                          DATEADD(DAY, DATEDIFF(DAY, 0, GETDATE()), 0))
        AND EventName NOT IN ( 'Exception', 'Blocked process report' )


--Get Procs Slower than normal
;
WITH    Exec11
          AS ( SELECT   DatabaseName ,
                        Duration ,
                        CPU ,
                        Reads ,
                        TEXTData ,
                        PATINDEX('%exec%', TEXTData) AS Loc
               FROM     #trace
               WHERE    ( EventName = 'RPC:Completed'
                          OR ( EventName = 'SQL:BatchCompleted'
                               AND TEXTData LIKE '%exec%'
                             )
                        )
                        AND DatabaseName NOT IN ( 'Distribution', 'msdb' )
                        AND TEXTData NOT LIKE '%sp_executesql%'
                        AND TEXTData NOT LIKE '%sp_prepare%'
                        AND ApplicationName = '.Net SqlClient Data Provider'
             ),
        Exec2
          AS ( SELECT   DatabaseName ,
                        Duration ,
                        CPU ,
                        Reads ,
                        SUBSTRING(TEXTData, Loc + 5, 100) AS TEXTData
               FROM     Exec1
             ),
        Exec3
          AS ( SELECT   DatabaseName ,
                        Duration ,
                        CPU ,
                        Reads ,
                        TEXTData ,
                        PATINDEX('% %', TEXTData) AS Loc
               FROM     Exec2
             ),
        Exec4
          AS ( SELECT   DatabaseName ,
                        Duration ,
                        CPU ,
                        Reads ,
                        CASE WHEN Loc > 0 THEN LEFT(TEXTData, Loc - 1)
                             ELSE TEXTData
                        END AS Procname
               FROM     Exec3
             )
    SELECT  t.DatabaseName ,
            t.Procname AS SlowerThanNormalProc ,
            COUNT(*) AS Cnt ,
            CAST(AVG(t.Duration) AS DECIMAL(5, 1)) AS AvgDuration ,
            MAX(h.AvgDuration) AS HistoricalAvgDuration ,
            CAST(CAST(AVG(t.Duration) AS FLOAT)
            / NULLIF(CAST(MAX(h.AvgDuration) AS FLOAT), 0) AS DECIMAL(8, 2)) AS DurationRatio ,
            AVG(t.CPU) AS AvgCpu ,
            MAX(h.AvgCPU) AS HistoricalAvgCpu ,
            CAST(CAST(AVG(t.CPU) AS FLOAT)
            / NULLIF(CAST(MAX(h.AvgCPU) AS FLOAT), 0) AS DECIMAL(8, 2)) AS CpuRatio ,
            AVG(t.Reads) AS AvgReads ,
            MAX(h.AvgReads) AS HistoricalAvgReads ,
            CAST(CAST(AVG(t.Reads) AS FLOAT)
            / NULLIF(CAST(MAX(h.AvgReads) AS FLOAT), 0) AS DECIMAL(8, 2)) AS ReadsRatio
    INTO    #Results
    FROM    Exec4 t
            LEFT JOIN dbo.HistoricalPerformance h ON t.DatabaseName = h.DatabaseName
                                                     AND t.Procname = h.ProcName
    GROUP BY t.DatabaseName ,
            t.Procname;

SELECT  * ,
        Cnt * AvgCpu AS SumCpu
FROM    #Results
ORDER BY 3 DESC

I hope this information has given you some ideas of ways to use SQL Trace to improve the health of your database.

Advertisements