Wednesday, June 28, 2017

Performance auditing with xSQL Profiler: Identifying slow queries

Most large scale systems, at some point in time, are bound to display a database related performance issue. As a DBA, if you haven't already, you will undoubtedly get a phone call or an email from a developer telling you that, somewhere in the midst of all the database's T-SQL code, you need to find those queries that are disrupting the system's performance. When this happens, usually you will have two choices: spend hours and hours running and testing queries to see which one could potentially be blocking the system, or employ a tool like xSQL Profiler that will collect information while the database is at work, filter that information, and present you only the execution related information needed to identify slow running queries. Needless to say why, the second option is much better.

xSQL Profiler offers an abstraction on top of SQL Server's native tracing mechanisms, SQL Traces. Let's go over the process of creating a traces on xSQL Profiler to identify slow running queries.

Event Definitions

SQL Traces register information provided by SQL Events when they are triggered during SQL Server's operation. xSQL Profiler supports all the native SQL Server event definitions and, in addition to this, it comes with extra built in event definitions which group together SQL Events that kind of "go together" and provide the full picture behind an action in SQL Server. To identify slow running queries you need to create traces that collect T-SQL execution related information such as the duration, I/O operations, records affected, estimated execution plans, etc.
I am going to use 2 xSQL Profiler event definitions from the "Performance" section of the Event Selection: Statement performance, and Analyze performance issues, and one event from the native SQL Server events: Performance - Showplan XML.

All together these events register data related to:

  • Query compilation and execution plans. This information is very useful in finding out why a query is running slow. For example, if the estimated number of records is different from the actual number of records in an execution plan, that means that SQL Server statistics are not up to date, which is one of the reasons queries might not perform well. These data are collected by the 'Performance - Showplan XML' xSQL Profiler event.
  • Query execution. This is the most useful information in identifying problematic queries. These data will show you when a piece of T-SQL code started executing, how long it took, how many I/O operations were performed, how much CPU resources were used, who executed the query, etc. Information regarding the query execution is mostly recorded by the 'Statement performance' and 'Analyze performance issues' events. 

Event Columns

Another very important aspect in building traces to identify slow queries is specifying the correct event columns. This affects both the effectiveness and efficiency of the traces. Choosing the right columns is substantial to gathering the information you need, and besides that, you should keep in mind that with every column you select there is an extra amount of data that needs to be collected which presents extra overhead for the server. So knowing exactly which columns to choose will help you avoid any unnecessary overhead on the server. Let's go over the necessary columns for each event definition:

Statement Performance

  • Duration - this right here is a no brainer. If you want to identify slow running queries you will most definitely need to know how long a query took to execute. This column displays the duration of the event in microseconds.
  • ObjectName -  this column shows the SQL object that executed the query. If it is a stored procedure or a function, it will show the function name. If it is a T-SQL statement that is not in a stored procedure, it will have the value 'Dynamic SQL'.
  • TextData - the value of this column depends on the SQL event that is being captured. for this event, it will display the T-SQL code for each of the statements that are being executed, inside and out of stored procedures.
  • CPU - This column shows the amount of CPU time (in milliseconds) used by the query.
  • Reads - This column shows the number of logical reads performed by the query. The smaller this number is, the less I/O operations are performed.
  • Writes - This column displays the number of physical writes a query performs. Again, the smaller this number, the less I/O operations are performed.
  • IntegerData - for this event definition, it will show the actual number of rows that are returned by the query. If the query is being executed by an application and it returns a high number of rows, you might want to think about making the WHERE clause a bit more restrictive or applying paging to get a smaller number of records because chances are, the client application does not need that many records.
  • ApplicationName, LoginName - this column are self descriptive, and while they serve no purpose on indicating whether the query is slow or not, they are very useful filtering columns in case your database is being queried by more than one application or user. If more than one application communicates with the database, but you know that only one of those applications has performance issues, you could place a filter on the ApplicationName or LoginName columns to record events that are raised only by that specific application or user.
  • Event sequence - The value on this column serves to show the sequence in which the events were raised. It will be used to link each individual query with it's execution plan.

Analyze performance issues

The columns for this event are the same as for the previous because the SQL events this event definition gathers data for, complement the events from 'Statement performance'.

Performance - Showplan XML

  • TextData - The value in this column is the XML text of the query's estimated execution plan. To view the execution plan simply save this value in a .sqlplan file and open it SQL Server Management Studio.
  • IntegerData - for this event, the value in this column displays the estimated number of returned rows.
  • EventSequence - the value of this column will always be 1 unit smaller than the value of the same column for excecution related events for the same queries. For example, if the value of EventSequence for SP:StmtCompleted SQL Event is 1001, the excecution plan for that query is in XML format in the row with event sequence 1000.  So if you order the data by EventSequence, the data from Showplan XML will always appear above the rest of the data for one query, enabling you to understand which execution plan belongs to which query.


The most important filter here is placed on the 'Duration Column'. Here you specify the threshold for a query to be considered "slow". There is no real formula for this value because it depends entirely on what a DBA considers a slow query but a good starting point is specifying the Duration to be greater than or equal to 5,000,000 microseconds (5 sec). You can then lower or raise this threshold depending on the data that the trace returns. If running the trace again is not an option you can always use xSQL Profiler's reporting capabilities to filter the data however you see fit.



Post a Comment