SQL Server Performance

How to find the cause for the speed discrepancy?

Discussion in 'T-SQL Performance Tuning for Developers' started by pcsql, May 4, 2004.

  1. pcsql New Member

    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.
  2. gaurav_bindlish New Member

    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.
  3. pcsql New Member

    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.


  4. derrickleggett New Member

    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
    derrickleggett@hotmail.com

    When life gives you a lemon, fire the DBA.
  5. pcsql New Member

    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.
  6. derrickleggett New Member

    You do have an index on table1.crefid correct? When you look at the execution plan, do you see any table scans?

    MeanOldDBA
    derrickleggett@hotmail.com

    When life gives you a lemon, fire the DBA.
  7. gaurav_bindlish New Member

    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.
  8. derrickleggett New Member

    It sounds like a compile issue, doesn't it? I would be interested to see a Profiler on the recompiles.

    MeanOldDBA
    derrickleggett@hotmail.com

    When life gives you a lemon, fire the DBA.
  9. gaurav_bindlish New Member

    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.
  10. pcsql New Member

    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.


  11. gaurav_bindlish New Member

    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.
  12. pcsql New Member

    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.




  13. pcsql New Member

    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.
  14. gaurav_bindlish New Member

    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.
  15. pcsql New Member

  16. gaurav_bindlish New Member

    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.
  17. gaurav_bindlish New Member

    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.
  18. pcsql New Member

    I will as soon as I figure out how to do that.
  19. gaurav_bindlish New Member

    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.
  20. pcsql New Member

    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.


  21. gaurav_bindlish New Member

    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.

Share This Page