Sunday, August 11, 2013

Why my SQL Statement taking long time to execute

Why my SQL Statement taking long time to execute


There’s a lot of instrumentation in SQL Server that helps you see what your query is doing behind the scenes to retrieve a given result set. You can use trace files, queries against Dynamic Management Views (DMVs) and Dynamic Management Functions (DMFs), and the many graphic features of SQL Server Management Studio (SSMS) to better illustrate the behaviors of a given SELECT statement



SET STATISTICS I/O

The command SET STATISTICS IO ON forces SQL Server to report actual I/O activity on executed transactions. Once the option is enabled, every query thereafter produces additional output that contains I/O statistics. To disable the option, execute SET STATISTICS IO OFF. For example, the following script obtains I/O statistics for a simple query counting rows of the “Employees” table in the NORTHWIND database:

SET STATISTICS IO ON
GO
SELECT COUNT(*) FROM employees
GO SET STATISTICS IO OFF

Results: ----------- 2977 Table 'Employees'.
Scan count 1,
logical reads 53,
physical reads 0,
read-ahead reads 0.


The scan count tells us the number of scans performed. Logical reads show the number of pages read from the cache. Physical reads show the number of pages read from the disk. Read-ahead reads indicate the number of pages placed in the cache in anticipation of future reads.

Additionally, you would execute a system stored procedure to obtain table size information for your analysis:

sp_spaceused employees

Results: name rows reserved data index_size unused ---------- ---- --------- ------- ----------- ------- Employees 2977 2008 KB 1504 KB 448 KB 56 KB

What can you tell by looking at this information? The query did not have to scan the whole table. The volume of data in the table is more than 1.5 megabytes, yet it took only 53 logical I/O operations to obtain the result. This indicates that the query has found an index that could be used to compute the result, and scanning the index took less I/O than it would take to scan all data pages. Index pages were mostly found in the data cache since the physical reads value is zero. This is because the query was executed shortly after other queries on the Employees table, and the table and its index were already cached. Your mileage may vary. SQL Server has reported no read-ahead activity. In this case, data and index pages were already cached. A table scan on a large table read-ahead would probably kick in and cache necessary pages before your query requested them. Read-ahead turns on automatically when SQL Server determines that your transaction is reading database pages sequentially. A separate SQL Server connection runs ahead of your process and caches data pages for it. Configuration and tuning of read-ahead parameters is beyond the scope of this paper. In this example, the query was executed as efficiently as possible. No further tuning is required.

SET STATISTICS TIME

Elapsed time of a transaction is a volatile measurement, since it depends on activity of other users on the server. However, it provides some real measurement, compared to the number of data pages, which doesn’t mean anything to your users. They are concerned about seconds and minutes they spend waiting for a query to come back, not about data caches and read-ahead efficiency. The SET STATISTICS TIME ON command reports the actual elapsed time and CPU utilization for every query that follows. Executing SET STATISTICS TIME OFF suppresses the option.

SET STATISTICS TIME ON
GO
SELECT COUNT(*) FROM titleauthors
GO
SET STATISTICS TIME OFF
GO

Results: SQL Server Execution Times: cpu time = 0 ms. elapsed time = 8672 ms. SQL Server Parse and Compile Time: cpu time = 10 ms. ----------- 25 (1 row(s) affected) SQL Server Execution Times: cpu time = 0 ms. elapsed time = 10 ms.

SQL Server Parse and Compile Time: cpu time = 0 ms. The first message reports a somewhat confusing elapsed time value of 8,672 milliseconds. This number is not related to the script and indicates the amount of time that has passed since the previous command execution. You may disregard this first message. It took SQL Server only 10 milliseconds to parse and compile the query. It took 0 milliseconds to execute it (shown after the result of the query). What this really means is that the duration of the query was too short to measure. The last message that reports parse and compile time of 0 ms, refers to the SET STATISTICS TIME OFF command (that’s the time it took to compile it). You may disregard this message since the most important messages in the output are highlighted. Note that elapsed and CPU time are shown in milliseconds. The numbers may vary on your computer between runs of the query because the time values are dependent on total server load. In other words, every time you execute this script you may get slightly different statistics depending on what else your SQL Server was processing at the same time. If you need to measure elapsed duration of a set of queries or a stored procedure, it may be more practical to implement it programmatically (shown below). The reason is that the STATISICS TIME reports duration of every single query and you have to add things up manually when you run multiple commands.