Understanding SET STATISTICS IO and SET STATISTICS TIME

Eric — Sun, 23 Mar 2008 14:15:07 GMT

Today, I want to talk about two commands that are often overlooked. SET STATISTICS IO and SET STATISTICS TIME these two commands are very useful when comes time to tune a query.

Tuning a query seems simple enough. In essence, we want our searches to run faster. When I teach my class on “Optimizing SQL Server” I realize that many people find it difficult to accomplish this task. While there are many reasons why query tuning is difficult, this article will concentrate on one aspect. And that is that query tuning takes place in an environment that is often changing from second to second, making it hard to really know what exactly is going on.

When you run a query, different server resources are used. One of those resources is the CPU time. If you run the same query over and over again, the CPU time needed to run the query will remain very close from one execution to other. I am not talking about the total time it takes to run query from the start to the end, but the amount of CPU time needed to run the query.

Another resource that the Server needs is IO. Whenever you run a query, the server must retrieve data from memory (logical reads) or from the disk (physical reads). Using high CPU and IO resources will result in slow query performance.

So your goal should be to rewrite your queries in such a way that they use less CPU and IO resources. If you accomplish this, then the performance of your query will improve.

Both the SET STATISTICS IO and the SET STATISTICS TIME Transact-SQL commands have been around a long time. But for some reason, they are often ignored.

Both commands can be “turned on” using Transact-SQL commands or by setting the appropriate connection properties in Options dialog from the tools menu in Management Studio.

By default, these settings are not turned on. The SET STATISTICS IO and the SET STATISTICS TIME commands act like settings, turning on and off various reported information on the resources our queries use.

So let’s look at an example of how use these commands.

To begin our example, start Management Studio and connect to a SQL Server. For this example, we will use the sample database provided by with SQL Server 2005 and that is AdventureWorks. So start by making AdventureWorks your default database.

Next, run this query:

USE AdventureWorks;

SELECT * FROM Person.Contact;

Normally this query should return 19972 rows. Now, let’s run the same query, but this time, let's run the SET STATISTICS IO and the SET STATISTICS TIME commands before we run the query. Before we begin our example, run these two commands DBCC DROPCLEANBUFFERS and DBCC FREEPROCCACHE (don’t run these on a production server) first. These two commands will clear out SQL Server’s data and procedure cache.

DBCC DROPCLEANBUFFERS
DBCC FREEPROCCACHE

Now, enter and run the following Transact-SQL commands:

SET STATISTICS IO ON
SET STATISTICS TIME ON

Once you have done this, then run this command again:

SELECT * FROM Person.Contact;

After you run these command, you will see new information in the message tab that you did not see before.

(The results you get may vary, but we will talk about this below as we explain everything you see above.)

Let me explain what it all means:

SET STATISTICS TIME Results:

“SQL Server parse and compile time:” tells us how much CPU time and total time it took SQL Server to parse and compile our T-SQL statement. In my case, it took 0 ms. of CPU time, and a total time of 359 ms. of elapsed time. Your CPU time will probably vary because your server is different than mine.

If you re-execute the query, again without clearing the cache (as recommended above), most likely both instances of CPU and compile time will be 0, as the cached query plan will be reused, so no new compile time is required.

This is not too important, what is of interest to us is the time information displayed at the bottom of the query’s output. Here is it is again:

SQL Server Execution Times:

CPU time = 125 ms, elapsed time = 1112 ms.

What this tells us is how much CPU time was used to execute the query, and how long the query took to run. The CPU time is a somewhat consistent measurement of the amount of CPU resources it takes for your query to run, and this is relatively independent of how busy your CPU is.

The elapsed time number is a measurement of how long the query took to execute (not counting the time for locks or reads). This number will vary a lot because depending on the load on your server.

Because the CPU time is relatively consistent, this is what you should use to determine whether the changes you make in your queries, are helping or making things worse.

SET STATISTICS IO Results:

Table 'Contact'. Scan count 1, logical reads 561, physical reads 1, read-ahead reads 559, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.

This is not all useful; let me try to explain what it means.

Output item	Meaning
Table	Name of the table, in our case ‘Contact’
Scan count	Refers to the number of times that tables referenced in the query have been accessed. In our example, the table in our query was only accessed 1 time. For queries that don’t include joins, this information is not too helpful. But if your query has one or more joins, then this information may be of use to you. You may want to pay attention to the Scan Count, watching to see if it is increasing or decreasing as you tune the query.
logical reads	Number of pages read from the data cache. This is the most useful piece of data provided by the SET STATISTICS IO commands. As you probably know, before SQL Server can do anything with data, that data must be in its data cache. In addition, when SQL Server reads data from the data cache, it reads it in 8K pages. A logical read is the number of pages SQL Server had to read from the data cache in order to produce the results specified by our query. The exact same number of logical reads will always occur when the same query runs against the exact same data on SQL Server. Knowing the number of logical reads that SQL Server takes to execute a query is important because it is the one thing that never changes from one execution to another giving us the perfect reference to use when we are tuning a query to determine if you we are succeeding or failing. The fewer the logical reads performed by a query, the more efficient it is, and the faster it will perform, assuming all other things are held equal.
physical reads	Number of pages read from disk. This information is not too useful for query tuning. First of all, a physical read refers to when SQL Server must go to disk to get data pages it needs to put into the data cache before it can execute the query. As mentioned above, all data must be in the data cache before SQL Server can execute a query. Whenever SQL Server begins to execute a query, the first thing it does is to check and see if the data pages it needs are in the data cache.
read-ahead reads	Number of pages placed into the cache for the query. Like physical reads, this information is not too useful for query tuning. This value tells you the number of physical page reads that SQL Server performed as part of its read-ahead mechanism. To help optimize its performance, SQL Server reads physical data pages ahead of when it thinks your queries might need the data.
lob logical reads	Number of text, ntext, image, or large value type (varchar(max), nvarchar(max), varbinary(max)) pages read from the data cache.
lob physical reads	Number of text, ntext, image or large value type pages read from disk.
lob read-ahead reads	Number of text, ntext, image or large value type pages placed into the cache for the query.

Now for a real example:

To be honest with you, when you execute a query without a WHERE clause there’s not much you can do to tune a query because the server performs a scan on the table. Let’s take another example:

Execute the following code:

USE AdventureWorks;

SELECT * FROM Person.Contact WHERE firstname='Carla';

Now look at the Message tab:

Even though we have filtered our query and the elapsed time is down (data is cached), the logical reads are still at 561. This means that reading 25 rows is costing us the same as in the previous example that was returning 19972 rows.

One thing we could do to reduce the number of logical reads is to create an index on firstname (I will cover the creation of index in another article).

You can create an index directly in Management Studio by selecting the table in the object explorer and right clicking on the Indexes folder:

A new index dialog will appear:

Or you can execute the following code:

USE [AdventureWorks]

CREATE NONCLUSTERED INDEX [IDX_firstname] ON [Person].[Contact]

(

[FirstName] ASC

)

Either way, you will achieve the same result. Now re-execute the query and look at the message tab:

Now that is quite an improvement…

Hope this was useful, feel free to post any comments.

Eric

Technorati : SET STATISTICS IO,SET STATISTICS TIME,Tuning,SQL Server,Performance

Search results matching tags 'Performance' and 'SET STATISTICS TIME'

Understanding SET STATISTICS IO and SET STATISTICS TIME