First run of a query takes much longer

Question

Post reply

First run of a query takes much longer

glu-1149094

SSC Journeyman

Points: 80
More actions
August 26, 2009 at 2:36 pm

#213868

I have a query of about 6000 character long, and join 9 tables. When I ran it first time, it took about 15 seconds, and return 656 rows. I ran it again and this time it took 6 seconds. All successive runs take 6 seconds, unless I do some operation like drop and create indexes. I collected statistics by set statistics io and time and also monitored with profiler. I observed the followings
1st run 2nd run
1) Physical reads, <100 0
2) Read ahead ~4000 ~2000
3) CPU time 5719 ms 5593 ms
4) CPU time from profiler
12344 ms 5593 ms
5) Observed elapsed 16 s 6 s
6) elapsed in stats 8059 ms 6542 ms
6)profiler duration 14828 ms 6541 ms
7) parse/compile 0 ms 0 ms
To summarize, compile took no time in both case,logical reads is the same, physical/ahead reads differ by ~2000, not very large. Times collected by SET TIME ON are similar in the two case. Profiler and the user observed 8-10 seconds more in 1st case.
Can someone tell me what SQL Server spends this 8 seconds on?
Thanks.

Viewing 14 posts - 1 through 13 (of 13 total)

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

Lynn Pettis SSC Guru Points: 442467 More actions · Answer 1

First run of the query had to actually access the data from disk. The second time the data has been cached.

glu-1149094 SSC Journeyman Points: 80 More actions · Answer 2

Thank you for the reply but it may not apply to the scenario. Accessing disk for data means physical reads. I listed physical reads in the two cases, the first run only had 100 physical reads. I do not think that will cost 10 seconds. Besides, the stats collected clearly indicates that elapsed time is 8059 ms, why it actualy took 16 seconds.

Lynn Pettis SSC Guru Points: 442467 More actions · Answer 3

Your right, the disk access alone won't answer that entirely, but it is a significant part of the difference. The other part is the time it takes to deliver the result set across the network to your desktop system. The other applications that may be running on your desktop, as well as other activity occuring on the server as well.

glu-1149094 SSC Journeyman Points: 80 More actions · Answer 4

This is the same query of different executions, and return the same numebr of rows, thus network load is the same. This scenario has been repeated many times and the first run alwasy take twice long time. Besides, I have run the queries dozens and dozens times. All runs after the first took 5-6 seconds. Thus cannot attribute to that other database operations as other operations will also slow down the runs after the first run. This is however never observed.

Lynn Pettis SSC Guru Points: 442467 More actions · Answer 5

Lynn Pettis

SSC Guru

Points: 442467

August 26, 2009 at 4:13 pm

#1045236

And I will say it again. CACHING!

Amit Singh Ten Centuries Points: 1295 More actions · Answer 6

i second that ... caching

-------------------------------------------------
-Amit
Give a man a fish and he'll ask for a lemon. Teach a man to fish and he wont get paged on weekends !! :w00t: - desparately trying to fish [/size]

Lynn Pettis SSC Guru Points: 442467 More actions · Answer 7

If this is a test/development server, try the following before each run of your query:

dbcc dropcleanbuffers

dbcc freeproccache

What are your results then?

SQLRNNR SSC Guru Points: 281334 More actions · Answer 8

Caching is what is causing your difference between first and subsequent runs.

First run has to build the actual execution plan and cache it, plus what Lynn said about the physical reads. Subsequent runs are going to be retrieved from cache.

Jason...AKA CirqueDeSQLeil
_______________________________________________
I have given a name to my pain...MCM SQL Server, MVP
SQL RNNR
Posting Performance Based Questions - Gail Shaw[/url]
Learn Extended Events

glu-1149094 SSC Journeyman Points: 80 More actions · Answer 9

Lynn is right. After I run

DBCC DROPCLEANBUFFERS

DBCC FREEPROCCACHE

the query took 32 seconds, the next run 6 seconds. execution plan takes 1 seconds, recompile takes 6 sec.

What puzzles me is that, take one table as example, display of SET STATISTICS IO ON shows "logical reads 62832, physical reads 55, read-ahead reads 1190" in the case of clear cache. By definition, I expect physical+read-ahead reads =logical reads. Is the stats displayed with SET STATISTICS IO wrong or I have a misunderstanding here.

Now what I should do to improve it. the memory set for the server is 0 to 2,147,483,647 MB. I guess that means all of my server memory.

Any suggestions.

Thanks

Lynn Pettis SSC Guru Points: 442467 More actions · Answer 10

If you need help with performance tuning a query, please read the second article in my signature block regarding "tips to get better help with Performance Problems." Following the instructions in that article regarding what to post and how. Once you do that, there are people here on SSC that will be more than happy to help you out. Based simply on the posts so far, there really isn't anything we can do to help, we can't see what you see from here.

Jeff Moden SSC Guru Points: 1004410 More actions · Answer 11

glu (8/26/2009)
Lynn is right. After I run
DBCC DROPCLEANBUFFERS
DBCC FREEPROCCACHE
the query took 32 seconds, the next run 6 seconds. execution plan takes 1 seconds, recompile takes 6 sec.
What puzzles me is that, take one table as example, display of SET STATISTICS IO ON shows "logical reads 62832, physical reads 55, read-ahead reads 1190" in the case of clear cache. By definition, I expect physical+read-ahead reads =logical reads. Is the stats displayed with SET STATISTICS IO wrong or I have a misunderstanding here.
Now what I should do to improve it. the memory set for the server is 0 to 2,147,483,647 MB. I guess that means all of my server memory.
Any suggestions.
Thanks

Again, Lynn is correct. Tuning a query requires being able to see the query, know the structure of the tables and any indexes that may be on the query. Of course, you don't want to post a 6000 line query but... you could attach it along with the other information that the article at the link Lynn referred you to tells you to provide.

--Jeff Moden

RBAR is pronounced "ree-bar" and is a "Modenism" for Row-By-Agonizing-Row.
First step towards the paradigm shift of writing Set Based code:
________Stop thinking about what you want to do to a ROW... think, instead, of what you want to do to a COLUMN.

Change is inevitable... Change for the better is not.

Helpful Links:
How to post code problems
How to Post Performance Problems
Create a Tally Function (fnTally)

Gail Shaw SSC Guru Points: 1004504 More actions · Answer 12

glu (8/26/2009)
What puzzles me is that, take one table as example, display of SET STATISTICS IO ON shows "logical reads 62832, physical reads 55, read-ahead reads 1190" in the case of clear cache. By definition, I expect physical+read-ahead reads =logical reads. Is the stats displayed with SET STATISTICS IO wrong or I have a misunderstanding here.

Imagine a situation where there's a table with 100 pages. As part of the query's execution (maybe inner table of a nested loop or key lookup) the query processor reads those 100 pages 200 times. That'll give you 200000 logical reads, 100 physical reads. It gets read from disk once, then read from memory multiple times.

I've also seen a case where logical reads < physical + read_ahead. That in the case where the pages picked up by the read-ahead weren't actually needed.

Stats IO can be wrong when there are UDFs involved, but it's wrong low, not wrong high.

Gail Shaw
Microsoft Certified Master: SQL Server, MVP, M.Sc (Comp Sci)
SQL In The Wild: Discussions on DB performance with occasional diversions into recoverability

We walk in the dark places no others will enter
We stand on the bridge and no one may pass

Gail Shaw SSC Guru Points: 1004504 More actions · Answer 13

glu (8/26/2009)
This is the same query of different executions, and return the same numebr of rows, thus network load is the same. This scenario has been repeated many times and the first run alwasy take twice long time. Besides, I have run the queries dozens and dozens times. All runs after the first took 5-6 seconds. Thus cannot attribute to that other database operations as other operations will also slow down the runs after the first run.

Data caching, execution plan caching.

Gail Shaw
Microsoft Certified Master: SQL Server, MVP, M.Sc (Comp Sci)
SQL In The Wild: Discussions on DB performance with occasional diversions into recoverability

We walk in the dark places no others will enter
We stand on the bridge and no one may pass