Take the 2-minute tour ×
Database Administrators Stack Exchange is a question and answer site for database professionals who wish to improve their database skills and learn from others in the community. It's 100% free, no registration required.

I found this query by watching a test site with sql profiler for anything taking over 10 seconds. I plopped the code right out of sql profiler and into sql studio, where it was able to execute quickly. The slow "first run" behavior can be reset by using DBCC DROPCLEANBUFFERS.

Here's the slow query:

exec sp_executesql N'SELECT [t0].*
FROM [dbo].[MyTable] AS [t0]
WHERE [t0].[ParentID] IN (@p0, @p1, @p2, @p3, @p4, @p5, @p6, @p7, @p8, @p9, @p10, @p11, @p12, @p13, @p14, @p15, @p16, @p17, @p18, @p19, @p20, @p21, @p22, @p23, @p24, @p25, @p26, @p27, @p28, @p29, @p30, @p31, @p32, @p33, @p34, @p35, @p36, @p37, @p38, @p39, @p40, @p41, @p42, @p43, @p44, @p45, @p46, @p47, @p48, @p49, @p50, @p51, @p52, @p53, @p54, @p55, @p56, @p57, @p58, @p59, @p60, @p61, @p62, @p63, @p64, @p65, @p66, @p67, @p68, @p69, @p70, @p71, @p72, @p73, @p74)',N'@p0 int,@p1 int,@p2 int,@p3 int,@p4 int,@p5 int,@p6 int,@p7 int,@p8 int,@p9 int,@p10 int,@p11 int,@p12 int,@p13 int,@p14 int,@p15 int,@p16 int,@p17 int,@p18 int,@p19 int,@p20 int,@p21 int,@p22 int,@p23 int,@p24 int,@p25 int,@p26 int,@p27 int,@p28 int,@p29 int,@p30 int,@p31 int,@p32 int,@p33 int,@p34 int,@p35 int,@p36 int,@p37 int,@p38 int,@p39 int,@p40 int,@p41 int,@p42 int,@p43 int,@p44 int,@p45 int,@p46 int,@p47 int,@p48 int,@p49 int,@p50 int,@p51 int,@p52 int,@p53 int,@p54 int,@p55 int,@p56 int,@p57 int,@p58 int,@p59 int,@p60 int,@p61 int,@p62 int,@p63 int,@p64 int,@p65 int,@p66 int,@p67 int,@p68 int,@p69 int,@p70 int,@p71 int,@p72 int,@p73 int,@p74 int',@p0=121888,@p1=317624,@p2=278130,@p3=299426,@p4=128786,@p5=553917,@p6=169682,@p7=316993,@p8=319430,@p9=321347,@p10=377276,@p11=388570,@p12=233344,@p13=304376,@p14=318493,@p15=318190,@p16=144455,@p17=342559,@p18=309867,@p19=258251,@p20=139296,@p21=530970,@p22=288191,@p23=127107,@p24=547572,@p25=617531,@p26=238898,@p27=606923,@p28=267113,@p29=140833,@p30=122554,@p31=298846,@p32=562964,@p33=554626,@p34=414874,@p35=534996,@p36=614977,@p37=230423,@p38=261899,@p39=149666,@p40=179537,@p41=148420,@p42=262955,@p43=298094,@p44=575449,@p45=246861,@p46=572334,@p47=172152,@p48=529420,@p49=129074,@p50=266589,@p51=194619,@p52=376201,@p53=608389,@p54=162335,@p55=405965,@p56=125671,@p57=146195,@p58=538850,@p59=575254,@p60=129485,@p61=243677,@p62=615828,@p63=236197,@p64=343015,@p65=294449,@p66=562013,@p67=138933,@p68=614729,@p69=561779,@p70=-1,@p71=-1,@p72=-1,@p73=-1,@p74=-1

Here's the table definition, with indexes:

CREATE TABLE [dbo].[MyTable] (
[MyID] [int] IDENTITY (1, 1) NOT NULL ,
[GrandParentID] [int] NOT NULL ,
[ParentID] [int] NOT NULL ,
[Col1] [nvarchar] (200) COLLATE SQL_Latin1_General_CP1_CI_AS NOT NULL ,
[Col2] [nvarchar] (20) COLLATE SQL_Latin1_General_CP1_CI_AS NOT NULL ,
[Col3] [nvarchar] (200) COLLATE SQL_Latin1_General_CP1_CI_AS NOT NULL ,
[Col4] [nvarchar] (200) COLLATE SQL_Latin1_General_CP1_CI_AS NOT NULL ,
[Col5] [decimal](18, 2) NULL ,
[Col6] [char] (2) COLLATE SQL_Latin1_General_CP1_CI_AS NOT NULL ,
[Col7] [char] (4) COLLATE SQL_Latin1_General_CP1_CI_AS NOT NULL ,
[OtherKey] [int] NULL ,
[Col8] [nvarchar] (50) COLLATE SQL_Latin1_General_CP1_CI_AS NULL ,
[Col9] [datetime] NULL ,
[Col10] [nvarchar] (150) COLLATE SQL_Latin1_General_CP1_CI_AS NULL ,
 CONSTRAINT [PK__7E8439BE] PRIMARY KEY  CLUSTERED 
(
    [MyID]
)  ON [PRIMARY] 
) ON [PRIMARY]

CREATE  INDEX [MyTable_ParentID] ON [dbo].[MyTable]([ParentID]) WITH  FILLFACTOR = 90 ON [PRIMARY]
CREATE  INDEX [MyTable_OtherKey] ON [dbo].[MyTable]([OtherKey] DESC ) WITH  FILLFACTOR = 90 ON [PRIMARY]
CREATE  INDEX [MyTable_GrandParentID] ON [dbo].[MyTable]([GrandParentID]) ON [PRIMARY]

Here are the timings and IO:

-- Test site - first run:
(7064 row(s) affected)
Table 'MyTable'. Scan count 71, logical reads 49255, physical reads 3, read-ahead reads 13160, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
 SQL Server Execution Times:
   CPU time = 140 ms,  elapsed time = 30400 ms.

-- Test site - second run:
(7064 row(s) affected)
Table 'MyTable'. Scan count 71, logical reads 29054, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
 SQL Server Execution Times:
   CPU time = 78 ms,  elapsed time = 169 ms.

-- Production site - first run:
(7064 row(s) affected)
Table 'MyTable'. Scan count 71, logical reads 50513, physical reads 3, read-ahead reads 13157, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
 SQL Server Execution Times:
   CPU time = 62 ms,  elapsed time = 276 ms.

-- Production site - second run:
(7064 row(s) affected)
Table 'MyTable'. Scan count 71, logical reads 29054, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
 SQL Server Execution Times:
   CPU time = 63 ms,  elapsed time = 262 ms.

The test site and production site are setup the same way - database files are on a single virtual harddrive, which is backed by a many-disk load balancing SAN.

Execution plan:

constantscan -> sort -> nested loop -> index seek -> nested loop -> key lookup

share|improve this question
1  
Unfortunately that "Select t.*.." makes the use of a covering index useless. That way you might've got rid of those costly Key Lookups, which would be my first go to part. Are you using Entity Framework (or anything similar)? –  Marian Apr 16 '13 at 19:44
    
This is a LinqToSql compiled query. –  David B Apr 16 '13 at 20:02

3 Answers 3

The main impact on your query is due to the KEY LOOKUP which is has a cost of 77%. You can get rid of the key lookup by creating a covering index or included column index.

Covering Index will cover the query by including all the columns that are needed.

Included Index will allow you to include additional columns so that they are stored with the index but are not part of the index tree. This has an advantage of requiring less storage space (if you index is huge, in GB).

So if you create a non-clustered index on MyTable with included columns, it will eliminate the key lookup and there by improving the query performance.

Look at the Key Lookup property and see what columns are required.

for e.g. if the key lookup property shows MyID in the output list then below

CREATE NONCLUSTERED INDEX [MyTable_ParentID_included] ON [dbo].[MyTable]
(
       [ParentID] 
)
INCLUDE ([MyID])  ON [PRIMARY]
GO

some good explanation can be found Reducing Key Lookups

EDIT: Just noticed that you are using

SELECT [t0].*
FROM [dbo].[MyTable] AS [t0] .....

Does the application require all the columns from the base table ? this will negate the use of Included columns.

share|improve this answer
1  
While obviously useful for improving performance in general, the question was about why the query is slow on first run and fast on subsequent runs. Or at least that's how I read it. –  Aaron Bertrand Apr 16 '13 at 19:51
    
While a covering index would reduce the IO, it would cost dearly in space. I'm not prepared to recommend an 8G index at this time. My question is - why does the first run of the query work great in production, but poorly in test? –  David B Apr 16 '13 at 20:07
    
It depends on lots of factors which -- Aaron and Ali have mentioned. Is the server virtual, are all the config settings same on test and PROD, amount of RAM, sql server version and service pack same on test and PROD ? –  Kin Apr 16 '13 at 20:18

Well of course, the first time you run the query, it has to load it from disk, subsequently it uses memory, which is much faster than disk. If you clear the buffers, you essentially flush all of that data from memory, so next time you request the data, it has to load it from disk again. Think of disk vs. memory as turtle vs. hare. Outside of test scenarios, you want your queries generally to be running from a warm cache, and shouldn't be purposefully clearing out the buffer pool using DROPCLEANBUFFERS.

share|improve this answer
    
Yes, I am only using DROPCLEANBUFFERS to recreate the case of first query execution. Production site doesn't seem to care about first query execution. Any thoughts on that? –  David B Apr 16 '13 at 19:32
2  
I don't know what "doesn't seem to care" means. Are you saying in production it's always slow regardless or it's always fast? How much data is in production vs. test? How about memory, differences in I/O system, etc.? Have you compared execution plans in production vs. test? We're not very good mind readers. :-) –  Aaron Bertrand Apr 16 '13 at 19:34
1  
What I mean by I/O is not what you think, I guess. I mean is your test box a virtual machine with some iSCSI or DAS 7200 RPM slow disk with data/log/tempdb all sharing the same drive, and your production machine is using 15K SAS or SSD with data/log/tempdb appropriately distributed, making the I/O less significant? Comparing apples to apples is important, and when you're not, and you want input, you need to share all of the details. –  Aaron Bertrand Apr 16 '13 at 20:07
1  
Also, are you talking about an estimated execution plan or an actual execution plan? Toss out the estimated and take actuals for each of the four scenarios you've described. Preferably using Plan Explorer, which will include all kinds of useful runtime metrics you won't get from SSMS directly. If you eval the PRO version you'll even get wait stats for your session (so generate plans for each of the four scenarios in separate tabs). –  Aaron Bertrand Apr 16 '13 at 20:09
3  
@DavidB Do you realize that the difference must be the consequence of some difference between the two environments? Now regarding this difference even the best experts (including Aaron) can only guess, while you should be able to track it down. –  dezso Apr 18 '13 at 8:07

I'd love to hear some of the performance tuning experts but from what I can see with the presented info, the 13160 read ahead reads are loading it into memory. The 2nd time it reads it from memory and is much faster. Being a virtual system could mean shared IOPS and it might aggravate the situation as it loads it into cache. Once you clear the cache, it needs to read it from disk again.

If you could collect the wait stats for this, we would know if that is the right answer. I would expect perhaps 10 seconds of PAGELATCHIO to show up. Use this link to grab extended events for a single operation. Run the first query, get the extended events info, run it again without clearing memory, and get the extended events info and post. It should show disk io being the issue the first time.

share|improve this answer
    
Thanks for the link. Will try. –  David B Apr 16 '13 at 20:27

Your Answer

 
discard

By posting your answer, you agree to the privacy policy and terms of service.

Not the answer you're looking for? Browse other questions tagged or ask your own question.