STATISTICS TIME

What is tSTATISTICS TIME?

Last week you got to know STATISTICS IO, a tool that tells you how much data a query needs to read from disk to answer a query. How does STATISTICS TIME differ from STATISTICS IO? While STATISTICS IO logs disk accesses, STATISTICS TIME returns the CPU time required for a query. That is, the time that was used to read and understand the query and to find an execution plan for the query on the one hand, and the time that the CPU was busy calculating values during the execution of the query, for example.

How can you work with STATISTICS TIME?

If you want to see how many disk accesses a query causes, you can get this information by sending a ‘SET STATISTICS TIME ON’ before the query. What you will then see is a set of information that we will examine a bit more closely below.

Let’s use the statistics to query the StockItems table in the Wide World Importers database:

SET STATISTICS TIME ON
SELECT 
       [StockItemID]
      ,[StockItemName]
      ,[UnitPrice]
FROM [Warehouse].[StockItems]

In addition to the results, the Messages tab contains information about the execution:

SQL Server Execution Times:
CPU time = 1 ms, elapsed time = 0 ms
Total execution time: 00:00:00.019

Here you can see that the SQL Server had to spend a millisecond CPU time for the query. It is clear that the CPU did not have much to do here, only 3 values of a table were read and returned. So let’s give the CPU something to do by performing a calculation on one of the columns:

SET STATISTICS TIME ON
SELECT 
       sin([StockItemID])
      ,[StockItemName]
      ,[UnitPrice]
FROM [Warehouse].[StockItems]

So now we calculate the sine of the StockItemID. The ninja doesn’t want to say a word about how useful this is, but instead we’d rather talk about what happens to our statistics. The output now looks like this:

SQL Server parse and compile time:
CPU time = 0 ms, elapsed time = 0 ms.
(227 rows affected)
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.

Here you can see that the SQL Server now needs one more step in the query execution to read the query and determine an execution plan. However, the time required for this is so small that it is of no consequence and takes zero milliseconds for such a simple query. Even calculating the sine doesn’t seem to make the CPU glow at the moment, since the CPU time for the 227 lines isn’t even measurable, so according to the training principles of the ninja, we increase the complexity once again and try to get the CPU to calculate. To do this, we come up with something new and join to a larger table, doing a calculation on the columns we want to join.

Such a query would be, for example:

SET STATISTICS TIME ON
SELECT 
       si.[StockItemID]
      ,[StockItemName]
      ,[UnitPrice]
FROM [Warehouse].[StockItems] si
LEFT JOIN Warehouse.StockItemTransactions sit 
ON sin(si.[StockItemID]) = cos(sit.[StockItemID])

It is clear that this query is also completely meaningless, but it serves its purpose, because if you now look at the statistics, you should see an output that looks something like this:

SQL Server Execution Times:
CPU time = 97 ms,  elapsed time = 373 ms.
Total execution time: 00:00:00.453

Here you can see that the CPU of your computer actually had to perform some arithmetic operations for this query, which took 97 milliseconds of the 373 milliseconds your query took.

Similar to IO statistics, tuning queries using time statistics is a science in itself that would go beyond a simple ninja contribution. However, it’s worth taking a look at this, because even a parse and compile time of 10 milliseconds for a query that is executed 1000 times per minute will cause a difference in runtime of 10 seconds. Again, the Ninja in awe refers to the acknowledged tuning experts of this world.

References

Ninja-Notebooks @ GitHub

Leave a Reply

Your email address will not be published. Required fields are marked *