The Difference Between Statistics Time And Plan Operator Times In SQL Server Query Plans

Goal Posts

---

When you’re measuring query changes to see if your performance changes have made a difference, a common way to do that is to use STATISTICS TIME and IO.

They’re not perfect, but the barrier to entry is super low, and you can get a good enough feel for if you’re on the right track.

In a perfect world, people would only select the rows and columns they need.

Also in a perfect world: that really embarrassing thing you did in 3rd grade wouldn’t pop into your head every time you’re about to do something really important.

Durex

---

What can make judging differences tough is if you’re returning a lot of rows to SSMS.

Sometimes it feels like you can reduce reads and CPU time, but your overall query time hasn’t changed.

Now with query operator times, that becomes easier to see.

And Earl

---

Let’s take this query, which returns ~271k rows.

SET STATISTICS TIME, IO ON;

SELECT c.Score, c.UserId, c.Text 
FROM dbo.Comments AS c
WHERE c.Score BETWEEN 5 AND 30
ORDER BY c.Score DESC

In the Stack Overflow 2013 database, this runs for about 3 wall clock seconds.

It says so in the bottom corner of SSMS.

Since we turned on stats time, we can look in the messages window to see that information.

Here are the relevant details:

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

What looks odd here is that CPU and elapsed time are near-equal, but the plan shows parallelism.

Thankfully, with operator times, the actual plan helps us out.

The query itself ran for <900ms.

The situation isn’t so dire.

More Ales

---

In stats time, elapsed time measures until results are done getting to SSMS.

It might look like this query “ran” for ~3 seconds, but it didn’t. The query finished processing data in under a second, but it took another couple seconds for SSMS to render the results.

You can do a mock test by doing something like this:

DECLARE @blob_eater VARCHAR(8000);

SELECT @blob_eater = c.Score, 
       @blob_eater = c.UserId, 
	   @blob_eater = c.Text 
FROM dbo.Comments AS c
WHERE c.Score BETWEEN 5 AND 30
ORDER BY c.Score DESC

Now when we run the query, stats time is much closer to the operator finish time:

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

Thanks for reading!

Going Further

---

If this is the kind of SQL Server stuff you love learning about, you’ll love my training. I’m offering a 75% discount to my blog readers if you click from here. I’m also available for consulting if you just don’t have time for that and need to solve performance problems quickly.