How to find the cause for the speed discrepancy? | SQL Server Performance Forums

SQL Server Performance Forum – Threads Archive

How to find the cause for the speed discrepancy?

It takes 14 minutes to execute this statement right after I start the SQL Server: update table1 set column2 = table2.column2
from table1, table2 where table1.crefid = table2.cid If I execute the same statement again right away, it only takes 25 seconds. If I restart the SQL Server and run the same statement, it will take 14 minutes the 1st time and then only 25 seconds. How can I find out why the 1st time takes 14 minutes and then it only takes 25 seconds? I guess this is something related to cache but I don’t know how to check this.
Thank you for any help.
Well the thing is that may be Query Optimizer is taking lot of time to generate the plan and may be there is lot of data involved in this query so the time to fetch the data is too large. The second time you run the query, the data pages may already be present in the cache. Try this out… See how many physical and logical IO’s are needed when you run the query for the first time and also monitor the disk counters like disk queue length and read/sec during that time. Just a shot in the dark…. updating statistics may also help. Gaurav
Moderator
Man thrives, oddly enough, only in the presence of a challenging environment- L. Ron Hubbard

The views expressed here are those of the author and no one else. There are no warranties as to the reliability or accuracy of anything presented here.
Hi gaurav_bindlish, Yes, it is a lot of data. Table1 has 5 million records and table2 has 5000 records. I guess I need to use Performance Monitor, another tool I have not used before.

You can try something a little easier first. In Query Analyzer, run this query both times and around the statement put SET STATISTICS IO ON query SET STATISTICS IO OFF See what the counts are there and let us know. MeanOldDBA
[email protected] When life gives you a lemon, fire the DBA.
derrickleggett, I use SQL Query Analyzer and check Set Statistics IO connection property. 1st run: 00:03:49
Table ‘table1’ Scan count 1, logical reads 1407601, physical reads 0, read-ahead reads 0
Table ‘table2’ Scan count 1, logical reads 2. physical reads 0, read-ahead reads 0 1343488 row(s) affected 2nd run: 00:00:19
Table ‘table1’ Scan count 1, logical reads 1407601, physical reads 0, read-ahead reads 0
Table ‘table2’ Scan count 1, logical reads 2. physical reads 0, read-ahead reads 0 1343488 row(s) affected So, they are identical except one takes 3:49 and the other takes only 00:19.
You do have an index on table1.crefid correct? When you look at the execution plan, do you see any table scans? MeanOldDBA
[email protected] When life gives you a lemon, fire the DBA.
First thing is that there is lot of data being affected by this query. 140,000 * 8K = 1.1 GB is lot of data read from the system. If all the reads are random, and you are reading @ 60 Mbps, you would take around this much time. So as Derrick suggested, you should have indexes on table1.crefid and table2.cid However what is intersting is the first run of the query did not have any more physical reads than the second one and all the reads were logical. If SQL Server was just started, all these reads should have been physical and logical. Are you sure you are not missing anything? Gaurav
Moderator
Man thrives, oddly enough, only in the presence of a challenging environment- L. Ron Hubbard

The views expressed here are those of the author and no one else. There are no warranties as to the reliability or accuracy of anything presented here.
It sounds like a compile issue, doesn’t it? I would be interested to see a Profiler on the recompiles. MeanOldDBA
[email protected] When life gives you a lemon, fire the DBA.
I would be surprised if compilation took 14 minutes. It would be interesting to know what pcsql has to tell about that. Gaurav
Moderator
Man thrives, oddly enough, only in the presence of a challenging environment- L. Ron Hubbard

The views expressed here are those of the author and no one else. There are no warranties as to the reliability or accuracy of anything presented here.
gaurav_bindlish, It is 1407601 reads so I guess it is about 1407601 * 8k = 11GB of data. Well, I think I notice is that when I restart the SQL Server, sqlsvr.exe will consume more than 600MB of ram right away. Is that possible that SQL Server is retaining all the cache from previous time? If yes, I guess this explains why no physical reads. But I still don’t understand why the 2nd read will have logical reads = 2. When I look at sqlsvr.exe today (after a cold boot), it only consume 80MB of ram. I have started the profiler before I go home today. So, I believe I can provide more info tomorrow. BTW, the machine is a P4 2.6GHz with 768MB ram, 1 CPU. It has hyperthreading but I cannot remember whether the parallelism is turn on or off.

SQL Server does not retain the cache across reboot of the server. Check if there is some start up procedure which is running and selects all the records from the tables. Table 2 has 5000 records. May be all the records are on 2 pages. Can you verify this? If this is the case the you would see only 2 loigical IO’s. Gaurav
Moderator
Man thrives, oddly enough, only in the presence of a challenging environment- L. Ron Hubbard

The views expressed here are those of the author and no one else. There are no warranties as to the reliability or accuracy of anything presented here.
derrickleggett and gaurav_bindlish, I have captured every eventclass in the profiler for the 1st run and 2nd run. The 1st run takes about 90 min and 2nd run takes 17 min. I save the traces to 2 tables. I run the following statements: select eventclass, sum(eventclass) from trace1strun group by eventclass order by eventclass select eventclass, sum(eventclass) from trace2ndrun group by eventclass order by eventclass I only list the difference between the results: 1st run
eventclass sum(eventclass) event name
23 1633897 Lock: Released
24 2434680 Lock: Acquired
35 35 SP: CacheInsert
36 684 SP: CacheRemove
38 N/A SP: CacheHit
51 1996854 Scan: Started
52 2036112 Scan: Stopped
81 1053 Server Memory Change 2nd run
eventclass sum(eventclass) event name
23 62353 Lock: Released
24 85152 Lock: Acquired
35 N/A SP: CacheInsert
36 1188 SP: CacheRemove
38 38 SP: CacheHit
51 54774 Scan: Started
52 55952 Scan: Stopped
81 162 Server Memory Change I hope this is enough information. There should not be any special procedure to select data from the tables. These tables (entire database) I created.

I just find out one thing: the SQL SERVER has no service pack. So, I apply SP3a and here is the result: 1st run: 00:04:01
Table ‘table1’ Scan count 1, logical reads 1407601, physical reads 0, read-ahead reads 64073
Table ‘table2’ Scan count 1, logical reads 2. physical reads 0, read-ahead reads 0 1343488 row(s) affected 2nd run: 00:00:18
Table ‘table1’ Scan count 1, logical reads 1407601, physical reads 0, read-ahead reads 0
Table ‘table2’ Scan count 1, logical reads 2. physical reads 0, read-ahead reads 0 1343488 row(s) affected The difference between no service pack and SP3a is the read-ahead reads.

That’s neat! Still we haven’t got the answer for 0 physical reads. Gaurav
Moderator
Man thrives, oddly enough, only in the presence of a challenging environment- L. Ron Hubbard

The views expressed here are those of the author and no one else. There are no warranties as to the reliability or accuracy of anything presented here.
Gaurav, Based onhttp://www.sql-server-performance.com/statistics_io_time.asp, read-ahead reads are actually physical reads.
Still less than the 1400000 logical reads. Gaurav
Moderator
Man thrives, oddly enough, only in the presence of a challenging environment- L. Ron Hubbard

The views expressed here are those of the author and no one else. There are no warranties as to the reliability or accuracy of anything presented here.
Can you calculate how many pages in table1 are actually affected by the query and how many total pages are there? Gaurav
Moderator
Man thrives, oddly enough, only in the presence of a challenging environment- L. Ron Hubbard

The views expressed here are those of the author and no one else. There are no warranties as to the reliability or accuracy of anything presented here.
I will as soon as I figure out how to do that.
sp_spaceused will give you the total number of pages. Don’t forget to use the updateusage flag. No. of records affected / total no. of records will tell you how many pages got affected. Gaurav
Moderator
Man thrives, oddly enough, only in the presence of a challenging environment- L. Ron Hubbard

The views expressed here are those of the author and no one else. There are no warranties as to the reliability or accuracy of anything presented here.
Gaurav, table1:
rows = 1343488
data = 592696KB = 74087 pages
table2:
rows = 20
data = 32KB = 4 pages Since the row affected is all the rows in table1, so the pages affected is 74087 pages.

Okay here is the thing, as far as I knoe read ahead can fetch more than one page at a time – upto 256 KB at a time so it may be the case that all the pages were fetched by read ahead. As far as the number of logical pages goes, it looks like one page is being touched many a times in the execution. Gaurav
Moderator
Man thrives, oddly enough, only in the presence of a challenging environment- L. Ron Hubbard

The views expressed here are those of the author and no one else. There are no warranties as to the reliability or accuracy of anything presented here.
]]>