Actual Time Statistics in Execution Plans: Elapsed CPU Time and more

One of the coolest things to come to SQL Server Management Studio in a long time might be hard to see at first: it’s tucked away in the Properties Window.

But once you see it, it might just be something that you use all the time.

SQL Server now shows Actual Elapsed CPU Time and Actual Elapsed Time (duration) for each operator in an Actual Execution Plan

For SQL Server 2016 and 2014 SP2 and higher, actual execution plans contain a bunch of new information on each operator, including how much CPU they burn, how long it takes, and how much IO is done by that operator. This was a little hard to use for a while because the information was only visible in the XML of the execution plan.

Now you can see this information with just a few clicks in the properties window of a plan. Here’s the announcement from the SSMS team.

Watch an example: Finding Actual Time Statistics in an Execution Plan

Here’s an animated gif of running a query with ‘Actual Execution Plans’ turned on, then right-clicking to see the Properties window and looking at Elapsed CPU Time (ms) and Elapsed Time (ms) for specific operators:

Some things to note:

• The query took just over 8 seconds to execute. (It’s shorter in the .gif because I sped up the video)
• The total CPU time on the index scan shows as 20+ seconds. That’s because it’s adding up the CPU time for all the threads– this query is running at MAXDOP 4. The threads were pretty evenly distributed on the index scan and the longest one took about 5.2 seconds
• Notice how Thread 0 doesn’t accrue time? It’s the “watcher thread” that just waits for the worker threads to complete. It’s supposed to be lazy like that.
• The threads on the Stream Aggregate operator took some time as well–  8.4 seconds on the longest thread

Wait, Kendra, those don’t add up!

No, they don’t. That’s OK! As data flows through this execution plan, multiple operators can be busy at the same time. SQL Server doesn’t have to wait for the index scan to finish before it works on the Compute Scalar and the Stream Aggregate operator - in this case, these operators are non-blocking. (Craig Freedman writes about blocking vs. non-blocking operators in this post.)

Let’s watch the same query with Live Query Statistics turned on

Here’s the same query running with Live Query Stats. You can see that the data is flowing through and that multiple operators are working at the same time.

We get a lot of cool information from this view, but we don’t get the same detail that we get for Actual Elapsed CPU Time and Actual Elapsed Time in the properties window of an actual execution plan. These two tools complement each other nicely.

You can also see Actual IO Statistics

It’s not just about the CPUs, for each operator you can also see how many logical reads, read ahead reads, and physical reads done by that operator. And it’s all right there in the properties window now. Enjoy!