How to Identify Slow Running Queries using SQL Server Profiler


SQL Server Profiler is an interface to create and manage traces and analyze and replay trace results. Events are saved in a trace file that can later be analyzed or used to replay a specific series of steps when trying to diagnose a problem.
In this post we will see how to create a trace to capture slow running queries using profiler.

Selecting Events

Queries can come to a SQL Server instance in the form of stored procedures, batches of queries, or individual queries, so it's essential to include the necessary events to capture all three forms in which a slow-running query can appear.
Also, keep in mind that stored procedures can be executed in two different ways:
          -  An RPC event - i.e. as a result of a Remote Procedure Call.
          -  A Transact-SQL event - i.e. as a result of a call to the T-SQL EXECUTE statement
We need to capture both types of stored procedure events.

We will select some events that will help us to identify slow-running queries.

Events Description
RPC:Completed The RPC: Completed event fires after a stored procedure is executed as a remote procedure call.
SP:StmtCompleted The SP:StmtCompleted event tells us when a statement within a stored procedure has completed.
SQL:BatchStarting A SQL: BatchStarting event is fired whenever a new Transact-SQL batch begins. This can include a batch inside or outside a stored procedure.
Showplan XML This event displays the graphical execution plan of a query

Selecting Data Columns

Now, we have filtered some events to identify slow queries and will do the same for the data columns. We will be selecting only the data columns that are needed, in order to minimize the amount of resources consumed by the trace. The fewer data columns, the less overhead there is in collecting it.
In order to identify slow running queries we will select following data columns along with the events.

Data Columns Description
Duration This column provides the length of time in microseconds that an event takes from beginning to end. It is shown by default, in milliseconds
ObjectName This is the logical name of the object being referenced during an event. If a stored procedure is being executed, then the name of the stored procedure is displayed. If an isolated query is being executed, then the message "Dynamic SQL" is inserted in this data column. This column therefore provides a quick means of telling whether or not a query is part of a stored procedure.
TextData The contents of the TextData column depend on the event that is being captured and in what context.For some events like SQL:BatchStarting or SQL:BatchCompleted events, the TextData column will either contain the name of the executing stored procedure or, for a query outside a stored procedure, the Transact-SQL code for that query.
CPU This data column shows the amount of CPU time used by an event (in milliseconds). Obviously, the smaller this number, the fewer CPU resources were used for the query.
Reads This data column shows the number of logical page reads that occurred during an event. Again, the smaller this number, the fewer disk I/O resources were used for the event.
Writes This data column shows the number of physical writes that occurred during an event and provides an indication of the I/O resources that were used for an event.
IntegerData The value of this column depends on the event. For the SP:StmtCompleted event, the value is the actual number of rows that were returned for the event. For the ShowPlan XML event, it shows the estimated number of rows that were to be returned for the event, based on the query's execution plan.
DatabaseName This is the name of the database the event occurred in. Often, you will want to filter on this data column so that you only capture those events that occur in a specific database.
ApplicationName This is the name of the client application that is communicating with SQL Server. Some applications populate this data column; others don't. Assuming this data column is populated, you can use it to filter events on a particular application.
StartTime It includes the time the event started. Often, the start time of an event can be matched to other related events to identify their order of execution. It can also be compared to the stop time of events to determine the differences in time between when one event started and another completed
EndTime The EndTime data column is used for those events that have a specific end time associated with them. It can be used to help identify when a particular query or transaction runs at a specific point in time.
SPID This data column is mandatory for every event, and contains the number of the server process ID (SPID) that is assigned to the client process creating the event. It can help identify what connections are being used for an event, and can also be used as a filter to limit the number of events returned to those of particular interest.
LoginName This column stores the login of the user that triggered the event. Depending on the type of login used, this column can contain either the SQL Server login ID or the Windows Login ID (domain\username). This very useful data column helps you identify who is causing potential problems.
EventSequence Every event produced by SQL Server Profiler is assigned a sequence number that indicates the order that events occurred in SQL Server. Much of the time, you will capture traces in default order, which means the events are displayed in the order they occurred in the Profiler GUI. EventSequence numbers appear in ascending order.
BinaryData However, should you choose to apply a custom grouping, based on a certain data column such as Duration, then the EventSequence data column makes it easier for you to see which events occurred before, or after, other events.

Creating a filter

When creating a trace to identify long-running queries, we will be adding some filters in order to minimize the number of rows returned in a trace. 
The first filter is on the Duration data column, which returns the length of time it takes for a particular event to run. We will use 5000 milliseconds (5 seconds), although this is just a personal preference and can be adjust to best meet your needs. We will create second filter on the DatabaseName column, in order to limit trace data to events raised in a specific database, as shown below

Organizing Columns

Here, we are grouping column by Duration so that it becomes easy to identify the longest-running queries:

Creating Template

If you frequently monitor SQL Server, use templates to analyze performance. The templates capture the same event data each time and use the same trace definition to monitor the same events. There is no need to define the event classes and data columns every time while creating a trace. Also, a template can be given to another user to monitor specific SQL Server events. For example, a support provider can supply a customer with a template. The customer uses the template to capture the required event data, which is then sent to the support provider for analysis.

Running the trace

Once you have created your trace template, it is time to run it. Ideally this will be on a production server, otherwise on a test server and a stress test tool, or a simple load-generation script. Keep the following in mind when you run this trace to identify slow running queries:
  • Select a day that represents a typical workload.
  • Run the trace for an entire day. This might seem like a long time, but if your filters are effective, you should not collect too much data. If this is the first time you have run it, you may want to monitor the trace file size throughout the day to ensure that it is not using up too much space.
  • Before you start the trace, choose to save it to a file as the trace runs.
  • Start the trace manually and set it to stop automatically after 24 hours.
  • Up to this point, we have only discussed running traces from the Profiler GUI. However, you can also run this same trace using system stored procedures. By doing so, you will reduce the load on the server. You will learn how to use system-stored procedures to run a trace later in this book, in the chapter on "How to Capture Profiler Traces Programmatically".

Understanding the trace

Now we have created a trace, the next step is to review each event in the trace, starting with those at the bottom – i.e. the slowest-running events that took the most time to execute. Note that, the events are grouped by Duration, each event is aggregated by Duration. Click on the plus sign next to each of the duration to drill down and examine the events, as shown below

Execution of the stored procedure appears to be associated with the event: SP:StmtCompleted. For example, SP:StmtCompleted event is related to completion of the execution of a SELECT *…query within the INS_ServApprovalReq_Select stored procedure. Its duration was 7244, the CPU time was 1125 and there were 72586 reads. Following that is a RPC:Completed event relating to completion of the execution of the remote procedure call INS_ServApprovalReq_Select stored procedure, with a duration of 7244, CPU time of 1125 and 72586 reads. 
The Duration, CPU and Reads times for these two events look similar because they are in effect with the same event. We have an execution of a stored procedure that contains a single T-SQL statement. The SP:StmtCompleted is fired when the Transact-SQL statement within the stored procedure has completed; the RPC:Completed event is fired when a stored procedure is executed as a remote procedure call. In this case, these two events occur more or less simultaneously.
We also have showplan XML event that gives a graphical execution plan of the Transact-SQL as shown below:

NOTE: SQL Trace and SQL Server Profiler will be deprecated. This feature may not be available in a future version of Microsoft SQL Server. SQL Server Profiler for Analysis Services workloads is NOT deprecated, and will continue to be supported. Use Extended Events instead.

No comments:

Post a Comment