I’ve been watching some Webcasts by Ramesh Meyyappan at SQL Workshops on query performance tuning. This guy is a wizard… inspiring.
Many of his techniques, which he just does like second nature, may require someone to slow things down to really articulate what he does. Sort of like watching an instant replay during a sports event. How do those umpires get it so right (most of the time)? There’s just a huge difference between real-time and the slow-mo, frame-by-frame review.
So here’s my instant replay of one of Ramesh’s techniques… monitoring tempdb to determine if a query is spilling during a sort or JOIN operation. In particular we will do so using one of the SQL Server Dynamic Management (DM) functions, sys.dm_io_virtual_file_stats.
If you prefer to use PROFILER to monitor tempdb for sort spills you can do so simply by turning on the Errors and Warnings Events Selection subcategory.
I also highlighted the Hash Warning event which identifies when SQL Server goes into a hash recursion (bad) or hash bailout (very, very bad) during a hash operations such as a hash join or aggregation.
OK, back to the topic…
According to BoL, our DM function accepts 2 input arguments, the ID of the database and the File ID of the file for the database that we are interested in.
If we’re not exactly sure how to determine those input arguments we can wing it by supplying NULL values for the input.
SELECT * FROM sys.dm_io_virtual_file_stats (NULL, NULL);
The output of this query will give us the file stats for every database file on the SQL instance. Even on my lowly laptop the output is rather daunting if you don’t have any clue about which database is being presented:
When working with DM functions and views there are a few Metadata Functions that will serve to make our life easier. In our case db_name and file_name.
Let’s modify our query to help us figure out which database and file we need to look at:
SELECT DB_NAME(dm.database_id) AS [DB_Name], FILE_NAME(dm.file_id) AS [File_Name], dm.* FROM sys.dm_io_virtual_file_stats (NULL, NULL) dm;
All we did here is add two new columns to figure out which database and file we are interested in. Here’s a snippet of the output:
OK, now we know tempdb is database #2. We also know the data file is 1 (tempdev) and the tempdb log file is 2. Hopefully that is clear from the screen capture above.
(Note: With SQL Server there are always multiple ways to do the same thing. Another way we could have figured out the database and file IDs is with the system stored procedure sp_helpfile. We’ll leave that as an exercise for the reader or perhaps do a small posting on that one later on.)
OK, now we can limit the scope of our query to just return what we want to quantify how much tempdb is being used.
SELECT DB_NAME(dm.database_id) AS [DB_Name], FILE_NAME(dm.file_id) AS [File_Name], num_of_reads, num_of_bytes_read, num_of_writes, num_of_bytes_written FROM sys.dm_io_virtual_file_stats (NULL, NULL) dm WHERE dm.database_id = 2 AND dm.file_id = 1;
Note: This query will work fine but a simpler version follows, that introduces the use of the DB_ID function for the first argument to our DM.
SELECT DB_NAME(dm.database_id) AS [DB_Name], FILE_NAME(dm.file_id) AS [File_Name], num_of_reads, num_of_bytes_read, num_of_writes, num_of_bytes_written FROM sys.dm_io_virtual_file_stats (DB_ID('tempdb'), 1) dm;
So how do we actually use this to validate that tempdb is being used? Simply run the query to capture the file stats data, run a query writes to tempdb, then re-run the DM query.
drop table #demoiostats drop table #tempdcontact DBCC dropcleanbuffers; -- Query 1: Capture a snapshot of the file stats on tempdb -- before any data is written to it. SELECT CURRENT_TIMESTAMP as capture_time, DB_NAME(dm.database_id) AS [DB_Name], FILE_NAME(dm.file_id) AS [File_Name], num_of_reads, num_of_bytes_read, num_of_writes, num_of_bytes_written INTO #demoiostats FROM sys.dm_io_virtual_file_stats (DB_ID('tempdb'), 1) dm; -- Query 2: Force a write to tempdb. In practice we would be more interested -- in queries that are writing to tempdb as a result of a SORT -- or HASH operation. SELECT FirstName, LastName, EmailAddress into #tempdcontact FROM AdventureWorks.Person.Contact; SELECT * from #tempdcontact; -- Query 4: Capture the snapshot AFTER the write to tempdb. INSERT INTO #demoiostats SELECT CURRENT_TIMESTAMP as capture_time, DB_NAME(dm.database_id) AS [DB_Name], FILE_NAME(dm.file_id) AS [File_Name], num_of_reads, num_of_bytes_read, num_of_writes, num_of_bytes_written FROM sys.dm_io_virtual_file_stats (DB_ID('tempdb'), 1) dm; -- Query 5: Compute the total number of reads and writes. SELECT t2.num_of_reads - t1.num_of_reads AS [Total_Num_of_Reads], t2.num_of_bytes_read - t1.num_of_bytes_read AS [Total_Num_of_Bytes_Read], t2.num_of_writes - t1.num_of_writes AS [Total_Num_of_Writes], t2.num_of_bytes_written - t1.num_of_bytes_written AS [Total_Num_of_Bytes_Written] FROM #demoiostats t1 CROSS JOIN #demoiostats t2 WHERE t1.capture_time < t2.capture_time;
To recap the above code:
- Query 1 captures the file stats counters on tempdb to a temp file #demoiostats.
- Query 2 writes to a temp table #tempdcontact. In practice we would be more interested in a spill to tempdb from either a hash or sort physical operator.
- Query 3 does a simple read from the temp table we just created.
- Query 4 captures the file stats AFTER the write and read to and from tempdb.
- Query 5: Finally we take the differences between the two sets of counters we just captured.
Here’s the output of our little test:
What’s interesting is that we have 4 reads and and 171 writes. You might be wondering “Reads and writes of what?”
I ran these tests several times and the results are consistent. We’re doing about 64k per read and 12k per write.
The counts of reads and writes are PHYSICAL reads, or the number of trips to the physical disk. The definition of LOGICAL reads, which is not what this routine returns, is the number of trips data is sent to/from the data cache. This is why I added the DBCC dropcleanbuffers before running the routine. Without clearing the data cache, no increase of read counters would occur because the data would conveniently be sitting in cache.
I found a nice blog post on physical and logical reads by Kasim Wirama. Check it out for additional details.
Conclusion: The dm_io_virtual_file_stats DMV can be very useful to monitor PHYSICAL read and write operations to the tempdb (or any other db). It’s also a useful tool to point out the difference between LOGICAL and PHYSICAL reads. Clearly this tool can be easily used to build optimized queries to avoid spilling to tempdb.
Thanks to Ramesh for providing the lead example to get me thinking about this tool… and the many other posters out there who demonstrate how to really make this tool dance.
Anytime I attempt to post a blog I run the risk of learning something unexpected. In this case it was the distinction between logical and physical reads. We all know it’s there… but probably don’t think about it much.