We have been having CPU issues with one of our servers lately and while we have been looking into this we have also noticed queries running slowly with waits of
PAGEIOLATCH_XX. In particular, a reindex job is seemingly always having this wait type.
In response, I have run a collect against
sys.dm_io_virtual_file_stats and then broken this down into time chunk and worked out the average stall per operation. While there are spikes mostly, the disk seems to have a value of regularly under 20 ms. From what I remember, 20 ms is the recommended value(?).
Further to this I have run Glenn Barry's script:
select db_name(database_id) as DatabaseName, file_id ,io_stall_read_ms ,num_of_reads ,cast(io_stall_read_ms/(1.0+num_of_reads) as numeric(10,1)) as 'avg_read_stall_ms' ,io_stall_write_ms ,num_of_writes ,cast(io_stall_write_ms/(1.0+num_of_writes) as numeric(10,1)) as 'avg_write_stall_ms' ,io_stall_read_ms + io_stall_write_ms as io_stalls ,num_of_reads + num_of_writes as total_io ,cast((io_stall_read_ms+io_stall_write_ms)/(1.0+num_of_reads + num_of_writes) as numeric(10,1)) as 'avg_io_stall_ms' from sys.dm_io_virtual_file_stats(null,null) --where db_name(database_id) = 'tempdb' order by [DatabaseName] desc'
Which calculates the average I/O stall also and this also confirms stalls less than 20 ms.
I have also looked in the following to see if any pending tasks are taking longer than recommended, but this isn't throwing up any pending I/O operations taking regularly longer than 20 ms.
SELECT db_name(database_id) as 'Database', file_name(file_id) as 'File', io_stall, io_pending_ms_ticks FROM sys.dm_io_virtual_file_stats(NULL, NULL) iovfs, sys.dm_io_pending_io_requests as iopior WHERE iovfs.file_handle = iopior.io_handle
My question now is: If the issue is not disk related, why am I seeing lots of PAGEIOLATCH_XX waits? In particular, why is the reindex running extremely slowly with this wait type?
Could this be related to CPU pressure?
I just wanted to update the thread. After doing more analysis I have tracked down a particular proc that is causing significant reads. The proc is as follows:
ALTER PROCEDURE [dbo].[GetActiveSessionCount] @SessionCount INTEGER OUTPUT AS SET NOCOUNT ON BEGIN DECLARE @Error INTEGER, @RowCount INTEGER, @nExpireAfter INTEGER SELECT @nExpireAfter = ExpireSessionsAfter FROM KSYSTEM SELECT @Error = @@ERROR, @RowCount = @@ROWCOUNT IF(1 <> @RowCount) BEGIN RAISERROR (50003, 15, 1, 'GetActiveSessionCount') RETURN 50003 END IF (0 <> @Error) BEGIN RETURN @Error END SELECT @SessionCount = COUNT(SessionID) FROM KSESSION WITH (NOLOCK) WHERE ( ( Expirable = 0 ) OR ( Expirable = 1 AND ( --SessionID IS NOT NULL) EXISTS (SELECT SessionID FROM KFILESAWAITINGCOMMIT fac WITH (NOLOCK) WHERE SessionID = fac.SessionID) OR ( LastAccessDateTime IS NOT NULL AND GETDATE() <= (DATEADD(minute, @nExpireAfter, LastAccessDateTime)) ) ) ) ) SELECT @Error = @@ERROR IF(@Error <> 0) BEGIN RETURN @Error END RETURN 0 END
STATISTICS IO I can see the problem line is
SELECT SessionID FROM KFILESAWAITINGCOMMIT fac WITH (NOLOCK) WHERE SessionID = fac.SessionID
Looking at the execution plan it is doing a Clustered Index Scan. Now there is an non clustered index on that table already specifically for SessionID however it is not being used.
What I am finding in testing is if I run that
SELECT by itself then it uses the non clustered index and performs well. But if I use a hint in the proc to force it to use the non clustered index, then it actually performs worse.
Can anyone explain?