Weird differences in duration after clearing caches

  • I'm doing some query optimization within a stored proc, and after a lot of reading on this forum & elsewhere, decided to use the following before I call my proc:

    checkpoint;

    go

    dbcc dropcleanbuffers;

    go

    dbcc freeproccache;

    go

    DBCC FREESYSTEMCACHE ('ALL') WITH MARK_IN_USE_FOR_REMOVAL;

    GO

    EXEC sp_recompile N'mySproc' -- not really necessary since I drop/create every time instead of ALTER

    GO

    EXEC mySproc param1, param2, ...

    I've read that CHECKPOINT runs async and so it's a good idea to wait a few seconds after running it. So I run each of the statements above individually with a second or two in between.

    However, I'm getting some strange duration results from the sproc call. It seems like after some time has elapsed between tests, the first run takes about 7 seconds longer than my "baseline". If I immediately run all the cache-clearing commands again (with pauses), then run the sproc again, the second run takes about 5 seconds over baseline. I run the clearing commands again, then the sproc again, and the third run is 2 seconds above baseline. After this, the subsequent calls all run at baseline. (Unless something causes it to reset to the longer time, such as some time elapsing.) It always seems to be the 3rd or 4th run where it begins running at a consistent value, which I'm calling the "baseline".

    I have AUTO_UPDATE_STATISTICS turned on. I keep thinking maybe SQL is creating/updating some stats with regard to my sproc, and this is causing the differences in duration? I can't think of any other reason. I had really hoped that the above cache-clearing commands would allow me to get consistent results when testing.

    Any thoughts? Thanks!

    Jordan

  • Clarification: This is on a test server where no other SQL is currently being run. (I checked sp_who and nobody is talking to it except me.)

    I guess it could be some other processes on the server taking up time, but it has enough CPU & disk that that seems unlikely, especially to cause such a drastic difference. Keep in mind that the sproc itself is poorly written, having several ISNULLs and CASE statements that I'm working to clean up. But I would still expect it to run the same each time after clearing caches. Are there additional cache-clearing commands I should know about?

  • just a basic double check....after clearing cache, the FIRST time a proc gets run, it's slower, as a new execution plan gets created, adn that takes time...but subsequent calls after that should be quick...

    you are not comparing the FIRST execution to how fast it ran pre-cache clearing,a re you?

    Lowell


    --help us help you! If you post a question, make sure you include a CREATE TABLE... statement and INSERT INTO... statement into that table to give the volunteers here representative data. with your description of the problem, we can provide a tested, verifiable solution to your question! asking the question the right way gets you a tested answer the fastest way possible!

  • Lowell (11/17/2010)


    just a basic double check....after clearing cache, the FIRST time a proc gets run, it's slower, as a new execution plan gets created, adn that takes time...but subsequent calls after that should be quick...

    you are not comparing the FIRST execution to how fast it ran pre-cache clearing,a re you?

    No, I am running all of the commands in my enclosed SQL, for each test, exactly as I described above. So, the sproc is getting recompiled every time. I do this because I want as consistent a result as I can possibly get for my testing.

  • Of some interest to your results may be that a Cold Buffer is not necessarily an unused buffer.

    See this article:

    http://blogs.msdn.com/b/psssql/archive/2009/03/17/sql-server-what-is-a-cold-dirty-or-clean-buffer.aspx

    In particular:

    SQL Server understands the time of last access to buffers and when appropriate takes this into account when handling the free buffer lists.

    Now, that's from the SQL Server Engineer's department, but I can't find any backup stating if it re-uses newish free buffers, or sets older buffers to cold. For all I know it means both.

    That's the only 'official' word I can seem to find about what a Cold Buffer Cache means. I don't know for sure about absolutely no reuse but everyone else seems to think that's what is expected when I google around for it.

    I personally don't know either way. Just bringing it up as food for thought, since you're getting variable times.

    In either case, using FREEPROCCACHE tests the recompile more than it tests DiskI/O access for non-cache'd data. It does mean you won't end up with a bad compile, but you'd be better off running a series of tests that you don't load data for, such as a call for each of 80 ID's in different areas of the index.

    I'd be curious to know if it's the execution, or the compilation, of the query that's variable in time on first run. It's possible your QA system is sharing SAN space with something that has variable access on another LUN but the same physical spindles, and is causing some variability due to physical head contention.

    Can you turn on SET STATISTICS TIME ON and see if the difference in time is in the parse and compile times, or in the execution times?


    - Craig Farrell

    Never stop learning, even if it hurts. Ego bruises are practically mandatory as you learn unless you've never risked enough to make a mistake.

    For better assistance in answering your questions[/url] | Forum Netiquette
    For index/tuning help, follow these directions.[/url] |Tally Tables[/url]

    Twitter: @AnyWayDBA

  • Sure, here ya go...

    SQL Server parse and compile time:

    CPU time = 0 ms, elapsed time = 264 ms.

    SQL Server Execution Times:

    CPU time = 0 ms, elapsed time = 0 ms.

    SQL Server Execution Times:

    CPU time = 0 ms, elapsed time = 8 ms.

    SQL Server Execution Times:

    CPU time = 500 ms, elapsed time = 542 ms.

    (69647 row(s) affected)

    SQL Server Execution Times:

    CPU time = 0 ms, elapsed time = 0 ms.

    SQL Server parse and compile time:

    CPU time = 0 ms, elapsed time = 2 ms.

    SQL Server Execution Times:

    CPU time = 140 ms, elapsed time = 135 ms.

    SQL Server Execution Times:

    CPU time = 140 ms, elapsed time = 137 ms.

    (69137 row(s) affected)

    SQL Server Execution Times:

    CPU time = 6188 ms, elapsed time = 5484 ms.

    SQL Server Execution Times:

    CPU time = 7470 ms, elapsed time = 7729 ms.

  • I've also seen the following command mentioned somewhere on SSC:

    DBCC TRACEON(652)

    ...which is supposed to turn off read-aheads. I haven't tried it yet, but I wonder if this would make a difference in what I'm experiencing.

  • Sorry, stayed home sick today, just catching up with SSC. So your primary costs are definately in the executables. Hm, I'd definately look into the drive builds. See if you're bunking with someone else in the SAN.


    - Craig Farrell

    Never stop learning, even if it hurts. Ego bruises are practically mandatory as you learn unless you've never risked enough to make a mistake.

    For better assistance in answering your questions[/url] | Forum Netiquette
    For index/tuning help, follow these directions.[/url] |Tally Tables[/url]

    Twitter: @AnyWayDBA

Viewing 8 posts - 1 through 8 (of 8 total)

You must be logged in to reply to this topic. Login to reply