November 29, 2003 at 4:57 pm
I'm confused. I turned on statistics for time and IO. I then ran a reasonably simple query. I got the below. Taken on its own, it looks OK, but the strange thing is that query analyzer says it took 3 minutes 12 seconds (and that's about right in terms of how long I waited).
So why is the elapsed time below so much less?
Incidentally, there was no output other than the below, the query ran into a temp table, so there was no delay due to buffering a ton of output to the query analyzer screen.
It doesn't do it all the time, just occasionally. Maybe something to do with parallel execution, measuring the wrong thread?
SQL Server parse and compile time:
CPU time = 0 ms, elapsed time = 2 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
(278493 row(s) affected)
SQL Server Execution Times:
CPU time = 39922 ms, elapsed time = 44239 ms.
December 1, 2003 at 7:58 am
Perhaps the bulk of the 3 minutes occured after the query had processed the data, but it was still sending the data to the client over the network, and QA was translating it all to display as a grid?
December 1, 2003 at 8:00 am
Sorry should have read closer. You ran it into a temp table. Above wouldn't apply.
December 1, 2003 at 8:05 am
I assume that the exact same script/sp gives the intermittent result you showed above? If so could you post it? This one is really odd now that I read it closer. I've noticed some oddities with the graphical showplan myself but nothing I haven't been able to at least understand how I was confusing it.
December 1, 2003 at 8:48 am
Sample, sure. Here it is. I run the first 4 statements separately, then the rest are what I'm timing. I've attached the statistics run below. The query analyzer time which agrees with wall clock time was 3 minutes 2 seconds (versus 17 seconds total in the statistics).
The problem is 100% reproducible for this particular set of queries, but is not reproducible in general, most queries the wall time and statistics time agree.
dbcc freeproccache
dbcc dropcleanbuffers
set statistics io on
set statistics time on
declare @NinetyDays smalldatetime
set @NinetyDays=DateAdd(d,90,getdate())
-- #Overrides will store those customer/titles where overrides play a role in the future allotment
create table #Overrides (UnitCd char(3), CustCd int, TitleTK int,
NowBaseQty int, NowCurrStatusCd char(2), NowEndDt smalldatetime, NowOverrideTK int,
ThenBaseQty int, ThenCurrStatusCd char(2), ThenEndDt smalldatetime, ThenOverrideTK int,
UsedBaseQty int, UsedCurrStatusCd char(2), UsedEndDt smalldatetime, UsedOverrideTK int,
AvgSaleRtlAmt Decimal(9,2), ObsCountNbr int, StdDevDcNbr decimal(9,2), AvgSaleDcNbr Decimal(9,2),
CalculatedBaseQty int)
create clustered index oi on #Overrides (UnitCd, TitleTK, CustCd)
-- Pull out all the overrides both from now, and from 90 days hence
insert into #Overrides (UnitCd, CustCd, TitleTK, NowBaseQty, NowCurrStatusCd, NowEndDt, NowOverrideTK,
ThenBaseQty, ThenCurrStatusCd, ThenEndDt, ThenOverrideTK)
select IsNull(o1.UnitCd,o2.UnitCd) as UnitCd, IsNull(o1.CustCd,o2.CustCd) as CustCd, IsNUll(o1.TitleTK,o2.TitleTK) as TitleTK,
o1.BaseQty, o1.CurrStatusCd, o1.EndDt, o1.OverrideTK,
o2.BaseQty, o2.CurrStatusCd, o2.EndDt, o2.OverrideTk
from lift.dbo.fnOverrideView(default, default, default, default) o1
full join lift.dbo.fnOverrideView(@NinetyDays,default, default, default) o2 on o1.UnitCd=o2.UnitCd and o1.CustCd=o2.CustCd and o1.TitleTK=o2.TitleTK
inner join dw.dbo.Unit u on u.UnitCd=o1.UnitCd and u.UnitCd=o2.UnitCd
where u.ActiveFlg='Y'
order by UnitCd, TitleTK, CustCd
SQL Server parse and compile time:
CPU time = 0 ms, elapsed time = 14 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 1 ms.
SQL Server parse and compile time:
CPU time = 3 ms, elapsed time = 3 ms.
Table '#Overrides__________________________________________________________________________________________________________0000000110A8'. Scan count 1, logical reads 0, physical reads 0, read-ahead reads 0.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 1 ms.
(71160 row(s) affected)
Table '#Overrides__________________________________________________________________________________________________________0000000110A8'. Scan count 0, logical reads 183649, physical reads 0, read-ahead reads 0.
Table '#4FA7C8E8'. Scan count 1, logical reads 650, physical reads 0, read-ahead reads 650.
Table 'Unit'. Scan count 1, logical reads 1, physical reads 0, read-ahead reads 0.
Table '#15461D29'. Scan count 1, logical reads 2468, physical reads 0, read-ahead reads 1438.
SQL Server Execution Times:
CPU time = 13156 ms, elapsed time = 17302 ms.
December 1, 2003 at 12:30 pm
It's not because you are using a table function to get your results from? I think the statistics are missing from within that function - what it's timing is the insert-select from it.
I tried to set up a test because I think I ran into this one before, but can't find it or any other table valued function I have currently that is slow enough to show a disparity.
I custom coded a timer to get around it being off when it caused me problems- because I already have utility templates with timer/logging/printing code pre-set up. I wonder what a trace would show though...
December 1, 2003 at 12:47 pm
That may well be it (that it is a table function). That's one of the few places we have them, and this was the only one that I have been using that takes significant time.
And now that I look, the query plans for it are just plain wrong as well, it seems to ignore the function entirely.
December 1, 2003 at 2:37 pm
Does it show up more accurately in a trace, capturing CPU Duration and Disk IO? Perhaps filter by the SPID once you connect?
Viewing 8 posts - 1 through 7 (of 7 total)
You must be logged in to reply to this topic. Login to reply