Query Performance

How can I identify slow running queries and what causes a query to run slowly?

One approach I like to use to identify query performance issues  is use the built-in DMV’s available from SQL Server 2005 onwards. One of my favourites to start is sys.dm_exec_query_stats. This DMV looks at plans that are stored in the plan (procedure) cache. The view returns one row for each statement in a plan. When using this dmv I have to remind myself  that not everything gets stored in the plan cache for instance:

  • Zero cost or trivial plans
  • DBCC , Backups and RECOMPILES,

On top of this older plans can get aged out depending on resource requirements, so it will not give a complete picture of your system, but it is a good good place to start given its benefit’s including:

  • the data already collected for you by SQL Server
  • it is non intrusive and resource light

Query Anatomy

It is worth taking a quick step back and reviewing how the plan cache fits into to the Anatomy of a Query.  When a user executes a query SQL Server asks the  command parser to verify that the query is syntactically correct, once this completes successfully it next generates a hash for the query and checks the plan cache to see if an existing plan is available for the query. Command Parser checks the –> plan cache (part of the buffer pool memory). It is area of memory that sys.dm_exec_query_stats queries for its information

sqlplancahce

sys.dm_exec_query_stats

sys.dm_exec_query_stats can help identify where plans are over utilising resources such as:

  • CPU  (worker)
  • I/O – Memory (logical)
  • I/O – Disk (Physical)
  • CLR
  • Recompiles A bottleneck on any of these resources can cause queries to run slowly.

A quick but important distinction, important for SQL Server performance

  • Physical I/O = Disk = Expensive (slow)
  • Logical I/O = Memory = Faster

sys.dm_exec_query_stats gives the time the plan last  started executing and the time the plan was compiled. This can be useful in narrowing the scope of the result set, for example if I only want to look at queries executed today or this week. The dmv also gives the plan handle and sql handle these are tokens that refer to the batch and plan that the query is part of, more on these later.

 

The chart below distinguishes between the various resources required by a query and the values we can obtain from sys.dm_exec_query_stats.

image

Totals – are totals since last compile

max / min – values are values achieved ever by the query

When running a query I can order the result set based on any of the resources identified above. If for example I have already identified that  CPU is a bottleneck then I can order the result set by either total_worker_time or the average worker time DESCENDING.

Taking all this on board I usually end up with a query that look like:

SELECT
sql_handle
,plan_handle
,creation_time –time plan was last compiled
,last_execution_time — time the plan last started executing
,plan_generation_num – The number of times the plan was recompiled
,execution_count – number of times plan was executed since last recompile
,total_elapsed_time
,total_worker_time
,total_logical_reads
,total_physical_reads
,total_logical_writes
,last_elapsed_time
,total_worker_time/ execution_count  as avg_CPU_time
,last_worker_time
,total_logical_reads / execution_count  as avg_Logical_read
,last_logical_reads
,total_physical_reads  / execution_count  as avg_Physical_read
,last_physical_reads
,total_logical_writes / execution_count  as avg_logical_writes
,last_logical_writes
,total_elapsed_time
,last_elapsed_time
FROM SYS.dm_exec_query_stats
order by avg_CPU_time DESC

The result set will tell me; for an averaged execution which queries are using the most CPU time.

 

  • Has a query started to run slower and how can we tell ?
  • We already looked at the total_elapsed_time  /  execution_count = Average Elapsed time
  • Difference between the last_elapsed_time and the total_elapsed_time gives us an idea if it is running more slowly. Also we can look at the max_elapsed_time and the min_elapsed_time
  • Difference between Average worker Time  and last_worker_time = increase in query cpu time for last time run
  • Is the difference across multiple queries or just one?

sys.dm_exec_sql_text

To make it more meaningful and to allow me to start troubleshooting performance issues what I  need to see is the text of the query and the plan the query is using. To get these I use the sql_handle and plan_handle tokens I talked about earlier to call a couple of more DMV’s. Firstly sys.dm_exec_sql_text, this dmv is a function and takes the sql_handle as a parameter, it needs to be combined with the statement_start_offset and the statement_end_offset to retrieve the query text. Books Online has an example of how to achieve this.

(SELECT SUBSTRING(st.text, statement_start_offset/2 + 1,
(CASE WHEN statement_end_offset = -1
THEN LEN(CONVERT(nvarchar(max), st.text)) * 2
ELSE statement_end_offset
END – statement_start_offset) / 2
)
FROM sys.dm_exec_sql_text([sql_handle]) AS st) AS query_text

sys.dm_exec_query_plan

TO look at the query plan,I use the sys.dm_exec_query_plan dmv this takes the plan_handle as a parameter and returns the queries execution plan. Exercise caution when executing this dmv as can be resource intensive.

select * from sys.dm_exec_query_plan([plan_handle])

References

http://technet.microsoft.com/en-us/library/bb838723%28office.12%29.aspx

BOL search for : sys.dm_exec_query_stats

http://sqlblog.com/blogs/adam_machanic/archive/2010/04/22/a-warning-to-those-using-sys-dm-exec-query-stats.aspx

Advertisements