May 11, 2009 at 12:30 am
Hi all.
I want to get the average response time of a query without using profiler or traces. The obvious way to do it was to fetch the value of total_elapsed_time / execution_count from sys.dm_exec_query_stats. However its returning incorrect results in some scenarios. Consider these two queries:
select count(1) from TPCH.customer
select count(1) from TPCH.customer waitfor delay '00:00:10'
The first query runs for less than a second and its reported elapsed time is correct in sys.dm_exec_query_stats. However the second query takes about 10 seconds to execute (because of the delay) but its elapsed time is still less than 1 second in the view sys.dm_exec_query_stats. It seems the view is not considering the waitfor statement at all (though its creating a separate sql_handle for both statements (with the same query_hash in sql server 2008)). This may be an intended feature but I need the actual response time of the query (the time it took for the query to complete which is 10 seconds). How can I get it? Is there any other DMV (sys.dm_exec_sessions for example??.), query plan or any other resource in SQL Server 2005 and 2008 from which I can get/compute the response time of such queries?
I can't possibly get it from sys.dm_exec_requests though because its data is too shortlived.
Thanks for your help.
Regards
Nabeel Mukhtar
May 11, 2009 at 6:51 am
The issue is, the waitfor is not a part of the procedure itself. So the procs ran in the time reported. It sounds like you're trying to get client side response time. That's not doable from within SQL Server.
If you ran those procs within a wrapper proc so that it was measured independently, you'd see the full time of execution of both procs plus the wait time you forced on it.
"The credit belongs to the man who is actually in the arena, whose face is marred by dust and sweat and blood"
- Theodore Roosevelt
Author of:
SQL Server Execution Plans
SQL Server Query Performance Tuning
May 11, 2009 at 7:10 am
Here's the measurement harness that I have been using lately:
Declare @cpu_ int, @lreads_ int, @eMsec_ int
Select @cpu_ = cpu_time
, @lreads_ = logical_reads
, @eMsec_ = total_elapsed_time
From sys.dm_exec_requests
Where session_id = @@spid
--======
-- Test Code Goes Here
--======
Select cpu_time-@cpu_ as CpuMs
, logical_reads- @lreads_ as LogRds
, total_elapsed_time - @eMsec_ as Elapsed
From sys.dm_exec_requests
Where session_id = @@spid
It returns the same information as SET STATISTICS IO does, but in-proc as data that I can store. Also it's measurement can span any number of statements (unlike SET STATISTICS IO which are always single statement) making it easy to measure procs, routines and multi-statement examples like yours.
When I tested your examples (modified to use a generic table) like this:
Declare @cpu_ int, @lreads_ int, @eMsec_ int
Select @cpu_ = cpu_time
, @lreads_ = logical_reads
, @eMsec_ = total_elapsed_time
From sys.dm_exec_requests
Where session_id = @@spid
--======
select count(1) from sys.columns
--======
Select cpu_time-@cpu_ as CpuMs
, logical_reads- @lreads_ as LogRds
, total_elapsed_time - @eMsec_ as Elapsed
From sys.dm_exec_requests
Where session_id = @@spid
go
--====================================
Declare @cpu_ int, @lreads_ int, @eMsec_ int
Select @cpu_ = cpu_time
, @lreads_ = logical_reads
, @eMsec_ = total_elapsed_time
From sys.dm_exec_requests
Where session_id = @@spid
--======
select count(1) from sys.columns waitfor delay '00:00:05'
--======
Select cpu_time-@cpu_ as CpuMs
, logical_reads- @lreads_ as LogRds
, total_elapsed_time - @eMsec_ as Elapsed
From sys.dm_exec_requests
Where session_id = @@spid
here were the results:
-----------
431
CpuMs LogRds Elapsed
----------- -------------------- -----------
0 5 1
-----------
431
CpuMs LogRds Elapsed
----------- -------------------- -----------
0 5 5002
[font="Times New Roman"]-- RBarryYoung[/font], [font="Times New Roman"] (302)375-0451[/font] blog: MovingSQL.com, Twitter: @RBarryYoung[font="Arial Black"]
Proactive Performance Solutions, Inc. [/font][font="Verdana"] "Performance is our middle name."[/font]
May 11, 2009 at 8:12 am
You're really only getting times from cache and for small queries it's likely to be pointless, I understand the principle but do you really expect to have multiples of exactly the same query hitting your database where you think an average response time will be of any value?
My experience over the years has shown that quite often fluctuations in query times are not actually down to the query as such, waits, blocking, client connections, applications issues, storage latency, load and so on will all often have a part to play. It comes back to the support Q & A scenario User " Query Runs Slow " DBA " well it runs fine for me!"
If you're only testing then why make life difficult? why not make use of a minimal profiler trace?
[font="Comic Sans MS"]The GrumpyOldDBA[/font]
www.grumpyolddba.co.uk
http://sqlblogcasts.com/blogs/grumpyolddba/
May 11, 2009 at 10:43 am
Grant
The problem is that waitfor is shown as a part of the query when i get the query text from the sql_handle. And as I mentioned there are separate sql_handles for both the statements (with and without waitfor). So I think the elapsed time should also have been different.
As RBarryYoung mentions in his test harness, that the elapsed time is indeed different in sys.dm_exec_requests view, so it seems doable in SQL Server. The only problem is that data in sys.dm_exec_requests view is too short lived and I can't possibly sample it for every long running query that runs on the server. I need to get it from a more permanent source. It seems its not possible to get it from sys.dm_exec_query_stats.
Colin
I actually need to sample the average response time of long running queries by monitoring the server and I can't use traces or profiler because it needs to be agentless monitoring and no server/database modification is permitted.
I also need the find out the average resopnse time for a session (i.e. for queries executed by the session).
I wonder if the total_elapsed_time field of sys.dm_exec_sessions would be of any use here.
The Books Online define this total_elapsed_time as "Time, in milliseconds, since the session was established". So this should be the time since the login_time of the session. However its not returning that time on my SQL Server 2005 and 2008. It seems to be returning the accumulated total_elapsed_time of the queries that were executed by the session. Is this behaviour/observation correct?
If so what does total_scheduled_time in sys.dm_exec_sessions return?
For my example above the total_elapsed_time of sys.dm_exec_sessions does infact get incremented by 10 more seconds because of the waitfor delay statement.
Any ideas?
Thanks for all your responses.
Nabeel Mukhtar
May 13, 2009 at 6:36 am
Just found out that both sys.dm_exec_sessions and sys.dm_exec_requests return incorrect total_elapsed_time for parallel queries (requests with parallel execution plans). Is this a defect or a misunderstanding on my part?
So it seems I cannot get the correct response time of a query/request if it contains a waitfor statement.
Or are there any alternatives?
Thanks for all your responses.
Nabeel Mukhtar
May 13, 2009 at 7:34 am
nabeelmukhtar (5/13/2009)
Just found out that both sys.dm_exec_sessions and sys.dm_exec_requests return incorrect total_elapsed_time for parallel queries (requests with parallel execution plans). Is this a defect or a misunderstanding on my part?So it seems I cannot get the correct response time of a query/request if it contains a waitfor statement.
Or are there any alternatives?
Thanks for all your responses.
Nabeel Mukhtar
Do you have something that demonstrates this or a reference that I can follow-up on? I ask because this is very important to some of the work that I am currently doing and I had not yet heard anything about paralellism invaliding my numbers. thnx.
[font="Times New Roman"]-- RBarryYoung[/font], [font="Times New Roman"] (302)375-0451[/font] blog: MovingSQL.com, Twitter: @RBarryYoung[font="Arial Black"]
Proactive Performance Solutions, Inc. [/font][font="Verdana"] "Performance is our middle name."[/font]
May 13, 2009 at 12:13 pm
Basically what I mean is that for parallel queries the total_elapsed_time will not be the time taken by the query to complete its execution (or its response time). Its actually equal to the cpu time + wait time. And if multiple cpus are involved then the cpu time will also be multiplied and total_elapsed_time may be much greater than time time taken by the query to execute.
Surpsisingly its true only for sys.dm_exec_requests and sys.dm_exec_sessions and not for sys.dm_exec_query_stats.
You can test it by running a query that is parallelized on a machine with multiple cpus. As example of such query (with schema) can be found here..
http://www.sqlworkshops.com/dm_exec_query_stats.htm
A related discussion is on a different forum here.
Hope that helps.
Regards
Nabeel Mukhtar
May 13, 2009 at 12:40 pm
using profiler remotely is no difference to running remote queries, both require a user connection to the database.
I'm not particularly aware that the dmvs always keep everything - certain events can also clear the dmvs - a minimal profiler trace would do what you require, in fact that's what I've always done, I usually put the profiler data into a table and aggegate the results - works fine.
Failing that you could try something like SQL Diagnostic Manager.
[font="Comic Sans MS"]The GrumpyOldDBA[/font]
www.grumpyolddba.co.uk
http://sqlblogcasts.com/blogs/grumpyolddba/
May 13, 2009 at 1:40 pm
"SQL profiler trace" gets my vote!
* Noel
May 13, 2009 at 11:34 pm
RBarryYoung (5/13/2009)
nabeelmukhtar (5/13/2009)
Just found out that both sys.dm_exec_sessions and sys.dm_exec_requests return incorrect total_elapsed_time for parallel queries (requests with parallel execution plans). Is this a defect or a misunderstanding on my part?So it seems I cannot get the correct response time of a query/request if it contains a waitfor statement.
Or are there any alternatives?
Just found out that both sys.dm_exec_sessions and sys.dm_exec_requests return incorrect total_elapsed_time for parallel queries (requests with parallel execution plans). Is this a defect or a misunderstanding on my part?So it seems I cannot get the correct response time of a query/request if it contains a waitfor statement.
Or are there any alternatives?
Thanks for all your responses.
Nabeel Mukhtar
Do you have something that demonstrates this or a reference that I can follow-up on? I ask because this is very important to some of the work that I am currently doing and I had not yet heard anything about paralellism invaliding my numbers. thnx.
Nabeel:
Thanks for this information. Although some of these sites mis present some of the facts, your point is correct: both sys.dm_exec_sessions and sys.dm_exec_requests misrepresent elapsed time for parallel executions (cpu time is correct, however).
Fortunately, there is a simple solution for in-request measurements (which I prefer anyway), simply measure the elapsed time yourself. Here is what I am currently using:
Declare @cpu_ int, @lreads_ int, @tim_ datetime
Select @cpu_ = cpu_time
, @lreads_ = logical_reads
--, @eMsec_ = total_elapsed_timethis is inaccurate for parallel plans
, @tim_ = getdate()-- use this instead
From sys.dm_exec_requests
Where session_id = @@spid
--======
-- Test Code Goes Here
waitfor delay '00:00:10'
--======
Select cpu_time-@cpu_ as CpuMs
, logical_reads- @lreads_ as LogRds
, datediff(ms, @tim_, getdate()) as Elapsed
From sys.dm_exec_requests
Where session_id = @@spid
[font="Times New Roman"]-- RBarryYoung[/font], [font="Times New Roman"] (302)375-0451[/font] blog: MovingSQL.com, Twitter: @RBarryYoung[font="Arial Black"]
Proactive Performance Solutions, Inc. [/font][font="Verdana"] "Performance is our middle name."[/font]
May 13, 2009 at 11:38 pm
If you want to capture this out-of-request, thought, Trace/Profile is about the only accurate option.
[font="Times New Roman"]-- RBarryYoung[/font], [font="Times New Roman"] (302)375-0451[/font] blog: MovingSQL.com, Twitter: @RBarryYoung[font="Arial Black"]
Proactive Performance Solutions, Inc. [/font][font="Verdana"] "Performance is our middle name."[/font]
Viewing 12 posts - 1 through 11 (of 11 total)
You must be logged in to reply to this topic. Login to reply