{"id":567,"date":"2010-10-12T19:08:00","date_gmt":"2010-10-12T19:08:00","guid":{"rendered":"\/blogs\/jonathan\/post\/TSQL-Tuesday-11-Physical-IOe28099s-Done28099t-Always-Accumulate-Wait-Times.aspx"},"modified":"2017-04-13T12:13:41","modified_gmt":"2017-04-13T16:13:41","slug":"tsql-tuesday-11-physical-ios-dont-always-accumulate-wait-times","status":"publish","type":"post","link":"https:\/\/www.sqlskills.com\/blogs\/jonathan\/tsql-tuesday-11-physical-ios-dont-always-accumulate-wait-times\/","title":{"rendered":"TSQL Tuesday #11 – Physical IO\u2019s Don\u2019t Always Accumulate Wait Times"},"content":{"rendered":"

\nIt is time again for another TSQL Tuesday, this time hosted by my good friend and fellow MVP, Sankar Reddy(Blog<\/a>|Twitter<\/a>).   This month’s topic is Misconceptions about SQL Server<\/a>, and as Sankar points out in this months, there are so many misconceptions out there that almost anyone can blog about this topic, in fact I might even blog more than just one post on this topic since I have a few half finished blog posts that would fit into this topic.\n<\/p>\n

\nFor this post I am going to look at a recent misconception from the MSDN Forums, that physical reads of a data file, correlate to wait stats inside the database engine.  The background on this is rooted in two Dynamic Management Objects inside the database engine; the Dynamic Management Function (DMF) sys.dm_io_virtual_file_stats() which returns I\/O statistics for data and log files and the Dynamic Management View (DMV) sys.dm_os_wait_stats which returns information about all the waits encountered by threads that have executed.  These objects reflect cumulative totals for their information, generally since the server was last restarted.  While it is possible to reset the wait statistic information by using DBCC SQLPERF ('sys.dm_os_wait_stats', CLEAR), the I\/O statistics can only be cleared by restarting the server.  When using either of these objects for analysis of a specific time, it is important to take a snapshot of the data held in them at the start of the analysis, generally by INSERTing the information contained by the object into a temporary table and then performing a differential analysis of the data against a later SELECT from the objects (more on this in a minute).\n<\/p>\n

\nThe misconception on the forum thread was that I\/O stalls as reflected in the sys.dm_io_virtual_file_stats() DMF, would correlate to I\/O related wait counts, and wait times in the sys.dm_os_wait_stats DMV.  Prior to SQL Server 2008, this kind of thing would be impossible to prove without having indepth knowledge of the Database Engine code.  However, one of the new features in SQL Server 2008, Extended Events, actually allows us to define a Event Session to take a look at this in depth, and not only disprove the misconception, but potentially explain the what and why behind it.\n<\/p>\n

\nTo start off lets look at the snapshot information that lead to the misconception for a simple query against AdventureWorks:\n<\/p>\n

\n\tUSE <\/span>[AdventureWorks]
\n\tGO
\n\t<\/span>-- Clear the Buffer Cache to force reads from Disk
\n\t<\/span>DBCC <\/span>DROPCLEANBUFFERS
\n\tGO
\n\t<\/span>-- Drop temporary tables if they exist
\n\t<\/span>IF <\/span>OBJECT_ID<\/span>(<\/span>'tempdb..#io_stats'<\/span>) <\/span>IS <\/span>NOT NULL
\n\t<\/span>DROP TABLE <\/span>#io_stats
\n\t<\/span>GO
\n\t<\/span>IF <\/span>OBJECT_ID<\/span>(<\/span>'tempdb..#wait_stats'<\/span>) <\/span>IS <\/span>NOT NULL
\n\t<\/span>DROP TABLE <\/span>#wait_stats
\n\t<\/span>GO
\n\t<\/span>-- Create the Snapshots of the Dynamic Management Objects
\n\t<\/span>SELECT <\/span>*
\n\t<\/span>INTO <\/span>#io_stats
\n\t<\/span>FROM <\/span>sys.dm_io_virtual_file_stats<\/span>(NULL, NULL)
\n\t<\/span>GO
\n\t<\/span>SELECT <\/span>*
\n\t<\/span>INTO <\/span>#wait_stats
\n\t<\/span>FROM <\/span>sys.dm_os_wait_stats
\n\tGO
\n\t<\/span>-- Turn on Statistics IO so we can see the IO ops
\n\t<\/span>SET STATISTICS <\/span>IO <\/span>ON
\n\t<\/span>GO
\n\t<\/span>-- Run the Simple SELECT against AdventureWorks
\n\t<\/span>SELECT <\/span>SUM<\/span>(<\/span>TotalDue<\/span>), <\/span>SalesPersonID
\n\t<\/span>FROM <\/span>Sales.SalesOrderHeader
\n\t<\/span>GROUP BY <\/span>SalesPersonID
\n\tGO
\n\t<\/span>-- Turn Off Statistics IO
\n\t<\/span>SET STATISTICS <\/span>IO <\/span>OFF
\n\t<\/span>GO
\n\t<\/span>-- Get the Differential Wait Statistic Information
\n\t<\/span>SELECT
\n\t   <\/span>wait_type               <\/span>= <\/span>t1.wait_type<\/span>,
\n\t   <\/span>waiting_tasks_count     <\/span>= <\/span>t1.waiting_tasks_count <\/span>- <\/span>t2.waiting_tasks_count<\/span>,
\n\t   <\/span>wait_time_ms            <\/span>= <\/span>t1.wait_time_ms <\/span>- <\/span>t2.wait_time_ms<\/span>,
\n\t   <\/span>max_wait_time_ms        <\/span>= <\/span>t1.max_wait_time_ms <\/span>- <\/span>t2.max_wait_time_ms<\/span>,
\n\t   <\/span>signal_wait_time_ms     <\/span>= <\/span>t1.signal_wait_time_ms <\/span>- <\/span>t2.signal_wait_time_ms
\n\t<\/span>FROM <\/span>sys.dm_os_wait_stats <\/span>AS <\/span>t1
\n\t<\/span>JOIN <\/span>#wait_stats <\/span>AS <\/span>t2
\n\t   <\/span>ON <\/span>t1.wait_type <\/span>= <\/span>t2.wait_type
\n\t<\/span>WHERE <\/span>t1.wait_time_ms <\/span>- <\/span>t2.wait_time_ms <\/span>> <\/span>0
\n\tGO
\n\t<\/span>-- Get the Differential IO Statistic Information
\n\t<\/span>SELECT
\n\t   <\/span>database_name           <\/span>= <\/span>DB_NAME<\/span>(<\/span>t1.database_id<\/span>),
\n\t   <\/span>logical_name            <\/span>= <\/span>mf.name<\/span>,
\n\t   <\/span>physical_name           <\/span>= <\/span>mf.physical_name<\/span>,
\n\t   <\/span>num_of_reads            <\/span>= <\/span>t1.num_of_reads <\/span>- <\/span>t2.num_of_reads<\/span>,
\n\t   <\/span>num_of_bytes_read       <\/span>= <\/span>t1.num_of_bytes_read <\/span>- <\/span>t2.num_of_bytes_read<\/span>,
\n\t   <\/span>io_stall_read_ms        <\/span>= <\/span>t1.io_stall_read_ms <\/span>- <\/span>t2.io_stall_read_ms<\/span>,
\n\t   <\/span>num_of_writes           <\/span>= <\/span>t1.num_of_writes <\/span>- <\/span>t2.num_of_writes<\/span>,
\n\t   <\/span>num_of_bytes_written    <\/span>= <\/span>t1.num_of_bytes_written <\/span>- <\/span>t2.num_of_bytes_written<\/span>,
\n\t   <\/span>io_stall_write_ms       <\/span>= <\/span>t1.io_stall_write_ms <\/span>- <\/span>t2.io_stall_write_ms<\/span>,
\n\t   <\/span>io_stall                <\/span>= <\/span>t1.io_stall <\/span>- <\/span>t2.io_stall<\/span>,
\n\t   <\/span>size_on_disk_bytes      <\/span>= <\/span>t1.size_on_disk_bytes<\/span>,
\n\t   <\/span>file_handle             <\/span>= <\/span>t1.file_handle
\n\t<\/span>FROM <\/span>sys.dm_io_virtual_file_stats<\/span>(NULL, NULL) <\/span>AS <\/span>t1
\n\t<\/span>JOIN <\/span>#io_stats <\/span>AS <\/span>t2
\n\t   <\/span>ON <\/span>t1.database_id <\/span>= <\/span>t2.database_id
\n\t       <\/span>AND <\/span>t1.<\/span>FILE_ID <\/span>= <\/span>t2.<\/span>FILE_ID
\n\t<\/span>JOIN <\/span>sys.master_files <\/span>AS <\/span>mf
\n\t   <\/span>ON <\/span>mf.database_id <\/span>= <\/span>t1.database_id
\n\t       <\/span>AND <\/span>mf.<\/span>FILE_ID <\/span>= <\/span>t1.<\/span>FILE_ID
\n\t<\/span>WHERE <\/span>(<\/span>t1.num_of_reads <\/span>- <\/span>t2.num_of_reads <\/span>> <\/span>0<\/span>)
\n\t  OR (<\/span>t1.num_of_writes <\/span>- <\/span>t2.num_of_writes <\/span>> <\/span>0<\/span>)
\n\t<\/span>GO<\/span><\/code>\n<\/p><\/blockquote>\n

\nThe expectation in the forums thread was that the num_of_reads, and the io_stall_read_ms values from sys.dm_io_virtual_file_stats() would have an equivalent amount of waiting_tasks_count and wait_time_ms in sys.dm_os_wait_stats, but as can be seen from the below output, this is not the case.\n<\/p>\n

\n\"image\"<\/a>\n<\/p>\n

\nBefore I continue with this post, let me first provide some information about the hardware basis for these tests.  The information contained in this blog post comes from my VMware Workstation SQL Server 2008 VM running on my laptop which is a a Dell Inspiron 1400 which has 4GB RAM, and a 120GB OCZ Summit SSD.  The VM has a single vCPU and 1GB RAM allocated to it.  Now I would be remiss in thinking that this configuration wouldn’t raise some eyebrows, but rest assured that I have validated these findings on multiple enterprise class VM’s as well as physical servers including a dual quad core Dell R710 with 32GB RAM and a 8 Disk DAS that I have used in other tests for blog posts in the past.  The results have been consistent across all of my tests and the output from my laptop VM allows me to completely isolate the workload being performed in SQL to a single execution easily.\n<\/p>\n

\nSo why don’t these numbers line up?  To explain this further we can use an Extended Event Session to look at the internal workings when the example workload query is executed:\n<\/p>\n

\n\tIF <\/span>EXISTS(<\/span>SELECT <\/span>*
\n\t         <\/span>FROM <\/span>sys.server_event_sessions
\n\t         <\/span>WHERE <\/span>name<\/span>=<\/span>'test_session'<\/span>)
\n\t    <\/span>DROP <\/span>EVENT SESSION [test_session] <\/span>ON <\/span>SERVER<\/span>;
\n\t<\/span>CREATE <\/span>EVENT SESSION [test_session]
\n\t<\/span>ON <\/span>SERVER
\n\t<\/span>ADD <\/span>EVENT sqlserver.file_read<\/span>(
\n\t     <\/span>ACTION <\/span>(<\/span>sqlserver.database_id<\/span>, <\/span>sqlserver.session_id<\/span>)),
\n\t<\/span>ADD <\/span>EVENT sqlserver.file_written<\/span>(
\n\t     <\/span>ACTION <\/span>(<\/span>sqlserver.database_id<\/span>, <\/span>sqlserver.session_id<\/span>)),
\n\t<\/span>ADD <\/span>EVENT sqlserver.file_read_completed<\/span>(
\n\t     <\/span>ACTION <\/span>(<\/span>sqlserver.database_id<\/span>, <\/span>sqlserver.session_id<\/span>)),
\n\t<\/span>ADD <\/span>EVENT sqlserver.file_write_completed<\/span>(
\n\t     <\/span>ACTION <\/span>(<\/span>sqlserver.database_id<\/span>, <\/span>sqlserver.session_id<\/span>)),
\n\t<\/span>ADD <\/span>EVENT sqlos.async_io_requested<\/span>(
\n\t     <\/span>ACTION <\/span>(<\/span>sqlserver.database_id<\/span>, <\/span>sqlserver.session_id<\/span>)),
\n\t<\/span>ADD <\/span>EVENT sqlos.async_io_completed<\/span>(
\n\t     <\/span>ACTION <\/span>(<\/span>sqlserver.database_id<\/span>, <\/span>sqlserver.session_id<\/span>)),
\n\t<\/span>ADD <\/span>EVENT sqlos.wait_info<\/span>(
\n\t     <\/span>ACTION <\/span>(<\/span>sqlserver.database_id<\/span>, <\/span>sqlserver.session_id<\/span>)),
\n\t<\/span>ADD <\/span>EVENT sqlserver.sql_statement_starting<\/span>(
\n\t     <\/span>ACTION <\/span>(<\/span>sqlserver.database_id<\/span>, <\/span>sqlserver.plan_handle<\/span>,
\n\t            <\/span>sqlserver.session_id<\/span>, <\/span>sqlserver.sql_text<\/span>)),
\n\t<\/span>ADD <\/span>EVENT sqlserver.sql_statement_completed<\/span>(
\n\t     <\/span>ACTION <\/span>(<\/span>sqlserver.database_id<\/span>, <\/span>sqlserver.plan_handle<\/span>,
\n\t            <\/span>sqlserver.session_id<\/span>, <\/span>sqlserver.sql_text<\/span>))
\n\t<\/span>ADD <\/span>TARGET package0.ring_buffer
\n\t<\/span>WITH <\/span>(<\/span>MAX_MEMORY <\/span>= <\/span>4096KB<\/span>,
\n\t     <\/span>EVENT_RETENTION_MODE <\/span>= <\/span>ALLOW_SINGLE_EVENT_LOSS<\/span>,
\n\t     <\/span>MAX_DISPATCH_LATENCY <\/span>= <\/span>5 SECONDS<\/span>,
\n\t     <\/span>MAX_EVENT_SIZE <\/span>= <\/span>4096KB<\/span>,
\n\t     <\/span>MEMORY_PARTITION_MODE <\/span>= <\/span>PER_CPU<\/span>,
\n\t     <\/span>TRACK_CAUSALITY <\/span>= ON<\/span>,
\n\t     <\/span>STARTUP_STATE <\/span>= OFF<\/span>)<\/span><\/code>\n<\/p><\/blockquote>\n

\nSome items about this Event Session that should be noted:\n<\/p>\n

    \n
  1. The Event Session uses the TRACK_CAUSALITY session option which appends a sequential GUID to each event allowing the event sequences to be followed. <\/li>\n
  2. The Event Session captures the sql_statement_starting and sql_statement_completed events allowing isolation of the associated events between these two events by the attach_activity_id action, which is collected by causality tracking. <\/li>\n
  3. The Event Session captures the following IO related Events:\n