Re: Periodic spike on stored procedure execution time

Tech-Archive recommends: Repair Windows Errors & Optimize Windows Performance

A further trace on it, it was the SP:CacheRemove event causing the
spike.
In the trace, among the 200 execution (200 cahce remove), there're 5
of the remove takes longer than usual.
Does anyone what could have contribute to this long cache remove?

Peter C.

On Oct 19, 2:57 pm, "wodoy.peter" <wodoy.pe...@xxxxxxxxx> wrote:
I run the following code with profiler:
===================
declare @counter int
set @counter = 0
while @counter < 200
begin
        DBCC DROPCLEANBUFFERS
        DBCC FREEPROCCACHE
        select current_timestamp
        exec dbo.myStoredProcName
        select current_timestamp
        WAITFOR DELAY '000:00:02'

        set @counter = @counter + 1
end
===================

Counter used:
- SP:CahceInsert
- SP:CahceRemove
- SP:Recompile
- AutoStats

There's no recompile and auto stats logged in the trace.
For every stored proc execution, there's one CacheInset and
CacheRemove, this is due to the "DBCC DROPCLEANBUFFERS" and "DBCC
FREEPROCCACHE".
The result remain the same with periodic spike.

I then run it without the "DBCC DROPCLEANBUFFERS" and "DBCC
FREEPROCCACHE", the trace shows nothing, nothing is logged.

This spike seems to occur when a new query plan is generated, but
somehow, not everytime of query plan generation going to cause this
spike.
Is there any way to trace how long it takes to generate query plan and
what happen within it?

I also run the same trace again with the counter Showplan XML
Statistics Profile, the result is the same for every execution.

Peter C.

On Oct 17, 6:16 pm, Erland Sommarskog <esq...@xxxxxxxxxxxxx> wrote:

Dan Guzman (guzma...@xxxxxxxxxxxxxxxxxxxxxxxxxxx) writes:
I suggest you peruse Erland's article on dynamic search techniques
(http://www.sommarskog.se/dyn-search-2005.html).  I expect you will gain
some *significant* performance improvements and more stable execution
plans by using some of the methods suggested in the article.

Given the code, the executions that Wodoy posted are amazingly good. But
I guess execution times depends a lot on the input parameters.

After the first shock, the code is not that bad. InventTable.DataAreaID
seems to be a mandatory parameter, and if there is a clustered index
here, that's a good start. Then there are all these:

   and (@RangeJoinHistory = 0 or exists (
        select top 1 1 from TOPS_CustSalesHistory
        where   TOPS_CustSalesHistory.DataAreaID                = @DataAreaID
        and             TOPS_CustSalesHistory.CustAccount       = @CustAccount
        and             TOPS_CustSalesHistory.ItemID    = InventTable.ItemID
   ))

The plan should include startup filters, so as long as the input parameter
is 0, the subquery will never be executed.

But "TOP 1 1" should be changed to a simple * for legibility.

Can you elaborate a bit more on your test methodology?  If there is no
other activity on the server and you running the proc with the same
parameters in a T-SQL WHILE loop.  I would expect a stable plan unless
stats are updated. If this is a parallel plan, it could be that a
different number of processors is used for some of the queries.  A trace
can show that.

My guess is that the sort required for the row_number() requires some
tempdb space, and that causes the spikes.

I think a good start is to run a trace with all SP: events +
SQL:StmtRecompile and watch for recompiles, and cache removes and
cache inserts. It can also be a good idea to include all error events
to see if there are any sort warnings.

In a second step, may also be an idea to add Showplan XML Statistics,
to see if there are any differences between the executions. However,
adding this event to the trace may have a direct impact on the execution
times itself.

--
Erland Sommarskog, SQL Server MVP, esq...@xxxxxxxxxxxxx

Links for SQL Server Books Online:
SQL 2008:http://msdn.microsoft.com/en-us/sqlserver/cc514207.aspx
SQL 2005:http://msdn.microsoft.com/en-us/sqlserver/bb895970.aspx
SQL 2000:http://www.microsoft.com/sql/prodinfo/previousversions/books.mspx

.

Relevant Pages

  • Re: Periodic spike on stored procedure execution time
    ... In the trace, among the 200 execution, there're 5 ... Does anyone what could have contribute to this long cache remove? ... not everytime of query plan generation going to cause this ...
    (microsoft.public.sqlserver.server)
  • Re: "Resultcache" effect in 10.2.0.4 ??
    ... 'slow', say, 15 minutes or alike, and the second execution is 5 times ... SQL caching does not explain it ... or even if the subquery is altered in a small way (example, ... get the trace 10046 from a small but reproductible example ...
    (comp.databases.oracle.server)
  • Re: Kernel Mode vs. User Mode
    ... Please let me know if I'm wrong, but if I can't trace through ... the "trap-code" (which I presume is the boundary between kernel and user ... CALL instruction, unwind the EIP and continue, etc. ... >> I'm thinking of other ways to trace the execution of a program. ...
    (microsoft.public.win32.programmer.kernel)
  • Re: Tracking (logging) user commands
    ... commands. ... you don't want to track and log user execution. ... specific program "trace", the invocation of which needs to be logged ... you enable capture command line arguments, ...
    (comp.unix.solaris)
  • Re: cache and smls
    ... >"the Pentium 4 processor includes an Execution Trace Cache that stores ... >up to 12-K decoded micro-ops in the order of program execution. ... >increases performance by removing the decoder from the main execution ... trace cache holds small "traces of execution". ...
    (comp.lang.functional)