2

I'm having a problem with a query usually being so slow on first time run that it times out and then executing in under a second once it's loaded into cache.

The query looks something like this

exec sp_executesql N'SELECT
    [Project1].RecordID AS [RecordId],
    ...
    FROM ( SELECT
        [Extent1].RecordId] AS [RecordId],
        ...
        FROM Items AS [Extent1]
        LEFT OUTER JOIN ItemParameters as [Extent2] 
        ON [Extent1].[RecordId] = [Extent2].[SampleId]
        WHERE ...
    ) as [Project1]
    ORDER BY [Project1].CreatedDate DESC, [Project1].RecordId ASC, ...

The query is generated by EntityFramework for me and only has this one join. The Items table is ~3.5 million rows and ~2.5 GB data and the ItemParameters is ~23.6 million rows and ~19.2 GB data. The query returns 11400 rows and, as far as I can tell, properly hits the indexes.

I've written a test program that does this in a loop, forever:

  • Restart the SQL Server service (MSSQLSERVER).
  • Sleep for 6 minutes. To allow it to start up.
  • Execute above query.
  • Write execution time to a file.

The results are disturbing. Sometimes it takes 4 minutes and sometimes it takes 4 seconds and I don't see why. It is running on a VM Ware virtual machine. On my developer laptop the same query (against a third of the data) is completed in 3 seconds.

I've run it with set statistics io on and set statistics time on and the output looks like this:

(11409 rows affected)
Table 'ItemParameters'. Scan count 3803, logical reads 19689, physical reads 2724, read-ahead reads 4261, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'Items'. Scan count 109, logical reads 40423, physical reads 4, read-ahead reads 4089, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.

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

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

Things I've done to speed up performance:

What can I do to make sure the query executes quickly enough every time? Any help is greatly appreciated.

EDIT

  • I updated column statistics, it did not help. I've also started investigating disk performance. I'll update the original post once I have the results. – Johan Gov Oct 9 '18 at 13:03
3

What can I do to make sure the query executes quickly enough every time?

It's unlikely that this is a query performance issue. You're doing very little IO, using very little CPU time, and the query isn't processing very much data. The likely solution will be to resolve the hardware or configuration issue that is causing your query to run for so long sometimes. In one of your executions the query 92636 ms of elapsed time but only used 546 ms of CPU time That means that SQL Server was waiting for something for over 92 seconds during query execution. Based on your description of the problem it's likely that there's a severe IO problem on the server. 11000 physical reads isn't that much and what you're seeing isn't normal.

You didn't include your version of SQL Server, but to get more information about the problem I would look at wait stats. You seem to have control over the server so you can try taking a before and after snapshot of the sys.dm_os_wait_stats DMV and seeing which waits increase after the query finishes executing. That DMV is server wide so you'll want to avoid running other queries if possible. You can also reset the DMV immediately before running your query by running the following T-SQL:

DBCC SQLPERF ("sys.dm_os_wait_stats" , CLEAR);

The wait stats should let you confirm if IO is indeed the problem. You may need to work with the admin in charge of the VM or storage to resolve this issue.

  • It turned out the the PAGEIOLATCH_SH from sys.dm_os_wait_stats was way higher on the server than on my machine. This article helped me understand the statistics. – Johan Gov Oct 18 '18 at 8:21
1

This is just a supplementary answer to the previous one.

The sys.dm_os_wait_stats System Management View can be queried using the following statements provided by Paul Randal in his blog post:

Capturing wait statistics for a period of time (SQLskills.com)

Paul uses a WAITFOR DELAY '00:30:00'; in his script.

Instead you just execute the script above that line, before you execute your long running statement and once the statement has finished you execute the part below that line.

The script will generate a list of top 95% of wait types for the duration of the your long-running statement.

This can look like this:

WaitType | Wait_S | Resource_S | Signal_S  | WaitCount | Percentage | AvgWait_S | AvgRes_S | AvgSig_S
---------+--------+------------+-----------+-----------+------------+-----------+----------+--------------
WRITELOG | 0.00   | 0.00       | 0.00      | 1         | 100.00     | 0.0020    | 0.0020   |  0.0000

Depending on the wait type found, you can then look them up either in Paul Randal's library.

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.