Wednesday, 27 March 2013

Profiler and trace

I have a question regarding profiler, What exactly are reads? and what is the correlation between cpu, reads and duration? is that correlation direct?


I typically start by tracing the SQL:BatchCompleted event and the RPC:CompletedEvent event. These two events should capture performance for all your SQL batches and stored procedures. The SQL:BatchCompleted event is generated whenever a batch of SQL statements is completed. If you run code in SQL Server Management Studio (or Query Analyzer) it will generate SQL:BatchCompleted events. If you create a .NET SqlCommand object and give it a CommandType of "Text" that will also generate SQL:BatchCompleted events. If your SqlCommand object has a CommandType of "StoredProcedure" that will generate RPC:Completed events.

Data Columns

I normally capture the following data columns for the two events above:

1. EventClass. This identifies the event. It must be selected.
2. TextData. This is the text of the SQL batch or the name of the stored procedure. We'll see situations below where RPC:Completed events that have what looks like a SQL batch in the TextData.
ApplicationName. This is the name of the application that generated this event such as Query Analyzer or SQL Server Management Studio. This is something you can set in your applications through the connection string.
3. HostName. This is the computer that connected to SQL Server and issues the SQL statement.
4. LoginName. This identifies the account that the SQL statements were run under.
5. EndTime. This identifies when the event ended. StartTime could be used instead.
6. SPID. This is the SPID of the connection that ran the SQL statement. This is required.
7. CPU. This is the actual amount of CPU used in milliseconds (one thousandth of a second).
8. Duration. This is the actual duration of the batch. In SQL Server 2000 traces it is in milliseconds. In SQL Server 2005 this is reported in microseconds (one millionth of a second) however Profiler 2005 automatically translates it back into microseconds.
9. Reads. This is the number of logical disk reads in 8KB pages. For example if this number is 85 then SQL Server logically read 5,570,560 bytes of data (85 pages times 8192 bytes per page). Physical disk reads are typically much lower than logical reads as SQL Server typically caches data pages. There's no direct way to find the number of physical reads a query generates. I typically find a fairly strong correlation between logical and physical reads though. If I can reduce the logical reads usuallly the physical reads will fall also. These logical reads also take up memory. Either these data pages are already in memory or they are read into memory. A high logical reads is also a good proxy for the memory usage of a query.
10. Writes. This is the nubmer of logical disk writes in 8KB pages. Logical writes are typically much closer to physical writes. I usually don't look at this number as much.
Those events should give you a good start identifying slow queries or queries that use a lot of resources.


You may see a pattern like this:

declare @P1 int
set @P1=180150001
declare @P2 int
set @P2=8
declare @P3 int
set @P3=1
declare @P4 int
set @P4=1
exec sp_cursoropen
  @P1 output,
  N'select SomeColumn FROM TableName',
  @P2 output,
  @P3 output,
  @P4 output
select @P1, @P2, @P3, @P4
- - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
exec sp_cursorfetch 180150001, 2, 1, 1
- - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
exec sp_cursorclose 180150001
The three sections above will be three different events. The sp_cursorfetch event may be repeated any number of times. You'll find it will be repeated once per row returned by the query. This is a server-side cursor and it is the slowest way to query data out of SQL Server.

This occurs when the client issues an sp_cursoropen statement with a SQL query. This executes and is stored in a temporary table. For each row the client wants to return it issues an sp_cursorfetch. When it's done it issues an sp_cursorclose to close the cursor and delete the temporary table. This means that the client makes on full round trip to SQL Server for EACH row it wants to return. You'll find that each individual event profiled (the creates, fetches and closes) isn't that slow but combined they result in terrible performance. In SQL Server 7.0 this also resulted contention in tempdb as the database was locked while the temporary table was created.

I typically see these when a client has two active result sets open on a single connection. For example, a client might run a query to list all the books that match a search criteria. Then inside the loop that is returning that data it will run a second query to get some additional details about each book returned. That second query will run against the same connection as the outer query. That results in a server-side cursor. I think you can also generate these by specifying a server-side cursor in ODBC or OLEDB.

These typically have to be fixed on the client side by creating additional connections for each active query. If you have access to the source code they are fairly easy to fix. In ADO.NET 2.0 you can use the Multiple Active Resultset (MARS) option to allow this same situation without generating a server-side cursor.

In ClearTrace I pull the actual executed SQL statement out of the sp_cursoropen statement. I prefix it with "{CURSOR}" so it can be easily identified as a server-side cursor. You can use the keyword search to quickly find these.

Prepared SQL

I also see this pattern quite a bit -- especially with Access:

declare @P1 int
set @P1=1
exec sp_prepare
  @P1 output,
  N'@P1 int',
  N'SELECT CustName FROM Customers CustID = @P1', 1
select @P1
- - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
exec sp_execute 1, 125
- - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
exec sp_execute 1, 126
- - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
exec sp_execute 1, 127
- - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
exec sp_unprepare 1
The sp_prepare statement is compiling the SQL statement (i.e. building a query plan) and assigning it handle of 1. Each sp_execute statement is calling that SQL statement and passing it the second value as the parameter @P1. The final statement is unpreparing statement nubmer 1. There are a number of variations on this including sp_prepexec and sp_prepexecrpc. I don't know if this is actually any faster than just executing the raw SQL statements. In ClearTrace I replace each sp_exectue statement with the actualy SQL statement it executes.


Profiler has a useful search functionality that helps you find particular piece of information you're looking for. To activate such a search, simply choose Edit --> Find within the Profiler. The "Search value" is the string that you are looking for. Data column lets you specify the particular data column you wish to find the search value in. If you don't specify the data column then all columns within the current trace will be searched. The Find Next and Find Previous buttons let you find the same piece of information again. The search functionality within the Profiler is great for finding execution of the same stored procedure or events caused by the same login. The limitation of this tool is that you cannot order or group data within the trace once it is collected.

If you wish to perform a more extensive analysis of the captured trace you should save its output as a SQL Server table. To do so, choose File --> Save As --> Trace Table within the Profiler. You will be asked to provide the server name where you wish to save the trace to and valid login credentials. Once you connect to the server you must also provide the database name and table name where trace should be saved. You can choose an existing table as the destination for the trace, so long as it has the same structure (data columns) as the trace. Keep in mind however, that saving a trace as a SQL Server table can be a resource and time intensive operation. The trace that contains millions of rows might take a while to save as a table. Therefore, avoid saving traces to production SQL Servers.

Once you have saved a trace as a table you can treat it as any other SQL Server table - you can build indexes, add and remove columns, build views on top of this table and so forth. The main advantage of saving a trace as a table is the extensive searching and sorting capabilities available with TSQL. For example, to return all events generated by SQL Server Enterprise Manager from the saved trace you could execute the following query:
1. SELECT * FROM replay_trace WHERE ApplicationName = 'MS SQLEM'
If you wish to see events in the order of their duration and CPU time taken, simply order the output by those columns:
2. SELECT * FROM replay_trace WHERE ApplicationName = 'MS SQLEM' ORDER BY duration, CPU
Here is a SELECT statement that will return the least, greatest and average execution time for each captured event, along with the total number of executions of that query. The output is ordered by the total number of times a particular statement was executed. This statement is useful for identifying the longest running queries; therefore it limits the output only to those events that have reported the duration of 1 or more milliseconds:
SELECT MAX(duration) AS MaximumExecutiontime, MIN(duration) AS MinimumExecutiontime, AVG(duration) AS AverageExecutiontime, COUNT(*) AS NumberOfTimes, SUBSTRING(TextData, 1, 255) AS QueryText
FROM trace
/* eliminate those events that don't report duration or report 0 milliseconds */
WHERE duration > 0 AND duration IS NOT NULL GROUP BY SUBSTRING(TextData, 1, 255) ORDER BY 3 DESC
Notice that TextData column has a data type of TEXT and therefore cannot be used within GROUP BY statements unless you apply a SUBSTRING function first. That is why the statement above only brings back the first 255 characters of the text data column. Notice also that when you save the trace as a table, the event class column is automatically converted to the event number. If you wish to limit the query output by event class you must use event numbers. For example, the following query limits results by event number 41, which is SQL: StmtCompleted:
view sourceprint?
4. SELECT * FROM trace1 WHERE EventClass = 41 /* SQL: Stmt Completed */
ORDER BY duration DESC

No comments:

Post a Comment