Sudden poor SELECT performance on a large table with existing indexes

Question

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.

Answer 1

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.