What is Elapsed time, CPU time in SET STATISTICS TIME ON.
Question
Monday, October 15, 2018 5:17 AM
Hi Everyone,
I have a simple Question.
When we do SET STATISTICS TIME ON and run a query.
We get results like:
SQL Server Execution Times:
** CPU time = 5672 ms, elapsed time = 5867 ms.**
As I understand:
elapsed time = CPU time + IO time.
IO time = IO time (read) + IO time (write) + network time.
Is my understanding correct?
Regards
Sharat K Gupta
All replies (29)
Monday, October 15, 2018 5:50 AM
Older thread, but a good discussion....
Please mark this reply as answer if it solved your issue or vote as helpful if it helped.
[Blog]
Monday, October 15, 2018 6:12 AM
Hi Latheesh,
Thanks for the link. I referred to it.
In the older thread David said:
Elapsed Time = CPU Time + Waits.
On a standalone with the database in single user mode, there are no "Waits".
So, on a standalone:
Elapsed Time = CPU Time + IO time.
IO time = disk IO (read) time + disk IO (write) time + network time.
Is my understanding correct?
Regards,
Sharat
Monday, October 15, 2018 7:24 AM
No. CPU time can be both greater and less than elapsed time. It will be less when the process had to wait. Which could be I/O. But it could also have been blocked by another process. Or it can have just been waiting for a slot to execute on the CPU. The CPU time can also exceed the elapsed time by wide margin, if there is parallelism.
Erland Sommarskog, SQL Server MVP, esquel@sommarskog.se
Monday, October 15, 2018 8:09 AM
Hi Erland,
You said: "CPU time can be both greater and less than elapsed time."
On a standalone when we do SET STATISTICS TIME ON and a query. Its returns CPU time and elapsed time.
What is elapsed time, is it not the total time taken by the query?
Let me put it this way, there are 4 equations here:
1) elapsed time = total time taken by the query to execute from start to end.
2) total time (elapsed time) = CPU time + total IO time. So how can CPU time be more than elapsed time, simple mathematics?
3) total IO time = disk IO time (read) + disk IO time (write) + network time
4) In case of standalone: network time = time taken to return results to client on the same machine, where as in case of networked machine: network time = time taken to return results to client from server on a different machine through network.
Do you agree? If not, which equation is incorrect?
Sharat
Monday, October 15, 2018 8:25 AM
That assumption is incorrect - Wait times have nothing to do with being on a stand alone server or not.
As part of any sql being executed SQL Server process has to execute multiple processes, and each of those sub-processes has a wait for execution associated with it. So if it needs to read from disk there will be a PAGE* wait. and so on.
Google for SQL Server Wait types to find out more - and do read this link SQL Server Wait Stats
Monday, October 15, 2018 8:38 AM
Hi none_none_none,
Welcome to the thread.
On a standalone with database in single user mode (no WAIT on any resource). When we do SET STATISTICS TIME ON and execute a query. Its returns CPU time and elapsed time.
What is elapsed time, is it not the total time taken by the query?
Let me put it this way, there are 4 equations here:
1) elapsed time = total time taken by the query to execute from start to end.
2) total time (elapsed time) = CPU time + total IO time. So how can CPU time be more than elapsed time, simple mathematics?
3) total IO time = disk IO time (read) + disk IO time (write) + network time
4) In case of standalone: network time = time taken to return results to client on the same machine, where as in case of networked machine: network time = time taken to return results to client from server on a different machine through network.
Do you agree? If not, which **EQUATION ** is incorrect? Do not post some English, post which EQUATION out of the 4 EQUATIONS is wrong?
Do you not have knowledge of this and its beyond your level of comprehension? Techical discussions are based on Metrics and NOT some unnecessary English.
Regards,
Sharat
Monday, October 15, 2018 8:47 AM
Stop posting the same question again and again - I gave you the answer, and I gave you a link to a very extensive explanation of what wait stats are - on the other thread that was posted by Latheesh NK there is also a wealth of information regarding this same question so go read what has been given to you.
Also this from Paul Randal - Wait statistics, or please tell me where it hurts again has all info on wait stats - with the 3 links given to you there is enough information for a beginner to see that your assumptions are wrong and that your point 2, 3 and 4 are incorrect.
Monday, October 15, 2018 9:01 AM
Hi none_none_none,
Points 2, 3 and 4 are incorrect. Why? please give a valid reason. Its simple Mathematics.
Its okay to disagree, but without a valid reason, you are just an unreasonable person or you do not have the basic technical know-how.
Sharat
Monday, October 15, 2018 9:20 AM
What is elapsed time, is it not the total time taken by the query?
That's the wallclock time for the execution.
2) total time (elapsed time) = CPU time + total IO time. So how can CPU time be more than elapsed time, simple mathematics?
Because of parallelism. That is, the query may have executed on multiple CPUs simultaneously.
Monday, October 15, 2018 9:58 AM
Hi Erland,
What is difference between "wallclock time" and "total time" and "elapsed time"? Its showing red underline under "wallclock" no such word in the Technet Dictionary. Word is clock.
So, Question is:
What is difference between "clock time" and "total time" and "elapsed time"?
Regards,
Sharat
Monday, October 15, 2018 11:50 AM
Sorry around that. A wallclock is simply a clock that hangs on the wall. "wallclock time" is just a way to say "actual time". That is, elapsed time is the same time as you would have measure if you had used a stopwatch (and had been perfectly synchronised with the computer). Not sure what you mean with "total time" here.
The important thing is that elapsed time and CPU time are really two different things. See it this way: how long time does it take to complete Tour de France? 2-3 weeks I believe from start whereever they start until the finish on Champs d'Elyssé. How much time in total have all cyclists cycled? A lot more than 2-3 weeks, since there are many cyclists.
Erland Sommarskog, SQL Server MVP, esquel@sommarskog.se
Monday, October 15, 2018 12:04 PM
Hi Erland,
So you agree that "elapsed time" measured by computer is same as "clock time" measured by stopwatch synchronized with the computer. Good.
What is elapsed time?
Is it execution time taken by the query?
If a query starts at "Monday, October 15, 2018 5:32 PM" and ends at "Monday, October 15, 2018 5:33 PM"
Is the elapsed time = 1 minute?
Is the clock time = 1 minute?
Regards
Sharat
Monday, October 15, 2018 9:16 PM
So you agree that "elapsed time" measured by computer is same as "clock time" measured by stopwatch synchronized with the computer. Good.
Yes. Conceptually at least. Timing in modern computers is somewhat problematic. Say that you do this:
DECLARE @d datetime2(3) = sysdatetime()
EXEC quick_procedure
SELECT datediff(ms, @d, sysdatetime())
You may see a negative execution time! And the above is more or less the same as SET STATISTICS TIME ON. I don't know if they have any logic to avoid negative duration. But conceptually it is the same: how long time did it take?
As for why you can get negative durations, this has to do with CPU frequency often varying to save energy etc, and different CPU may be slight out of sync with each other. But this does not affect the concept. Just imagine that you look at one watch when you start doing something, and an other when you stop and compte the duration that way.
Erland Sommarskog, SQL Server MVP, esquel@sommarskog.se
Tuesday, October 16, 2018 8:11 AM
Hi Erland,
I created 3 quick_procedures.
Create proc quick_procedure1
As
Select 0
GO
Create proc quick_procedure2
As
Select 1
GO
Create proc quick_procedure3
As
Select NULL
GO
And executed them repeatedly as follows:
DECLARE @d1 datetime2(3) = sysdatetime()
Exec quick_procedure1
SELECT datediff(ms, @d1, sysdatetime())
GO
DECLARE @d2 datetime2(3) = sysdatetime()
Exec quick_procedure2
SELECT datediff(ms, @d2, sysdatetime())
GO
DECLARE @d3 datetime2(3) = sysdatetime()
Exec quick_procedure3
SELECT datediff(ms, @d3, sysdatetime())
GO
"You may see a negative execution time! ". Yes I see its happening. But not the execution time that's negative. its the result reported by datediff() that's negative.
So I ran another repeatedly test,
SET STATISTICS TIME ON
GO
--DECLARE @d1 datetime2(3) = sysdatetime()
Exec quick_procedure1
--SELECT datediff(ms, @d1, sysdatetime())
GO
--DECLARE @d2 datetime2(3) = sysdatetime()
Exec quick_procedure2
--SELECT datediff(ms, @d2, sysdatetime())
GO
--DECLARE @d3 datetime2(3) = sysdatetime()
Exec quick_procedure3
--SELECT datediff(ms, @d3, sysdatetime())
GO
I never got negative CPU time or negative elapsed time. Both CPU time and elapsed time were = 0 ms, never a negative value.
Datediff() reports the difference in clock time where as SET STATISTICS TIME returns the CPU time and elapsed time.
**Quick Question: Datediff() returns negative value only for procedures that have elapsed time of 0 ms. But for a quick procedure which has elapsed time greater than 0 ms, datediff() will not return a negative value, Correct?. I am trying to write a quick procedure that has elapsed time of 1 ms, not so easy to do. **
Regards
Sharat
Tuesday, October 16, 2018 11:39 AM
I'm not saying that you always get a negative value. I'm saying that it can happen. It can be difficult to reproduce at will. I can't speak for what SET STATISTICS TIME ON reports in these case, because it is nothing I have studied.
Note that an elapsed time of 0 ms is of course a rounded value. The real value maybe 1.2 µs or whatever, but time measurement in a normal computer is simply not that accurate to register this.
Erland Sommarskog, SQL Server MVP, esquel@sommarskog.se
Tuesday, October 16, 2018 12:54 PM
Hi Erland
SET STATISTICS TIME ON return times is ms (milliseconds) while datediff() can return differences in ns (nanoseconds).
Why are we talking of a case where datediff() returns a negative value? It will happen only in case when elapsed time = 0 ms. We are taking an example of a query that takes more than 0 ms elapsed time, say 1 minute.
My original Question was:
If a query starts at "Monday, October 15, 2018 5:32 PM" and ends at "Monday, October 15, 2018 5:33 PM"
Is the elapsed time = 1 minute?
Is the clock time = 1 minute?
You have agreed:
**"But conceptually it is the same: how long time did it take?". **
Lets keep the focus on SET STATISTICS TIME ON and leave clock time difference reported by datediff() aside.
Lets say we have a procedure that has multiple queries and takes 1 minute to execute. To view the time taken by each query to complete(elapsed time), we are NOT going to code datediff() after every query, we simply set SET STATISTICS TIME ON. It will report the CPU time and elapsed time of each query.
**As agreed by you elapsed time is **"how long time did it take?". So, elapsed time is the SUM UP of time taken by all operations performed. Do you agree?
There are only two type of operations performed, CPU operations and IO operations. Any other operations can you think of? The network operation is a subset of the IO operation.
Regards
Sharat
Tuesday, October 16, 2018 9:10 PM
SET STATISTICS TIME ON return times is ms (milliseconds) while datediff() can return differences in ns (nanoseconds).
But that is nothing you have use for when measuring time in SQL Server. The resolution is in practice 1 ms, not considering the drift that results in negatives time.
Why are we talking of a case where datediff() returns a negative value?*It will happen only in case when elapsed time = 0 ms. We are taking an example of a query that takes more than 0 ms elapsed time, say*1 minute.
Yeah, when execution time is in that range, these funny inaccuracies do not have to bother us.
There are only two type of operations **performed, **CPU**operations** and IO operations. Any other operations can you think of? The network operation is a subset of the IO operation.
I would disagree with the network operation being a subset of IO, but I would say that this is a class of its own, since this in a different direction. That is, one thing that can slow down query execution is that the client is very slow to consume the result set. Or because the network connection between client and server is slow.
Also, as already has been pointed out, there are waits due to blocking, waiting for CPU to execute etc. Yeah, you've been talking about a single-user system, but that is not particularly interesting. And even on a single-user system, your anti-virus may go ballistic and hi-jack about all CPU on the machine, causing SQL Server to run very slow. (Yes, I have seen this happen.)
Wednesday, October 17, 2018 3:50 AM
Look at it this way.
I am running a test. I have created a SELECT that returns 183 rows.
Test cases are:
1) Execute only SELECT.
2) Execute INSERT SELECT on a perm table.
3) Execute INSERT SELECT on #temp.
**4) Execute INSERT SELECT on @table.**
5) Execute INSERT SELECT on ##temp.
Capture CPU times of all the 5 test cases using SET STATISTICS TIME ON.
Test case 1 returns results to the client, so network is involved. But in test case 2,3,4,5 there are NO results being returned to the client. The CPU time in all the test cases should be the same as the SELECT is same. The CPU time is determined by SELECT, while the IO time is determined by what read or writes are taking place.
Read and writes can be described as:
1) Read or write to RAM.
2) Read or write to disk.
3) Read or write to network.
Do you Agree?
Wednesday, October 17, 2018 7:17 AM
There is also CPU time for the INSERT. How much depends on a lot of things. For instance, if the table has plenty of indexes there may be multiple sort operations. And that can also affect the SELECT part, because the optimizer may go for a plan that sorts the data to fit the clustered index of the target table on an earlier stage etc. And since the various target tables are logged different, obviously there is different CPU time to construct the log records etc.
In short: there is not really any point of trying to find such a formula, because it is a lot more complex.
Erland Sommarskog, SQL Server MVP, esquel@sommarskog.se
Wednesday, October 17, 2018 1:07 PM
Now we are focusing on SELECT vs INSERT-SELECT where the SELECT is the same.
I ran this query1 on my SQL Express 2017.
Set Statistics Time On
GO
Select COUNT(*) From View1
GOReturns183(1 row affected)SQL Server Execution Times:
CPU time = 11703 ms, elapsed time = 11701 ms
I ran another query2.
Set Statistics Time On
GO
If OBJECT_ID('Temp','U') Is Not Null
Drop Table Temp
GO
Create Table Temp
(
C Int
)
GO
Insert Temp
Select COUNT(*) From View1
GOReturn(1 row affected)SQL Server Execution Times:
CPU time = 30313 ms, elapsed time = 30346 ms.
Question is: Why CPU time in query1 = 11703ms = 11.703 seconds, where as in query2 CPU time = 30313ms = 30.313 seconds?
Agreed, that INSERT also takes CPU time. But we are writing only a single value = 183 (4 bytes) to table Temp. It should not take an extra 18 seconds extra to process just 4 bytes.
You mean to say that SQL takes 18 seconds to extra due to Transaction Log Processing for 4 bytes of data. THAT'S BAD NEWS.
Wednesday, October 17, 2018 1:45 PM
Hey Sharat,
It's TheRock here, sorry been busy recently, but just seen your post. Do you have the execution plans for these two queries?
And do you have the definition for View1 as this will help me understand what differences there might be.
Thanks
TR
Wednesday, October 17, 2018 2:00 PM
Erland has said: CPU time differences between SELECT and INSERT-SELECT are due to Transaction Log Processing. So where does execution plan come into picture. I have compared the execution plans of both the queries. In the execution plans there is no information about Transaction Log Processing and the CPU time taken by it.
There is no difference in execution plan except a "Table Insert" operator in the end. That makes sense, first build the result set from SELECT and then INSERT it into Temp. Result of SELECT is only 4 bytes of data. SQL is taking extra 18 seconds to INSERT 4 bytes of data into table Temp and that's happening due to an internal process called Transaction Log Processing. As a user I expect internal SQL processes like Transaction Log Processing to be quick. THAT's BAD NEWS.
Quick question: How many Transaction Log records have to written to Transaction Log if we are writing 4 bytes to a perm table?
Wednesday, October 17, 2018 2:10 PM
This should explain it.
Because the target table already exists, SQL Server has to read a page on the target table for every single row to establish where the row is going to be inserted to.
Try using
INSERT ... SELECT WITH (TABLOCK)
Enjoy
TR
Wednesday, October 17, 2018 2:26 PM
WOW with TABLOCK CPU time of INSERT-SELECT is same as CPU time of SELECT.
DOES that mean we have to SPECIFY TABLOCK every time we do an INSERT-SELECT to save CPU time. That's STRANGE.
WHY are CPU times in case of TABLOCK and NO TABLOCK different?
Wednesday, October 17, 2018 2:27 PM
There are no minimally logged operations in the FULL recovery model. As the ‘SELECT … INTO’ creates the destination table, it exclusively owns that table and is quicker compared to the ‘INSERT … SELECT’. Because the ‘INSERT … SELECT’ inserts data into an existing table, it is slower and requires more resources due to the higher number of logical reads and greater transaction log usage. However, providing the query hint to lock the entire destination table, the two statements perform exactly the same.
Wednesday, October 17, 2018 2:53 PM
Why should I use a query hint?
A quote from the Microsoft documentation:
Caution
Because the SQL Server query optimizer typically selects the best execution plan for a query, we recommend only using hints as a last resort for experienced developers and database administrators.
Link is:
https://docs.microsoft.com/en-us/sql/t-sql/queries/hints-transact-sql-query?view=sql-server-2017
Wednesday, October 17, 2018 3:01 PM
As more features have been added to SQL Server and queries became more and more complex on larger data sets, the optimizer is now so complex and has so many possible plans to investigate there’s no way it could always come up with the best plan. The goal now is to come up with a “good enough plan” without taking more time to optimize than the query will need for execution.<o:p></o:p>
This still rings true with your small dataset.<o:p></o:p>
Hints can be a solution if you haven’t been able to find any other way to get SQL Server’s optimizer to find an acceptable plan.<o:p></o:p>
Wednesday, October 17, 2018 3:47 PM
SQL is not able to come up with the best execution plan. Why? Its only 10 MB data to be read and 4 bytes to be written. Whats causing SQL to not come up with the best execution plan in this case? ITS BAD NEWS that SQL is NOT ABLE TO COME UP WITH best execution plan. There are BILLIONS of function and stored procedures around the world. And you are saying check each one to see whether SQL has come up with best execution plan or not. Creation of the execution plan is an internal process and the USER does not want to interfere with an internal process.
Wednesday, October 17, 2018 3:59 PM
What is the aim of your posts here? It is not a perfect situation, and there are many ways to achieve the same results. There are also many factors at play here, from the processing engine to the hardware etc that could impact on this performance. On top of that SQL does give you option to help with optimizing the plan it comes up with. The vast majority of the time the plan that it comes up with will be sufficient. Sometimes it requires expects to work with the tool to get the best out of it. This is case with the majority of Microsoft products.