Catching Slow File I/O with a Filtered Extended Events Session
sys.dm_io_virtual_file_stats will tell you that one of your data files has an average read latency of 45 milliseconds, which is bad, but it is an average since the file was opened. It cannot tell you whether that 45 ms is a steady drizzle of slightly-slow reads or a flat-calm file that froze for two seconds at 3 a.m. during a backup. Averages hide exactly the spikes you are being paged about. To see the individual slow I/Os, with the file, the size, and the offset, you need to watch each operation as it completes.
SQL Server raises an event for every completed file read and every completed file write, and you can capture them with Extended Events. The catch is volume: a busy instance does tens of thousands of these per second, and capturing all of them would cost more than the problem. This is the fifth and final post in the Extended Events for the working DBA series, and it is built on the technique that makes high-frequency events usable: filter at the session, so SQL Server only ever materialises the events you care about.
The Predicate Earns Its Keep
file_read_completed and file_write_completed each carry a duration field, in microseconds, for how long the I/O took.[1] Put a WHERE clause on that duration and the session discards every fast, healthy I/O before it is ever serialised, keeping only the outliers. This is the same lesson as the error session in the third post: the predicate is what makes a firehose event safe to turn on. Here the stakes are higher, because without the filter you would be capturing essentially all storage activity on the instance.
The threshold is a number of microseconds. A value of 100000 (100 ms) captures genuinely slow I/O without much noise; lower it toward 20000 (20 ms) on storage you expect to be fast, such as NVMe, to catch latency that still matters there. Set collect_path so each event records which file it touched, and attach the database name as an action so you do not have to resolve it later.
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 |
IF EXISTS ( SELECT 1 FROM [sys].[server_event_sessions] AS [ss] WHERE [ss].[name] = N'FileIO_filtered_ringbuffer' ) BEGIN DROP EVENT SESSION [FileIO_filtered_ringbuffer] ON SERVER; END; CREATE EVENT SESSION [FileIO_filtered_ringbuffer] ON SERVER ADD EVENT [sqlserver].[file_read_completed] ( SET collect_path = (1) ACTION ([sqlserver].[database_name]) WHERE ([duration] > 100000) /* microseconds; 100000 = 100 ms */ ), ADD EVENT [sqlserver].[file_write_completed] ( SET collect_path = (1) ACTION ([sqlserver].[database_name]) WHERE ([duration] > 100000) ) ADD TARGET [package0].[ring_buffer] ( SET max_events_limit = 1000, max_memory = 2048 ) WITH ( MAX_MEMORY = 4096 KB , EVENT_RETENTION_MODE = ALLOW_MULTIPLE_EVENT_LOSS , MAX_DISPATCH_LATENCY = 30 SECONDS , STARTUP_STATE = ON ); ALTER EVENT SESSION [FileIO_filtered_ringbuffer] ON SERVER STATE = START; |
Two of the WITH options differ deliberately from the earlier posts. EVENT_RETENTION_MODE is ALLOW_MULTIPLE_EVENT_LOSS rather than single-event loss, because for sampling slow I/O it is far better to drop a few events under pressure than to let the session slow down the very workload you are measuring. And MAX_DISPATCH_LATENCY is a relaxed 30 seconds, since nothing here is time-critical to the second. This is a sampling tool, not an audit.
Shredding to Name the File
The ring buffer now holds only slow I/Os. Shred them as in the earlier posts, but with one addition that turns raw ids into something readable: join the database_id and file_id from each event to sys.databases and sys.master_files, so the output names the database and the physical file rather than making you look them up.[2]
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 |
DECLARE @target_data xml; SELECT @target_data = CONVERT(xml, [t].[target_data]) FROM [sys].[dm_xe_sessions] AS [s] INNER JOIN [sys].[dm_xe_session_targets] AS [t] ON [t].[event_session_address] = [s].[address] WHERE [s].[name] = N'FileIO_filtered_ringbuffer' AND [t].[target_name] = N'ring_buffer'; ;WITH [evt] AS ( SELECT [event_name] = [xe].[x].value('(@name)[1]', 'varchar(30)') , [event_time] = [xe].[x].value('(@timestamp)[1]', 'datetimeoffset(3)') , [database_id] = [xe].[x].value('(data[@name="database_id"]/value)[1]', 'int') , [file_id] = [xe].[x].value('(data[@name="file_id"]/value)[1]', 'int') , [io_mode] = [xe].[x].value('(data[@name="mode"]/text)[1]', 'varchar(20)') , [duration_us] = [xe].[x].value('(data[@name="duration"]/value)[1]', 'bigint') , [size_bytes] = [xe].[x].value('(data[@name="size"]/value)[1]', 'bigint') , [path] = [xe].[x].value('(data[@name="path"]/value)[1]', 'nvarchar(260)') FROM @target_data.nodes('/RingBufferTarget/event') AS [xe]([x]) ) SELECT [DatabaseName] = [d].[name] , [FileName] = [mf].[name] , [evt].[event_name] , [evt].[io_mode] , [duration_ms] = [evt].[duration_us] / 1000.0 , [size_kb] = [evt].[size_bytes] / 1024.0 , [evt].[path] , [evt].[event_time] FROM [evt] LEFT JOIN [sys].[databases] AS [d] ON [evt].[database_id] = [d].[database_id] LEFT JOIN [sys].[master_files] AS [mf] ON [evt].[database_id] = [mf].[database_id] AND [evt].[file_id] = [mf].[file_id] ORDER BY [evt].[duration_us] DESC; |
Note the unit conversion. The captured duration is microseconds; dividing by 1000 gives milliseconds, the unit everyone actually talks about when discussing storage latency. Sorting by the raw microsecond value puts the worst offenders on top:
|
1 2 3 4 5 6 |
DatabaseName FileName event_name io_mode duration_ms size_kb path ------------ ------------- -------------------- ------- ----------- ------- ---------------------- SalesDB SalesDB_data file_read_completed Contig 1842.6 512.0 S:\Data\SalesDB.mdf SalesDB SalesDB_data file_read_completed Scatter 934.1 64.0 S:\Data\SalesDB.mdf tempdb tempdev file_write_completed Contig 612.7 256.0 T:\tempdb\tempdev.ndf SalesDB SalesDB_log file_write_completed Contig 488.3 4.0 L:\Log\SalesDB.ldf |
That is a different and more actionable picture than an average. A 1.8-second read against the SalesDB data file names the database, the file, and the moment, so you can line it up against what else was running, a backup, an index rebuild, a noisy neighbour on shared storage. The tempdb write near the top points at spill or version-store pressure. None of this is visible in a latency average; all of it falls out of capturing the individual slow operations.
Turn It Off When You Are Done
Unlike the deadlock, blocked process, and error sessions, which are cheap enough to leave running permanently, this one is a diagnostic you turn on to investigate a specific complaint and turn off afterward. Even filtered, file I/O events are high frequency, and there is no reason to pay for the session once you have your answer.
|
1 2 |
ALTER EVENT SESSION [FileIO_filtered_ringbuffer] ON SERVER STATE = STOP; DROP EVENT SESSION [FileIO_filtered_ringbuffer] ON SERVER; |
Caveats
- Duration is microseconds. Both the predicate and the captured value are in microseconds. Filtering on
> 100when you meant 100 ms would capture essentially everything. 100 ms is100000. - The filter is not optional. Without the duration predicate this session captures all file I/O on the instance. Never run these events unfiltered on a busy server.
- This is a sampling tool.
ALLOW_MULTIPLE_EVENT_LOSSmeans events can be dropped under load by design. Do not use this to audit every I/O; use it to find the slow ones. - It is a session-on, session-off diagnostic. Stop and drop it when the investigation is over. The cheap, always-on sessions in this series are the deadlock, blocked process, and error ones, not this.
- Pair it with the file stats DMV.
sys.dm_io_virtual_file_statsgives you the averages and totals; this session gives you the individual spikes. Use them together: the DMV to spot which file is slow on average, this session to see the shape of the slowness.
The Takeaway, and the Series
File I/O latency is the case where the filter is not a nicety but the whole point. Capture file_read_completed and file_write_completed with a duration predicate, shred the ring buffer, and join to sys.master_files, and a vague “storage was slow” turns into a ranked list of the exact operations that stalled, named down to the file and the millisecond. Turn it on to investigate, turn it off when you are done.
That closes out the series. Across five posts the same handful of moves kept coming back: define a session that captures exactly the event you need, filter at the source so you keep signal and discard noise, persist the ring buffer into a table when you want history, and shred the XML into columns you can group and rank. The events change, deadlocks, blocking, errors, the system_health firehose, file I/O, but the pattern does not. Once it is muscle memory, Extended Events stops being the intimidating replacement for Profiler and becomes the first thing you reach for.
Which of these will you set up first, or what would you add to the list? I would like to hear how you use Extended Events. Find me on Bluesky or LinkedIn.
For more on shredding a ring buffer target specifically, see Reading the ring buffer target, which goes through the XML in more detail than there was room for here.
More in this series
- Part 1: From deadlock graph to repeat offender
- Part 2: Blocked process reports, from capture to root cause
- Part 3: A lightweight error audit with Extended Events
- Part 4: Mining the system_health session you already have
- Part 5: Catching slow file I/O with a filtered session (this post)
References
- Extended Events – Microsoft Learn. The file_read_completed and file_write_completed events and the duration, size, and path fields they carry. ↩
- sys.master_files (Transact-SQL) – Microsoft Learn. Joining database_id and file_id to name the physical file behind an I/O event. ↩