I have a virtual SQL Server 2016 SP2 CU2 with SAN storage. TempDB has 8 files. I know it is recommended to put TempDB on SSD but TempDB is hardly used so spinning disks are cheaper.
I've noticed that sometimes their is write latency on all my TempDB files of approx 200ms. I checked this using a snapshot on
sys.dm_io_virtual_file_stats and calculated
The first thing I did was look at
sys.dm_exec_query_stats to check if there was a query with high number of spills but no such query. Next I wrote an extended event to look if there where queries executed on tempdb but also this returned nothing.
So where does the write latency come from? I decided to track the
file_write_completed event on tempdb. Here I saw that on moment of the latency that session 22 wrote something with a size of 8192 (don't know the unit) to all files of tempdb. In
sys.dm_exec_sessions the last command of this session was 'RESOURCE MONITOR'.
The first thing I did was checking
sys.dm_os_ring_buffers with following query:
SELECT EventTime, record.value('(/Record/ResourceMonitor/Notification)', 'varchar(max)') as [Type], record.value('(/Record/ResourceMonitor/IndicatorsProcess)', 'int') as [IndicatorsProcess], record.value('(/Record/ResourceMonitor/IndicatorsSystem)', 'int') as [IndicatorsSystem], record.value('(/Record/MemoryRecord/AvailablePhysicalMemory)', 'bigint')/1024. AS [Avail Phys Mem, MB], record.value('(/Record/MemoryRecord/AvailableVirtualAddressSpace)', 'bigint') AS [Avail VAS, Kb] FROM ( SELECT DATEADD (ss, (-1 * ((cpu_ticks / CONVERT (float, ( cpu_ticks / ms_ticks ))) - [timestamp])/1000), GETDATE()) AS EventTime, CONVERT (xml, record) AS record FROM sys.dm_os_ring_buffers CROSS JOIN sys.dm_os_sys_info WHERE ring_buffer_type = 'RING_BUFFER_RESOURCE_MONITOR') AS tab ORDER BY EventTime DESC;
But again the result of the query didn't match with the moment of latency.
I also monitored the tempdb-drive with perfmon, using the counters 'Avg. Disk sec/Write' and 'Current Disk Queue Length'. On moment of latency the latency was 6ms and the queue length was 18.
I ran CrystalDiskMark and this is the avg result of multiple runs:
╔═════════════╦═══════════╦═════════╦══════════╦═══════╗ ║ ║ seq Q32T1 ║ 4k q8T8 ║ 4K Q32T1 ║ 4Q1T1 ║ ╠═════════════╬═══════════╬═════════╬══════════╬═══════╣ ║ Read(MB/s) ║ 1596,57 ║ 505,77 ║ 336,27 ║ 20,94 ║ ║ Write(MB/s) ║ 591,01 ║ 127,6 ║ 87,87 ║ 2,74 ║ ╚═════════════╩═══════════╩═════════╩══════════╩═══════╝
After some extended research I discovered that on moment of latency the lazy writer process starts flushing pages to disk. If I understand correctly, SQL Server removes the least used pages (dirty and clean) from the buffer pool when memory is needed.
So If above is correct, I should see high number of physical reads at moment of latency, this I will investigate further.
Also at moment of latency there are no checkpoints running.
This is my conclusion so far:
- Resource Monitor is writing to Tempdb (detected with extended events, what/why is written I don't know)
- Lazy Writer process is flushing pages from bufferpool because memory is needed. (I don't think this can cause write latency on Tempdb)
All this looks like signs of memory pressure to me. But what I don't understand is why is this causing write latency on Tempdb? What can I do to investigate this problem further?