4

I am writing an application which builds a database on a SQL server. The application loads data into some staging tables, then executes a series of stored procedures which merge the staging tables into the main tables.

The problem I'm seeing is that the merge itself is consistently much slower than I expect given the resources available to the server (8 cores, DB stored on RAID0 array of two SSDs, 32GB RAM, no other server processes running on the machine or other users of the SQL Server instance).

To be specific, during the merge:

  1. Server CPU usage is very low (a few percent)
  2. There are essentially no writes and reads to the logical volume that the database is stored on (measured in perfmon)
  3. In a 30s period during the merge, Brent Ozar's wait stats triage script (http://www.brentozar.com/responder/triage-wait-stats-in-sql-server/) reports a maximum wait time of only 0.6s (on the SOS_SCHEDULER_YIELD wait type)
  4. Inspecting dm_io_virtual_file_stats for both tempdb and the main database before and after a 30s period during the merge shows that IO stall time increases by less than 0.1s, indicating that we are not blocked on IO
  5. Activity Monitor confirms the IO system is lightly loaded: maximum IO response latency is only 9ms, with very low number of bytes transferred
  6. Intel Performance Counter Monitor (http://www.intel.com/software/pcm) shows that we are not swamping RAM bandwidth because only about 500MB/s is being transferred (out of a benchmarked maximum on this machine of around 13GB/s)
  7. Inspecting dm_exec_sessions for the merging session before and after a 30s period during the merge shows that:
    • total_elapsed_time increased by ~10s (I assume this is not 30s because dm_exec_sessions only gets updated periodically)
    • cpu_time increases by only 0.1s
    • memory_usage is only 2 pages both before and after
    • 20,000 logical_reads are performed in this 10s period (i.e. 2,000 a second). This seems very low to me given that that only represents 16MB/s of data transfer.
    • 1196 writes and 36 reads are performed. (I'm not quite sure how to interpret this.)

SQL Profiler shows that it is the execution of statements of the following form that is slow (taking as much as 5s when there are ~1000 rows in the staging table stage.LastTradePrice):

;WITH Source AS 
(
    SELECT 
        RowNumber = 
            ROW_NUMBER() OVER (PARTITION BY GSAQuoteID, Date ORDER BY ID DESC)
        , Source.* 
    FROM 
        stage.[LastTradePrice] Source
)

INSERT INTO @Stage 
    (
    GSAQuoteID
    , Date
    , Value
    )
SELECT 
    Source.GSAQuoteID
    , Source.Date
    , Source.Value
FROM 
    Source
OUTER APPLY 
    (
    SELECT TOP 1 
        Value = 
            CASE WHEN ToSourceID IS NULL THEN Target.Value ELSE NULL END
    FROM 
        dbo.[LastTradePrice] Target
    WHERE 
        Target.GSAQuoteID = Source.GSAQuoteID 
    AND Target.Date = Source.Date
    ORDER BY 
        Target.FromSourceID DESC
    ) Target
WHERE 
    Source.RowNumber = 1
AND (
        (Source.Value IS NULL AND Target.Value IS NOT NULL) 
        OR 
        (Source.Value IS NOT NULL AND Target.Value IS NULL) 
        OR 
        (Source.Value <> Target.Value)
    );

This query is the first stage of the merge: it selects those elements of the staging table stage.LastTradePrice which are different from the data we already have in the main table dbo.LastTradePrice.

The query plan for this statement looks pretty much optimal (i.e. it sorts the staging table by (GSAQuoteID,Date,ID DESC), segments it by (GSAQuoteID,Date) and then does a single-row seek into the LastTradePrice table for the top row in each segment, before doing the final clustered index insert). More details:

  • stage.LastTradePrice has a clustered index on ID, a synthetic integer primary key. Rows occur in the order they are bulk inserted by the application
  • dbo.LastTradePrice has a clustered index on (GSAQuoteID, Date, FromSourceID)
  • There are about 56M rows in dbo.LastTradePrice, an average of 168 per GSAQuoteID and just over 1 per (GSAQuoteID, Date) pair.

The database itself is about 34GB in size and therefore should almost entirely fit into memory. This is confirmed by the very high buffer cache hit ratio of >=99.8% I see consistently.

This all leaves me a bit confused. If these slow statements aren't starved of CPU time, waiting on IO, waiting on a lock or starved of memory bandwidth, what actually is left as a possible cause of the slowdown?

The only thing that I think might be a bit unusual about the system is that there is a relatively large number of tables and stored procedures. For various reasons, each of the ~330 fields I wish to store (e.g. LastTradePrice, Volume, OpenPrice and lots more) are given their own table+staging table, each with a corresponding stored procedure that implements the merge. (All of the sprocs are generated from a template, so the merge logic is basically identical for all fields.).

I think the large number of sprocs may explain why I'm seeing what I believe is a relatively high "Stolen pages" count of 200,000 and plan cache hit ratio of only ~80% even though no adhoc SQL is being used. However, I don't see how this could explain my problem.

11
  • 2
    Can you add the execution plan to your question please. Link to the plan XML preferably. Jan 4, 2014 at 18:59
  • Certainly. This file contains a query plan generated from the execution of a representative subset of the merge procedures (including LastTradePrice, my example above). Be warned that it is quite long: dropbox.com/s/cq0wqjk9gfw7lp8/Example2014-01-02.zip Jan 4, 2014 at 19:12
  • Note that the plan I point to above uses a LEFT JOIN rather than OUTER APPLY (as in my SQL in the question above), because the plan is slightly out-of-date. However, I saw exactly the same behaviour with both forms of the query. (OUTER APPLY instead of LEFT JOIN lowered logical reads reported by SET STATISTICS IO by about 7%, but didn't otherwise have noticable impact) Jan 4, 2014 at 19:25
  • Do you notice lockwaits while the query is running?
    – MichaelD
    Jan 4, 2014 at 19:42
  • 1
    As you've narrowed it down to a specific query can you supply the actual execution plan for just that statement on one of its 5 second runs? (So we can see actual vs estimated row counts etc) and also the output of SET STATISTICS IO ON;SET STATISTICS TIME ON; for that. Also the wait statistics for that single spid during the operation? Jan 4, 2014 at 21:26

2 Answers 2

3

This is most likely caused by the MERGE operation in SQL Server being single threaded. No matter how many resources you throw at it, it wont run faster which is exactly what you are observing.

The solution is to manually parallelise the query by running multiple copies of the MERGE statement at the same time, each operating on their own subset of the data.

The problem is very common in data warehouses running SQL Server. There are a series of good design pattern in this document: http://technet.microsoft.com/en-us/library/dd425070(v=sql.100).aspx (DISCLAIMER: This is written by yours truly, so I am shamelessly plugging this)

1
  • Thanks Thomas, this looks like an interesting document - I'll definitely give it a read because although MERGE was not the problem in this instance, it may turn out to be my next bottleneck :) Jan 5, 2014 at 0:14
1

OK, so the problem turned out to be waits on IO after all. When gathering data to respond to Martin Smith's comment, I noticed that those fields which were slow to merge were precisely those which SET STATISTICS IO reported as having performed physical IO.

I had originally ruled out this hypothesis because dm_io_virtual_file_stats had reported low IO wait times when I had used to to monitor the application as it performed merges, and I had expected any IO waits to be reported by Brent Ozar's script.

However, when I tried doing the merge from within SSMS instead, running dm_io_virtual_file_stats in the same batch as the merge itself, I found that almost all of the merge time was being spent blocked on disk IO!

I'm not sure why this discrepancy exists between what I can observe about the merge when done from SSMS vs. what I can observe about it when done from the application's connection.

The fact that perfmon reports low bytes/sec actually being transferred means that my query must just be being killed by the latency of disk requests: I suppose that when SQL server makes a disk request for some seek into dbo.LastTradePrice, it just then sits there and blocks rather than doing something like e.g. seeking forward into stage.LastTradePrice for another row it could speculatively make an IO request for. This would probably be mitigated somewhat if the query optimiser had decided to made use of any parallelism for my query.

I think my solution will be fourfold:

  1. Rebuild the dbo.* tables. Currently the pages are only about 50% full which is likely causing a bit more logical IO than is really necessary. (SQL Server also reports that these tables are about 97% fragmented, which probably hurts a little bit too.)
  2. Enable page-level compression on the dbo.* tables. sp_estimate_data_compression_savings suggests that this will halve the number of pages required to store the table, which should again reduce logical IO
  3. Look into changing the clustered index on tables like dbo.LastTradePrice to be (Date,GSAQuoteID) instead of (GSAQuoteID,Date). The reason for this is that each merge tends to refer to only a single Date but multiple GSAQuoteIDs, so changing the table sort order should increase the locality of access and allow the buffer cache to be more effective.
  4. Look into introducing parallelism at some level e.g. running each field's merge in parallel in a different connection. This should hopefully mean that SQL Server has something to do while it waits for its IO requests to be serviced.
4
  • 2
    This isn't adding up. You did say RAID0 SSD array right? Jan 5, 2014 at 1:46
  • Yes, it is a RAID0 array of SSDs. SET STATISTICS IO reports that e.g. a statement that required 1129 physical reads executed in 3604ms. An equivalent statement that is serviced entirely from memory executes in ~70ms. So assuming all the physical reads are issued serially, that means that each physical read incurs a latency of (3694-70)/1129=3.2ms. SiSoft Sandra reports a latency of 0.04-5.23ms on the array, so this doesn't seem that unreasonable. Is that latency higher than you would expect for a SSD? Jan 5, 2014 at 11:34
  • 1
    Quick test suggests 0.5-1ms per physical read on the consumer SSD in my laptop (with read-ahead disabled via TF652). 50% full is certainly costing you, probably ~50% given the fragmentation level. Jan 5, 2014 at 15:43
  • Thanks Mark - my latency does seem perhaps a little high then. I'll investigate whether anything can be done to reduce it. Hopefully with my other changes I should be able to avoid hitting disk at all, though! Jan 5, 2014 at 15:53

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

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