Search code examples
sql-serverperformanceunit-testing

Understanding SQL Server query performance testing - output not understood


I am trying to test the time it takes to run certain queries in my project. I am testing the query in management studio.

Here is a snippet of my code:

SET STATISTICS TIME ON

SET STATISTICS IO ON
EXEC <my stored procedure>

SET STATISTICS IO OFF
SET STATISTICS TIME OFF

I do not understand what I am getting as an output:

SQL Server Execution Times:
   CPU time = 0 ms,  elapsed time = 0 ms. 
SQL Server parse and compile time: 
   CPU time = 21 ms, elapsed time = 21 ms.

 SQL Server Execution Times:
   CPU time = 0 ms,  elapsed time = 0 ms.
Table 'Worktable'. Scan count 0, logical reads 0, physical reads 0, page server reads 0, read-ahead reads 0, page server read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob page server reads 0, lob read-ahead reads 0, lob page server read-ahead reads 0.
Table 'product_loadtable'. Scan count 1, logical reads 942, physical reads 0, page server reads 0, read-ahead reads 0, page server read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob page server reads 0, lob read-ahead reads 0, lob page server read-ahead reads 0.
Table 'Workfile'. Scan count 0, logical reads 0, physical reads 0, page server reads 0, read-ahead reads 0, page server read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob page server reads 0, lob read-ahead reads 0, lob page server read-ahead reads 0.
Table 'product_option'. Scan count 2, logical reads 26, physical reads 0, page server reads 0, read-ahead reads 0, page server read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob page server reads 0, lob read-ahead reads 0, lob page server read-ahead reads 0.
Table 'product_description'. Scan count 157, logical reads 628, physical reads 0, page server reads 0, read-ahead reads 0, page server read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob page server reads 0, lob read-ahead reads 0, lob page server read-ahead reads 0.
Table 'barsizes'. Scan count 0, logical reads 314, physical reads 0, page server reads 0, read-ahead reads 0, page server read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob page server reads 0, lob read-ahead reads 0, lob page server read-ahead reads 0.
Table 'product_detail'. Scan count 1, logical reads 17, physical reads 0, page server reads 0, read-ahead reads 0, page server read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob page server reads 0, lob read-ahead reads 0, lob page server read-ahead reads 0.
Table 'product'. Scan count 1588, logical reads 6299, physical reads 0, page server reads 0, read-ahead reads 0, page server read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob page server reads 0, lob read-ahead reads 0, lob page server read-ahead reads 0.
Table 'inventory'. Scan count 1, logical reads 24, physical reads 0, page server reads 0, read-ahead reads 0, page server read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob page server reads 0, lob read-ahead reads 0, lob page server read-ahead reads 0.
Table 'option_value'. Scan count 1, logical reads 3, physical reads 0, page server reads 0, read-ahead reads 0, page server read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob page server reads 0, lob read-ahead reads 0, lob page server read-ahead reads 0.

 SQL Server Execution Times:
   CPU time = 0 ms,  elapsed time = 41 ms.

 SQL Server Execution Times:
   CPU time = 31 ms,  elapsed time = 62 ms.

 SQL Server Execution Times:
   CPU time = 0 ms,  elapsed time = 0 ms.

Completion time: 2023-04-21T09:49:57.7878903-04:00

Why so many SQL Execution times - are they additive? Can I make all the times into one easy to read time? Am I doing something wrong here?


Solution

  • Assuming that STATISTICS TIME was OFF at the start of the batch, you likely have:

    1. SET STATISTICS IO ON (CPU time = 0 ms, elapsed time = 0 ms.)
    2. Parsing and compiling of your procedure (CPU time = 21 ms, elapsed time = 21 ms.)
    3. The first statement in your procedure (CPU time = 0 ms, elapsed time = 0 ms.)
    4. The second statement in your procedure (CPU time = 0 ms, elapsed time = 41 ms.)
    5. The total duration of your procedure (CPU time = 31 ms, elapsed time = 62 ms.)
    6. SET STATISTICS IO OFF (CPU time = 0 ms, elapsed time = 0 ms.)

    You might want to use SET STATISTICS IO, TIME <ON|OFF> instead, to remove 2 of those steps.