HostWeb Forums » Microsoft Databases » microsoft.public.sqlserver.relationalserver.performance » Total_elaped time column appears inaccurate
Topic: Total_elaped time column appears inaccurate
I am using SQL 2005
So when i run the query below to list all my active requests and at the same
time have profiler running that filters on duration > 5 secs, I see some
sprocs show up in profiler that has a total_elapsed_time > 5000 in the query
below come up, but there are quite a few of those requests that show a high
total_elapsed_time even as high as 18 secs,etc. that do not make it in the
profiler. I am capturing all RPC:Completed and Batch: SqlCompleted in
there.. So why is not showing up ?
select * from sys.dm_exec_requests where session_id > 50
Also, i looked at start_time( from the DMV) and getdate() in the same query
as such..
select *,getdate() from sys.dm_exec_requests where session_id > 50
and here are the numbers:
Total_elapsed_time :11332
Start_time : 2008-01-04 12:05:42.003
Getdate() : 2008-01-04 12:05:43.660
As can be seen, its only a second difference between start_time and getdate,
but total_elapsed_time has it at 11 secs
Whats going on ?
Replies below ↓
Replies
Re: Total_elaped time column appears inaccurate
Check out this KB
http://support.microsoft.com/kb/931279
"Hassan" <hassan@test.com> wrote in message
news:OGb0s7ZUIHA.5160@TK2MSFTNGP05.phx.gbl...
>I am using SQL 2005
>
> So when i run the query below to list all my active requests and at the
> same
> time have profiler running that filters on duration > 5 secs, I see some
> sprocs show up in profiler that has a total_elapsed_time > 5000 in the
> query
> below come up, but there are quite a few of those requests that show a
> high
> total_elapsed_time even as high as 18 secs,etc. that do not make it in
> the
> profiler. I am capturing all RPC:Completed and Batch: SqlCompleted in
> there.. So why is not showing up ?
>
> select * from sys.dm_exec_requests where session_id > 50
> Also, i looked at start_time( from the DMV) and getdate() in the same
> query
> as such..
>
> select *,getdate() from sys.dm_exec_requests where session_id > 50
>
> and here are the numbers:
>
> Total_elapsed_time :11332
> Start_time : 2008-01-04 12:05:42.003
> Getdate() : 2008-01-04 12:05:43.660
>
> As can be seen, its only a second difference between start_time and
> getdate,
> but total_elapsed_time has it at 11 secs
>
> Whats going on ?
Re: Total_elaped time column appears inaccurate
Hassan (hassan@test.com) writes:
> So when i run the query below to list all my active requests and at the
> same time have profiler running that filters on duration > 5 secs, I see
> some sprocs show up in profiler that has a total_elapsed_time > 5000 in
> the query below come up, but there are quite a few of those requests
> that show a high total_elapsed_time even as high as 18 secs,etc. that
> do not make it in the profiler. I am capturing all RPC:Completed and
> Batch: SqlCompleted in there.. So why is not showing up ?
>
> select * from sys.dm_exec_requests where session_id > 50
> Also, i looked at start_time( from the DMV) and getdate() in the same
> query as such..
>
> select *,getdate() from sys.dm_exec_requests where session_id > 50
>
> and here are the numbers:
>
> Total_elapsed_time :11332
> Start_time : 2008-01-04 12:05:42.003
> Getdate() : 2008-01-04 12:05:43.660
>
> As can be seen, its only a second difference between start_time and
> getdate, but total_elapsed_time has it at 11 secs
A wild guess is that the query runs a parallel plan, and total_elapsed_time
is the total of all threads. At this late hour, I could not think of a
quick way to test that.
--
Erland Sommarskog, SQL Server MVP, esquel@sommarskog.se
Books Online for SQL Server 2005 at
http://www.microsoft.com/technet/prodtechnol/sql/2005/downloads/books.mspx
Books Online for SQL Server 2000 at
http://www.microsoft.com/sql/prodinfo/previousversions/books.mspx
Re: Total_elaped time column appears inaccurate
Erland, I can give you till tomorrow ;)
just a quick thought, anytime the sql goes through parallelism, i should see
a waittype of CXPacket, right ? and if so, i dont see that in the wait type.
But heres the thing, i have profiler running at the same time in parallel
filtering for calls > 5 secs and if the total elapsed time has reached 11
secs, it should up once its done in my trace, but it goesnt. Hence the
suspicion. And you would think that constantly running my query would show
that total elapsed time slowly increment.. but thats not the case.. eg:
first time i run the DMV, theres nothings and the next sec i run, theres the
11 sec session id in there..
Seems buggy... I dont see this behaviour on all servers.
Yes Jasons post is what we are aware of as well... Fun times...
"Erland Sommarskog" <esquel@sommarskog.se> wrote in message
news:Xns9A201BB18B63Yazorman@127.0.0.1...
> Hassan (hassan@test.com) writes:
>> So when i run the query below to list all my active requests and at the
>> same time have profiler running that filters on duration > 5 secs, I see
>> some sprocs show up in profiler that has a total_elapsed_time > 5000 in
>> the query below come up, but there are quite a few of those requests
>> that show a high total_elapsed_time even as high as 18 secs,etc. that
>> do not make it in the profiler. I am capturing all RPC:Completed and
>> Batch: SqlCompleted in there.. So why is not showing up ?
>>
>> select * from sys.dm_exec_requests where session_id > 50
>> Also, i looked at start_time( from the DMV) and getdate() in the same
>> query as such..
>>
>> select *,getdate() from sys.dm_exec_requests where session_id > 50
>>
>> and here are the numbers:
>>
>> Total_elapsed_time :11332
>> Start_time : 2008-01-04 12:05:42.003
>> Getdate() : 2008-01-04 12:05:43.660
>>
>> As can be seen, its only a second difference between start_time and
>> getdate, but total_elapsed_time has it at 11 secs
>
> A wild guess is that the query runs a parallel plan, and
> total_elapsed_time
> is the total of all threads. At this late hour, I could not think of a
> quick way to test that.
>
>
> --
> Erland Sommarskog, SQL Server MVP, esquel@sommarskog.se
>
> Books Online for SQL Server 2005 at
> http://www.microsoft.com/technet/prodtechnol/sql/2005/downloads/books.mspx
> Books Online for SQL Server 2000 at
> http://www.microsoft.com/sql/prodinfo/previousversions/books.mspx
Re: Total_elaped time column appears inaccurate
Hassan (hassan@test.com) writes:
> just a quick thought, anytime the sql goes through parallelism, i should
> see a waittype of CXPacket, right ? and if so, i dont see that in the
> wait type.
Yes, a CXPACKET is to be expected. Also, if you do
SELECT * FROM sys.dm_os_tasks WHERE session_id = 55
you should see more than one row, if there is parallelism.
> But heres the thing, i have profiler running at the same time in parallel
> filtering for calls > 5 secs and if the total elapsed time has reached 11
> secs, it should up once its done in my trace, but it goesnt.
Put per your difference between start_date and getdate(), 11 seconds
had not elapsed. If the DMV for some reason counts all threads, that
does not mean that the Profiler does the same.
> And you would think that constantly running my query would show that
> total elapsed time slowly increment.. but thats not the case.. eg: first
> time i run the DMV, theres nothings and the next sec i run, theres > the
> 11 sec session id in there..
So the request is running a batch which loops and runs the same thing
all over again?
Since I don't have a repro, I cannot really say that much more. But, yes,
it could be a bug.
--
Erland Sommarskog, SQL Server MVP, esquel@sommarskog.se
Books Online for SQL Server 2005 at
http://www.microsoft.com/technet/prodtechnol/sql/2005/downloads/books.mspx
Books Online for SQL Server 2000 at
http://www.microsoft.com/sql/prodinfo/previousversions/books.mspx