4

My company uses a software suite in which the only thing I can truly modify is the database. We've always had performance issues (mostly hardware problems that we hope to resolve soon), but lately it's been particularly bad in a specific area - taking 20-120 seconds to load when it should be less than 5. I shouldered some users, ran a trace on their (and my) machines, and this appears to be the offending query:

SELECT s.create_timestamp, s.create_timestamp, s.create_timestamp_tz, s.row_timestamp, log_msg, pre_mod, post_mod, u.first_name, u.mi, u.last_name, log_id
FROM log_events s (NOLOCK), user_mstr u (NOLOCK)
WHERE s.organization_id = '00001'
    AND source1_id = @account_id --Place holder for a client account unique id
    AND source2_id IS NULL
    AND source3_id IS NULL
    AND source4_id IS NULL
    AND s.created_by = u.user_id

I know NOLOCK is bad, but I have no control over that.

It only lags on the 1st time per new source1_id - every execution after is faster - and it appears to get worse with the greater the row count. I ran the query manually using a source1_id that hadn't been ran yet with SET STATISTICS IO/TIME ON, which returned a small-medium number of rows (490), here's the results:

Table 'user_mstr'. Scan count 0, logical reads 6948, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'log_events'. Scan count 1, logical reads 13939, physical reads 1221, read-ahead reads 34, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.

SQL Server Execution Times:
  CPU time = 46 ms,  elapsed time = 18751 ms.

SQL Server Execution Times:
  CPU time = 0 ms,  elapsed time = 0 ms.

The log_events table is big (31,847,167 rows) and is used as a change/audit log for significant changes throughout our DB. Here's a create statement for the table and simplified indices:

CREATE TABLE log_events (
    log_event_id UNIQUEIDENTIFIER NOT NULL,
    organization_id CHAR(5) NOT NULL,
    site_id CHAR(4) NULL,
    source1_id UNIQUEIDENTIFIER NULL,
    source2_id UNIQUEIDENTIFIER NULL,
    source3_id UNIQUEIDENTIFIER NULL,
    source4_id UNIQUEIDENTIFIER NULL,
    event_source_type CHAR(2) NOT NULL,
    log_id CHAR(4) NOT NULL,
    log_msg VARCHAR(4000) NOT NULL,
    pre_mod VARCHAR(1000) NULL,
    post_mod VARCHAR(1000) NULL,
    create_timestamp DATETIME NOT NULL CONSTRAINT DFlog_events_create_timestamp DEFAULT (GETDATE()),
    created_by INT NOT NULL,
    modify_timestamp DATETIME NOT NULL CONSTRAINT DFlog_events_modify_timestamp DEFAULT (GETDATE()),
    modified_by INT NOT NULL,
    row_timestamp TIMESTAMP,
    group_id INT NULL,
    create_timestamp_tz SMALLINT NULL,
    modify_timestamp_tz SMALLINT NULL,
    CONSTRAINT pk_log_events PRIMARY KEY NONCLUSTERED (log_event_id) WITH (FILLFACTOR = 90) ON MAINSYSTEM_INDEX_1
) 
--Simplified Indices:
INDEX inx_log_events1 ON log_events (source1_id, source2_id, source3_id, source4_id)
INDEX inx_log_events3 ON log_events (source1_id, source2_id, event_source_type)
INDEX inx_log_events4 ON log_events (site_id, source2_id, source1_id)
INDEX inx_log_events5 ON log_events (source1_id, event_source_type, site_id, log_event_id)
CLUSTERED INDEX inx_log_events7 ON log_events (create_timestamp, event_source_type)
INDEX inx_log_events8 ON log_events (site_id, source2_id, event_source_type, log_id)
INDEX inx_log_events9 ON log_events (organization_id, site_id, source1_id, source2_id, source3_id, source4_id, event_source_type)

The user_mstr table isn't very big, and user_id field is a PK.

I'm a novice when it comes to indexing, so my questions are:

  1. Can I could improve performance by creating a new index on the organization_id, source1_id, source2_id, source3_id, and source4_id fields?
  2. If so, what type? If not, what can I do without changing the query?
  3. Approximately how much disc space would that consume? Or what other drawbacks would there be to creating this seemingly curtailed query?
  4. What could explain this sudden drop in performance? It's possible our software vendor made some changes over the weekend, but i can't think of what they'd do that would have this effect.
  • What does your explain plan look like? – druzin May 20 '15 at 22:33
  • Performing 21,000-ish logical reads to return 490 rows! That's just wrong. You may have massive fragmentation, or a table scan. Do you perform index maintenance on a regular basis? – Michael Green May 26 '15 at 13:44
6

The CPU time is tiny compared to the amount of actual time.

The second time the query runs, it's fast - presumably once the data is in RAM (being one of the few things which benefits from the second run).

Sounds to me like the problem isn't SQL, but the disk. Notice the PAGEIOLATCH waits increasing while your query runs. Have a look at what's happening on that front. Talk to your SAN guy. Find out if there's other disk activity going on. See if a RAID 5 or 6 disk is being rebuilt.

  • 2
    "problem ... disk" that's one way to look at it (+1). Or, add an index to avoid the scan on log_events. – usr May 20 '15 at 22:55
  • 2
    It's a total of 14k reads on log_events, on a table with 31M rows. That doesn't sound like a table scan to me. And a total of 21k reads, with CPU time less than 1% of the total time - just sounds like bad disk. – Rob Farley May 20 '15 at 23:11
  • 1
    That's a range scan. That's what a seek does if it's returning more than one record. – Rob Farley May 21 '15 at 7:29
  • 1
    This has been an increasingly common theme for us lately. We have an older NetApp SAN, the network is a known bottleneck for us, & I think our SAS HDDs are only 7k (10K max). We're prepping to upgrade the NetApp & network (ethernet fabric), but I'm afraid that's a ways off. I've recently been petitioning IT (I'm a developer) to just install SSDs as DAS in the VM, only have the essentials & our prod DB on it. Any advice on what to do to prove that disk IO is the issue? Generally speaking, should we go with the DAS SSDs be worthwhile, or wait until the SAN/network are upgraded? – jreed121 May 21 '15 at 16:44
  • 1
    There is a lot of stuff out there. This from Microsoft: blogs.msdn.com/b/sqlmeditation/archive/2012/12/06/… – Rob Farley May 21 '15 at 20:44

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

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