solating a Long-Running Query with SQL Profiler

If your application has a performance problem that you think might be caused by a particularly long-running query, you can use the SQLProfilerTSQL_Duration template to analyze query durations. You can either analyze the queries interactively, or you can save information to an output file and analyze the data offline.

Identifying a Long-Running Query Interactively

The most immediate way of analyzing query performance is to use SQL Profiler to show trace information interactively.

To identify a long-running query interactively

1. Start SQL Profiler.

2. On the File menu, click New, and then click Trace.

3. Specify the relevant connection details to connect to the computer running SQL Server.

   1. The Trace Properties dialog box appears.

4. In the Template name list, click SQLProfilerTSQL_Duration.

5. Click the Events tab.

• 1. Notice that two key events are selected:

     • RPC:Completed from the Stored Procedures event class

     • SQL:BatchCompleted from the T-SQL event class

6. Click Run to run the trace.

7. Start SQL Query Analyzer.

8. Run the queries you want to analyze. For example, using the Pubs database, you might run the following query.

• 1. select au_id, au_lname + ' ' + au_fname, phone from authors where au_lname like 'G%' order by au_lname select * from authors Select au_id from authors

9. View the trace output in SQL Profiler. Note that durations are given in milliseconds.

• 1. Figure 1 shows sample output.

     1. Figure 1: Sample SQL Profiler output using the SQLProfilerTSQL_Duration template

  2. Stop the trace.

• • 1. Note   Your duration times may vary from those shown, and may even appear as zero if the database server has a small load.

Identifying a Long-Running Query from Trace Output

As an alternative to the interactive approach, you can save trace information to an output file and analyze the data offline. The trace information can then be imported into a database table for further analysis. This approach is useful where large sets of trace data need to be analyzed.

The following steps show you how to save trace data to a trace file and then import it into a trace table for analysis. A stored procedure named AnlzTrcExec is provided to aid in data analysis.

Note   When trace data is saved to a file, the values in the EventClass column are converted into integer values. To increase readability, the AnlzTrcExec procedure uses a lookup table named trace_events so that the event class can be displayed as text.

To identify a long-running query from trace output

1. In SQL Profiler, on the File menu, click New, and then click Trace.

2. Specify the relevant connection details to connect to the computer running SQL Server.

   1. The Trace Properties dialog box appears.

3. In the Template name list, select SQLProfilerTSQL_Duration.

4. Select the Save to file check box, specify the trace file name as c:\MyTrace.trc, and then click Save.

5. On the Data Columns tab, select the following data columns, clicking Add after each selection:

• • CPU

  • IntegerData

  • Reads

  • StartTime

  • Writes

6. Click Run.

7. In SQL Query Analyzer, run the queries you want to analyze. For example, using the Pubs database, you might run the following query.

• 1. select au_id, au_lname + ' ' + au_fname, phone from authors where au_lname like 'G%' order by au_lname select * from authors Select au_id from authors

8. Stop the trace.

9. In SQL Query Analyzer, import the trace file into the database of your choice by using the following query:

• 1. SELECT * INTO MyTraceTable FROM ::fn_trace_gettable('C:\MyTrace.trc', default)

10. Run the following query to create a trace events lookup table.

• 1. if exists (select * from dbo.sysobjects     where id = object_id(N'[trace_events]') and OBJECTPROPERTY(id, N'IsUserTable') = 1)     drop table [trace_events]  create table trace_events ([EventClass] int, [EventName] varchar(31))  Insert trace_events values (10,'RPC:Completed')  Insert trace_events values (11,'RPC:Starting')  Insert trace_events values (12,'SQL:BatchCompleted')  Insert trace_events values (13,'SQL:BatchStarting')  Insert trace_events values (14,'Login')  Insert trace_events values (15,'Logout')  Insert trace_events values (16,'Attention')  Insert trace_events values (17,'ExistingConnection')  Insert trace_events values (18,'ServiceControl')  Insert trace_events values (19,'DTCTransaction')  Insert trace_events values (20,'Login Failed')  Insert trace_events values (21,'EventLog')  Insert trace_events values (22,'ErrorLog')  Insert trace_events values (23,'Lock:Released')  Insert trace_events values (24,'Lock:Acquired')  Insert trace_events values (25,'Lock:Deadlock')  Insert trace_events values (26,'Lock:Cancel')  Insert trace_events values (27,'Lock:Timeout')  Insert trace_events values (28,'DOP Event')  Insert trace_events values (33,'Exception')  Insert trace_events values (34,'SP:CacheMiss')  Insert trace_events values (35,'SP:CacheInsert')  Insert trace_events values (36,'SP:CacheRemove')  Insert trace_events values (37,'SP:Recompile')  Insert trace_events values (38,'SP:CacheHit')  Insert trace_events values (39,'SP:ExecContextHit')  Insert trace_events values (40,'SQL:StmtStarting')  Insert trace_events values (41,'SQL:StmtCompleted')  Insert trace_events values (42,'SP:Starting')  Insert trace_events values (43,'SP:Completed')  Insert trace_events values (44,'Reserved ')  Insert trace_events values (45,'Reserved ')  Insert trace_events values (46,'Object:Created')  Insert trace_events values (47,'Object:Deleted')  Insert trace_events values (48,'Reserved')  Insert trace_events values (49,'Reserved')  Insert trace_events values (50,'SQL Transaction')  Insert trace_events values (51,'Scan:Started')  Insert trace_events values (52,'Scan:Stopped')  Insert trace_events values (53,'CursorOpen')  Insert trace_events values (54,'Transaction Log')  Insert trace_events values (55,'Hash Warning')  Insert trace_events values (58,'Auto Update Stats')  Insert trace_events values (59,'Lock:Deadlock Chain')  Insert trace_events values (60,'Lock:Escalation')  Insert trace_events values (61,'OLE DB Errors')  Insert trace_events values (67,'Execution Warnings')  Insert trace_events values (68,'Execution Plan')  Insert trace_events values (69,'Sort Warnings')  Insert trace_events values (70,'CursorPrepare')  Insert trace_events values (71,'Prepare SQL')  Insert trace_events values (72,'Exec Prepared SQL')  Insert trace_events values (73,'Unprepare SQL')  Insert trace_events values (74,'CursorExecute')  Insert trace_events values (75,'CursorRecompile')  Insert trace_events values (76,'CursorImplicitConversion')  Insert trace_events values (77,'CursorUnprepare')  Insert trace_events values (78,'CursorClose')  Insert trace_events values (79,'Missing Column Statistics')  Insert trace_events values (80,'Missing Join Predicate')  Insert trace_events values (81,'Server Memory Change')  Insert trace_events values (82,'User Configurable')  Insert trace_events values (83,'User Configurable')  Insert trace_events values (84,'User Configurable')  Insert trace_events values (85,'User Configurable')  Insert trace_events values (86,'User Configurable')  Insert trace_events values (87,'User Configurable')  Insert trace_events values (88,'User Configurable')  Insert trace_events values (89,'User Configurable')  Insert trace_events values (90,'User Configurable')  Insert trace_events values (91,'User Configurable')  Insert trace_events values (92,'Data File Auto Grow')  Insert trace_events values (93,'Log File Auto Grow')  Insert trace_events values (94,'Data File Auto Shrink')  Insert trace_events values (95,'Log File Auto Shrink')  Insert trace_events values (96,'Show Plan Text')  Insert trace_events values (97,'Show Plan ALL')  Insert trace_events values (98,'Show Plan Statistics')  Insert trace_events values (99,'Reserved')  Insert trace_events values (100,'RPC Output Parameter')  Insert trace_events values (101,'Reserved')  Insert trace_events values (102,'Audit Statement GDR')  Insert trace_events values (103,'Audit Object GDR')  Insert trace_events values (104,'Audit Add/Drop Login')  Insert trace_events values (105,'Audit Login GDR')  Insert trace_events values (106,'Audit Login Change Property')  Insert trace_events values (107,'Audit Login Change Password')  Insert trace_events values (108,'Audit Add Login to Server Role')  Insert trace_events values (109,'Audit Add DB User')  Insert trace_events values (110,'Audit Add Member to DB')  Insert trace_events values (111,'Audit Add/Drop Role')  Insert trace_events values (112,'App Role Pass Change')  Insert trace_events values (113,'Audit Statement Permission')  Insert trace_events values (114,'Audit Object Permission')  Insert trace_events values (115,'Audit Backup/Restore')  Insert trace_events values (116,'Audit DBCC')  Insert trace_events values (117,'Audit Change Audit')  Insert trace_events values (118,'Audit Object Derived Permission')  Go

11. Create a stored procedure named AnlzTrcExec by running the following code:

• 1. if exists (select * from dbo.sysobjects where id = object_id(N'[dbo].[AnlzTrcExec]') and OBJECTPROPERTY(id, N'IsProcedure') = 1)  drop procedure [dbo].[AnlzTrcExec]  GO    Create  Proc AnlzTrcExec @trc nvarchar(255), @len int = 60, @Top int = 100, @EventClass nvarchar(20) = 'all', @TextData nvarchar(255) = 'none' as  declare @cmd nvarchar(2048)  declare @TopV as nvarchar(20)  SET @TopV = ' 100 PERCENT '  if @Top != 100  BEGIN    SET @TopV = ' ' + cast(@Top as nvarchar(4)) + ' '  END  set @cmd = ' SELECT TOP' + @TopV + ' e.EventName,  Count(*) as CountOfEvents,AVG(Duration) AS AvgDuration,MIN(Duration) AS MinDuration,MAX(Duration) AS MaxDuration,  SUM(a.Duration) AS [SumDuration],SUBSTRING(a.TextData, 1, '+ cast(@Len as nvarchar(4)) + ') AS [Substring from Text Data],  MIN(starttime) as MinStartTime,MAX(starttime) as MaxStartTime,AVG(CPU) AS AvgCPU,MIN(CPU) AS MinCPU,MAX(CPU) AS MaxCPU,  AVG(Reads)AS AvgReads,MIN(Reads) AS MinReads,MAX(Reads) AS MaxReads,AVG(Writes) AS AvgWrites,MIN(Writes) AS MinWrites,  MAX(Writes) AS MaxWrite,AVG(IntegerData) AS AvgIntegerData,MIN(IntegerData) AS MinIntegerData,MAX(IntegerData) AS MaxIntegerData    FROM dbo.' + @Trc +' a LEFT OUTER JOIN         dbo.trace_events e      ON a.EventClass = e.EventClass    WHERE 1=1'  if @textdata != 'none'  begin    set @cmd = @cmd + ' AND a.TextData like ''%' + @TextData + '%'  end  if @eventclass != 'all'  begin   set @cmd = @cmd + ' AND a.EventClass IN (' + @EventClass + ')'  end    set @cmd = @cmd +   ' GROUP BY SUBSTRING(a.TextData, 1, '+ cast(@Len as nvarchar(4)) + '), e.EventName    HAVING (SUM(a.Duration) > 0)    ORDER BY SUM(a.Duration) DESC'    exec(@cmd) GO

     1. Note   The AnlzTrcExec procedure is used to analyze the trace events used within this How To. It uses the trace_events table to provide English output names for the EventClass column and also provides several summary options. The stored procedure takes up to four parameters: trace table name, number of characters to group on from the query text, number of queries to return information for, and event class name. Only the trace table name is required.

12. Run the stored procedure using the following statement.

• 1. AnlzTrcExec 'MyTraceTable'

     1. Trace data is displayed using default options.

     2. Note   Only queries with a nonzero duration are shown in the summary information.

13. Run the following query.

• 1. AnlzTrcExec 'MyTraceTable', 20, 10, 41

     1. The top 10 'SQL:StmtCompleted' events are returned (ordered by the sum of duration) grouped on the first 20 characters of each query text.

_______________________________________________________________________________-

I’ve observed that as part of different incident(s), service requests, performance issues that we work on, very often requirement is to setup a SQL Profiler Trace to investigate on the issue. It is very important to interpret profile extract and only when we do that, our purpose is achieved else we are back to square one. I always recommend minimum events (using this word carefully) with appropriate filters considering the volume of data that are captured when we run a profiler so that it doesn't become unmanageable better we call it a PUZZLE.

 profiler events to understand how they can benefit us in troubleshooting different scenarios and following are my observations however you are free to add your own selections, but these are the primary counters we rely on.

Deadlocks/ Blocking

Lock: Deadlock

Lock: Deadlock Chain

Deadlock Graph

RPC: Completed

SQL: BatchCompleted

Blocked Process Report (Use if you only have to capture blockings)

General Performance Tuning issues

SP: StmtCompleted

RPC: Completed

SQL: BatchCompleted

Showplan XML

Long running queries

RPC: Completed

SQL: BatchCompleted

SP: StmtCompleted

Note : We can always add more events based on our requirement.