Vad virtuella filstater gör och inte gör, berättar om I/O-latens

Bakgrund

En av de första sakerna jag tittar på när jag felsöker ett prestandaproblem är väntestatistik via sys.dm_os_wait_stats DMV. För att se vad SQL Server väntar på använder jag frågan från Glenn Berrys nuvarande uppsättning SQL Server Diagnostic Queries. Beroende på resultatet börjar jag gräva i specifika områden inom SQL Server.

Som ett exempel, om jag ser höga CXPACKET-väntningar kontrollerar jag antalet kärnor på servern, antalet NUMA-noder och värdena för maxgraden av parallellitet och kostnadströskeln för parallellism. Detta är bakgrundsinformation som jag använder för att förstå konfigurationen. Innan jag ens överväger att göra några ändringar samlar jag på mig mer kvantitativ data, eftersom ett system med CXPACKET väntar inte nödvändigtvis har en felaktig inställning för maximal grad av parallellitet.

På liknande sätt har ett system som har höga väntetider för I/O-relaterade väntetyper som PAGEIOLATCH_XX, WRITELOG och IO_COMPLETION inte nödvändigtvis ett sämre lagringsundersystem. När jag ser I/O-relaterade väntetyper när toppen väntar, vill jag genast förstå mer om den underliggande lagringen. Är det direktansluten lagring eller ett SAN? Vad är RAID-nivån, hur många diskar finns det i arrayen och vilken hastighet har diskarna? Jag vill också veta om andra filer eller databaser delar lagringen. Och även om det är viktigt att förstå konfigurationen, är ett logiskt nästa steg att titta på virtuell filstatistik via sys.dm_io_virtual_file_stats DMV.

Denna DMV, som introducerades i SQL Server 2005, är en ersättning för funktionen fn_virtualfilestats som de av er som körde på SQL Server 2000 och tidigare förmodligen känner till och älskar. DMV innehåller kumulativ I/O-information för varje databasfil, men data återställs vid omstart av instansen, när en databas stängs, tas offline, kopplas bort och återansluts, etc. Det är viktigt att förstå att statistikdata för virtuella filer inte är representativa för nuvarande prestanda – det är en ögonblicksbild som är en aggregering av I/O-data sedan den senaste rensningen av en av de tidigare nämnda händelserna. Även om informationen inte är punkt-i-tid, kan den fortfarande vara användbar. Om de högsta väntetiderna på en instans är I/O-relaterade, men den genomsnittliga väntetiden är mindre än 10 ms, är lagring förmodligen inte ett problem – men att korrelera utdata med det du ser i sys.dm_io_virtual_stats är fortfarande värt att bekräfta lågt latenser. Dessutom, även om du ser höga latenser i sys.dm_io_virtual_stats, har du fortfarande inte bevisat att lagring är ett problem.

Inställningen

För att titta på virtuell filstatistik satte jag upp två kopior av databasen AdventureWorks2012, som du kan ladda ner från Codeplex. För det första exemplaret, hädanefter känt som EX_AdventureWorks2012, körde jag Jonathan Kehayias skript för att utöka tabellerna Sales.SalesOrderHeader och Sales.SalesOrderDetail till 1,2 miljoner respektive 4,9 miljoner rader. För den andra databasen, BIG_AdventureWorks2012, använde jag skriptet från mitt tidigare partitioneringsinlägg för att skapa en kopia av tabellen Sales.SalesOrderHeader med 123 miljoner rader. Båda databaserna lagrades på en extern USB-enhet (Seagate Slim 500GB), med tempdb på min lokala disk (SSD).

Innan jag testade skapade jag fyra anpassade lagrade procedurer i varje databas (Create_Custom_SPs.zip), som skulle fungera som min "normala" arbetsbelastning. Min testprocess var följande för varje databas:

1. Starta om instansen.
2. Fånga statistik för virtuella filer.
3. Kör den "normala" arbetsbelastningen i två minuter (procedurer anropas upprepade gånger via ett PowerShell-skript).
4. Fånga statistik för virtuella filer.
5. Bygg om alla index för lämplig(a) försäljningsordertabell(er).
6. Fånga statistik för virtuella filer.

Datan

För att fånga virtuell filstatistik skapade jag en tabell för historisk information och använde sedan en variant av Jimmy Mays fråga från hans DMV All-Stars-skript för ögonblicksbilden:

USE [msdb];
GO
 
CREATE TABLE [dbo].[SQLskills_FileLatency]
(
	[RowID] [INT] IDENTITY(1,1) NOT NULL,
	[CaptureID] [INT] NOT NULL,
	[CaptureDate] [DATETIME2](7) NULL,
	[ReadLatency] [BIGINT] NULL,
	[WriteLatency] [BIGINT] NULL,
	[Latency] [BIGINT] NULL,
	[AvgBPerRead] [BIGINT] NULL,
	[AvgBPerWrite] [BIGINT] NULL,
	[AvgBPerTransfer] [BIGINT] NULL,
	[Drive] [NVARCHAR](2) NULL,
	[DB] [NVARCHAR](128) NULL,
	[database_id] [SMALLINT] NOT NULL,
	[file_id] [SMALLINT] NOT NULL,
	[sample_ms] [INT] NOT NULL,
	[num_of_reads] [BIGINT] NOT NULL,
	[num_of_bytes_read] [BIGINT] NOT NULL,
	[io_stall_read_ms] [BIGINT] NOT NULL,
	[num_of_writes] [BIGINT] NOT NULL,
	[num_of_bytes_written] [BIGINT] NOT NULL,
	[io_stall_write_ms] [BIGINT] NOT NULL,
	[io_stall] [BIGINT] NOT NULL,
	[size_on_disk_MB] [NUMERIC](25, 6) NULL,
	[file_handle] [VARBINARY](8) NOT NULL,
	[physical_name] [NVARCHAR](260) NOT NULL
) ON [PRIMARY];
GO
 
CREATE CLUSTERED INDEX CI_SQLskills_FileLatency ON [dbo].[SQLskills_FileLatency] ([CaptureDate], [RowID]);
 
CREATE NONCLUSTERED INDEX NCI_SQLskills_FileLatency ON [dbo].[SQLskills_FileLatency] ([CaptureID]);
 
DECLARE @CaptureID INT;
 
SELECT @CaptureID = MAX(CaptureID) FROM [msdb].[dbo].[SQLskills_FileLatency];
 
PRINT (@CaptureID);
 
IF @CaptureID IS NULL	
BEGIN
  SET @CaptureID = 1;
END
ELSE
BEGIN
  SET @CaptureID = @CaptureID + 1;
END  
 
INSERT INTO [msdb].[dbo].[SQLskills_FileLatency] 
(
	[CaptureID],
	[CaptureDate],
	[ReadLatency],
	[WriteLatency],
	[Latency],
	[AvgBPerRead],
	[AvgBPerWrite],
	[AvgBPerTransfer],
	[Drive],
	[DB],
	[database_id],
	[file_id],
	[sample_ms],
	[num_of_reads],
	[num_of_bytes_read],
	[io_stall_read_ms],
	[num_of_writes],
	[num_of_bytes_written],
	[io_stall_write_ms],
	[io_stall],
	[size_on_disk_MB],
	[file_handle],
	[physical_name]
)
SELECT 
    --virtual file latency
	@CaptureID,
	GETDATE(),
	CASE 
		WHEN [num_of_reads] = 0 
			THEN 0 
		ELSE ([io_stall_read_ms]/[num_of_reads]) 
	END [ReadLatency],
	CASE 
		WHEN [io_stall_write_ms] = 0 
			THEN 0 
		ELSE ([io_stall_write_ms]/[num_of_writes]) 
	END [WriteLatency],
	CASE 
		WHEN ([num_of_reads] = 0 AND [num_of_writes] = 0)
             THEN 0 
		ELSE ([io_stall]/([num_of_reads] + [num_of_writes])) 
	END [Latency],
	--avg bytes per IOP
	CASE 
		WHEN [num_of_reads] = 0 
			THEN 0 
		ELSE ([num_of_bytes_read]/[num_of_reads]) 
	END [AvgBPerRead],
	CASE 
		WHEN [io_stall_write_ms] = 0 
			THEN 0 
		ELSE ([num_of_bytes_written]/[num_of_writes]) 
	END [AvgBPerWrite],
	CASE 
		WHEN ([num_of_reads] = 0 AND [num_of_writes] = 0)
			THEN 0 
		ELSE (([num_of_bytes_read] + [num_of_bytes_written])/([num_of_reads] + [num_of_writes])) 
	END [AvgBPerTransfer],
	LEFT([mf].[physical_name],2) [Drive],
	DB_NAME([vfs].[database_id]) [DB],
	[vfs].[database_id],
	[vfs].[file_id],
	[vfs].[sample_ms],
	[vfs].[num_of_reads],
	[vfs].[num_of_bytes_read],
	[vfs].[io_stall_read_ms],
	[vfs].[num_of_writes],
	[vfs].[num_of_bytes_written],
	[vfs].[io_stall_write_ms],
	[vfs].[io_stall],
	[vfs].[size_on_disk_bytes]/1024/1024. [size_on_disk_MB],
	[vfs].[file_handle],
	[mf].[physical_name]
FROM [sys].[dm_io_virtual_file_stats](NULL,NULL) AS vfs
JOIN [sys].[master_files] [mf] 
    ON [vfs].[database_id] = [mf].[database_id] 
    AND [vfs].[file_id] = [mf].[file_id]
ORDER BY [Latency] DESC;

Jag startade om instansen och fångade sedan omedelbart filstatistik. När jag filtrerade utdata för att bara visa EX_AdventureWorks2012- och tempdb-databasfilerna fångades endast tempdb-data eftersom ingen data hade begärts från EX_AdventureWorks2012-databasen:

Utdata från initial insamling av sys.dm_os_virtual_file_stats

Jag körde sedan den "normala" arbetsbelastningen i två minuter (antalet körningar av varje lagrad procedur varierade något), och efter att den slutförts infångade jag filstatistik igen:

Utdata från sys.dm_os_virtual_file_stats efter normal arbetsbelastning

Vi ser en latens på 57ms för datafilen EX_AdventureWorks2012. Inte idealiskt, men med tiden med min normala arbetsbelastning skulle detta förmodligen jämna ut sig. Det finns minimal latens för tempdb, vilket förväntas eftersom arbetsbelastningen jag körde inte genererar mycket tempdb-aktivitet. Därefter byggde jag om alla index för tabellerna Sales.SalesOrderHeaderEnlarged och Sales.SalesOrderDetailEnlarged:

USE [EX_AdventureWorks2012];
GO
ALTER INDEX ALL ON Sales.SalesOrderHeaderEnlarged REBUILD;
ALTER INDEX ALL ON Sales.SalesOrderDetailEnlarged REBUILD;

Ombyggnationerna tog mindre än en minut och märkte ökningen i läslatens för EX_AdventureWorks2012-datafilen och topparna i skrivfördröjning för EX_AdventureWorks2012-data och loggfiler:

Utdata från sys.dm_os_virtual_file_stats efter ombyggnad av index

Enligt den ögonblicksbilden av filstatistik är latensen hemsk; över 600ms för att skriva! Om jag såg detta värde för ett produktionssystem skulle det vara lätt att omedelbart misstänka problem med lagring. Det är dock också värt att notera att AvgBPerWrite ökade också, och större blockskrivningar tar längre tid att slutföra. AvgBPerWrite-ökningen förväntas för indexåteruppbyggnadsuppgiften.

Förstå att när du tittar på denna information får du inte en fullständig bild. Ett bättre sätt att titta på latenser med hjälp av virtuell filstatistik är att ta ögonblicksbilder och sedan beräkna latens för den förflutna tidsperioden. Skriptet nedan använder till exempel två ögonblicksbilder (nuvarande och tidigare) och beräknar sedan antalet läsningar och skrivningar under den tidsperioden, skillnaden i io_stall_read_ms och io_stall_write_ms värden, och dividerar sedan io_stall_read_ms delta med antal läsningar och io_stall_write_ms med delta antal skrivningar. Med den här metoden beräknar vi hur lång tid SQL Server väntade på I/O för läsning eller skrivning, och dividerar den sedan med antalet läsningar eller skrivningar för att bestämma latens.

DECLARE @CurrentID INT, @PreviousID INT;
SET @CurrentID = 3;
SET @PreviousID = @CurrentID - 1;
 
WITH [p] AS (	SELECT	
				[CaptureDate], 
				[database_id], 
				[file_id], 
				[ReadLatency], 
				[WriteLatency], 
				[num_of_reads], 
				[io_stall_read_ms], 
				[num_of_writes], 
				[io_stall_write_ms]
			FROM [msdb].[dbo].[SQLskills_FileLatency]
			WHERE [CaptureID] = @PreviousID
		)
SELECT	
	[c].[CaptureDate] [CurrentCaptureDate],
	[p].[CaptureDate] [PreviousCaptureDate],
	DATEDIFF(MINUTE, [p].[CaptureDate], [c].[CaptureDate]) [MinBetweenCaptures],
	[c].[DB],
	[c].[physical_name],
	[c].[ReadLatency] [CurrentReadLatency], 
	[p].[ReadLatency] [PreviousReadLatency], 
	[c].[WriteLatency] [CurrentWriteLatency], 
	[p].[WriteLatency] [PreviousWriteLatency],
	[c].[io_stall_read_ms]- [p].[io_stall_read_ms] [delta_io_stall_read],
	[c].[num_of_reads] - [p].[num_of_reads] [delta_num_of_reads],
	[c].[io_stall_write_ms] - [p].[io_stall_write_ms] [delta_io_stall_write],
	[c].[num_of_writes] - [p].[num_of_writes] [delta_num_of_writes],
	CASE
		WHEN ([c].[num_of_reads] - [p].[num_of_reads]) = 0 THEN NULL
		ELSE ([c].[io_stall_read_ms] - [p].[io_stall_read_ms])/([c].[num_of_reads] - [p].[num_of_reads])
	END [IntervalReadLatency],
	CASE
		WHEN ([c].[num_of_writes] - [p].[num_of_writes]) = 0 THEN NULL
		ELSE ([c].[io_stall_write_ms] - [p].[io_stall_write_ms])/([c].[num_of_writes] - [p].[num_of_writes])
	END [IntervalWriteLatency]
FROM [msdb].[dbo].[SQLskills_FileLatency] [c]
JOIN [p] ON [c].[database_id] = [p].[database_id] AND [c].[file_id] = [p].[file_id]
WHERE [c].[CaptureID] = @CurrentID 
AND [c].[database_id] IN (2, 11);

När vi kör detta för att beräkna latens under indexombyggnaden får vi följande:

Latens beräknad från sys.dm_io_virtual_file_stats under ombyggnad av index2_0Adventure för index2_0Adventure för index2_0Adventure. em>