1

Values for io_stall_read_ms seems to be higher than actual run time for query. The setup:

create database filestats;

use filestats;

create table t1_primary(
 a  int     identity
,b  int
,c  datetime
,d  char(780)
,constraint pk_p_a primary key clustered (a));

set nocount on;
declare @n int = 0;

while @n < 12800
begin
    insert into t1_primary select @n, CURRENT_TIMESTAMP, ABS(CHECKSUM(NEWID()))
select @n += 1
end

set statistics io, time on;

declare @before datetime 

dbcc dropcleanbuffers
checkpoint

if object_id('tempdb..#vfsBefore') is not null
    drop table #vfsBefore

if object_id('tempdb..#vfsAfter') is not null
    drop table #vfsAfter

select * 
into #vfsBefore
from sys.dm_io_virtual_file_stats(db_id('filestats'), null)

select @before = CURRENT_TIMESTAMP

select * from dbo.t1_primary 

select DATEDIFF(ms, @before, CURRENT_TIMESTAMP)

select * 
into #vfsAfter
from sys.dm_io_virtual_file_stats(db_id('filestats'), null)

select 
 db_name(b.database_id)
,mf.name
,a.num_of_reads-b.num_of_reads              as NumReads
,a.num_of_bytes_read-b.num_of_bytes_read    as NumBytesRead
,a.io_stall_read_ms-b.io_stall_read_ms      as IOStallReadMS
,a.num_of_writes-b.num_of_writes            as NumWrites
,a.num_of_bytes_written-b.num_of_bytes_written  as NumBytesWritten
,a.io_stall_write_ms-b.io_stall_write_ms    as IOStallWriteMS
,a.io_stall-b.io_stall                      as IOStallTotal
,a.size_on_disk_bytes-b.size_on_disk_bytes  as SizeOnDiskBytes
,mf.physical_name
from #vfsBefore b
join #vfsAfter a on b.database_id = a.database_id and b.file_id =     a.file_id
join sys.master_files mf on b.database_id = mf.database_id and b.file_id = mf.file_id

Running this results in the following:

Virtual file stats: num_of_reads = 26, io_stall_read_ms = 2153

Statistics IO: Table 't1_primary'. Scan count 1, logical reads 2571, physical reads 3, read-ahead reads 2552

Statistics time: CPU time = 46 ms, elapsed time = 595 ms.

Run time, DATEDIFF function: 593 ms

Not surprisingly a clustered index scan is performed, single threaded. How come the io_stall_read_ms value is higher than the time executing the query. What is going on here?

  • Stalls for read are high because when you ran query none of the pages were in memory and SQL Server only reads from memory. So it waited for pages to be fetched. Now SQL Server does not fetches just one page but does read aheads and makes educated guess and fetched some extra pages which would satify your query this is Called READ AHEAD MECHANISM. Now this could have taken some time. Can you run query again without dropcleaning buffer, do you still see same latency ? – Shanky Apr 2 '15 at 14:44
  • Shanky - consecutive runs without dbcc dropcleanbuffers, show no IO stall values, since the data is entirely in memory, as you say. That is exactly what one would expect too, since you're not reading from the data file. What I don't understand - even though read-ahead kicks in - is how the total IO stalls in ms can be higher than the total run time of the query (at least that's what I conclude from the result), when it's single threaded. For a parallel query it might be an accumulated value for all threads stall time. – GordonLiddy Apr 2 '15 at 16:09
  • * is how the total IO stalls in ms can be higher than the total run time of the query*....This may be because READ AHEADS start much before query is actually executed.Please read technet.microsoft.com/en-us/library/… If you find this satisfactory I would change my comments to answer – Shanky Apr 3 '15 at 5:02
  • The correct answer can be found here as StuartLC suggests on StackOverflow which makes perfect sense. I didn't find Shankys answer reasonable: "This may be because READ AHEADS start much before query is actually executed". But thanks anyway for taking your time and trying to help. – GordonLiddy Apr 4 '15 at 15:55

Your Answer

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

Browse other questions tagged or ask your own question.