Použití sledování kauzality k pochopení provádění dotazu

Když jste hluboce zapojeni do odstraňování problémů na serveru SQL Server, někdy se přistihnete, že chcete znát přesné pořadí, ve kterém se dotazy spouštěly. Vidím to u složitějších uložených procedur, které obsahují vrstvy logiky, nebo ve scénářích, kde je spousta nadbytečného kódu. Rozšířené události jsou zde přirozenou volbou, protože se obvykle používají k zachycení informací o provádění dotazu. K pochopení pořadí událostí můžete často použít session_id a časové razítko, ale pro XE existuje možnost relace, která je ještě spolehlivější:Track Causality.

Když pro relaci povolíte sledování příčinnosti, přidá ke každé události GUID a pořadové číslo, které pak můžete použít k procházení pořadí, ve kterém události nastaly. Režie je minimální a v mnoha scénářích odstraňování problémů může významně ušetřit čas.

Nastavit

Pomocí databáze WideWorldImporters vytvoříme uloženou proceduru, kterou použijeme:

DROP PROCEDURE IF EXISTS [Sales].[usp_CustomerTransactionInfo];
GO
 
CREATE PROCEDURE [Sales].[usp_CustomerTransactionInfo]
	@CustomerID INT
AS	
 
	SELECT [CustomerID], SUM([AmountExcludingTax])
	FROM [Sales].[CustomerTransactions]
	WHERE [CustomerID] = @CustomerID
	GROUP BY [CustomerID];
 
	SELECT COUNT([OrderID])
	FROM [Sales].[Orders]
	WHERE [CustomerID] = @CustomerID
GO

Poté vytvoříme relaci události:

CREATE EVENT SESSION [TrackQueries] ON SERVER 
ADD EVENT sqlserver.sp_statement_completed(
    WHERE ([sqlserver].[is_system]=(0))),
ADD EVENT sqlserver.sql_statement_completed(
    WHERE ([sqlserver].[is_system]=(0)))
ADD TARGET package0.event_file
(
  SET filename=N'C:\temp\TrackQueries',max_file_size=(256)
)
WITH
(
  MAX_MEMORY = 4096 KB, 
  EVENT_RETENTION_MODE = ALLOW_SINGLE_EVENT_LOSS,
  MAX_DISPATCH_LATENCY = 30 SECONDS,
  MAX_EVENT_SIZE = 0 KB,
  MEMORY_PARTITION_MODE = NONE,
  TRACK_CAUSALITY = ON,
  STARTUP_STATE = OFF
);

Chystáme se také spouštět dotazy ad-hoc, takže zachycujeme jak sp_statement_completed (příkazy dokončené v rámci uložené procedury), tak sql_statement_completed (dokončené příkazy, které nejsou v rámci uložené procedury). Všimněte si, že možnost TRACK_CAUSALITY pro relaci je nastavena na ON. Toto nastavení je opět specifické pro relaci události a musí být povoleno před jejím spuštěním. Toto nastavení nemůžete aktivovat za běhu, jako když můžete přidávat nebo odebírat události a cíle, když relace běží.

Chcete-li zahájit relaci události prostřednictvím uživatelského rozhraní, stačí na ni kliknout pravým tlačítkem a vybrat možnost Spustit relaci.

Testování

V Management Studio spustíme následující kód:

EXEC [Sales].[usp_CustomerTransactionInfo] 490;
 
SELECT [c].[CustomerID], [c].[CustomerName], [p].[FullName], [o].[OrderID]
    FROM [Application].[People] [p]
    JOIN [Sales].[Customers] [c] ON [p].[PersonID] = [c].[PrimaryContactPersonID]
    JOIN [Sales].[Orders] [o] ON [c].[CustomerID] = [o].[CustomerID]
    WHERE [p].[FullName] = 'Naseem Radan';

Zde je náš výstup XE:

Všimněte si, že první provedený dotaz, který je zvýrazněn, je SELECT @@SPID a má GUID FDCCB1CF-CA55-48AA-8FBA-7F5EBF870674. Tento dotaz jsme neprovedli, došlo k němu na pozadí, a přestože je relace XE nastavena tak, aby odfiltrovala systémové dotazy, tento – z jakéhokoli důvodu – je stále zachycen.

Následující čtyři řádky představují kód, který jsme skutečně spustili. Jsou zde dva dotazy z uložené procedury, samotná uložená procedura a pak náš ad-hoc dotaz. Všechny mají stejné GUID, ACBFFD99-2400-4AFF-A33F-351821667B24. Vedle GUID je id sekvence (seq) a dotazy jsou očíslovány jedna až čtyři.

V našem příkladu jsme nepoužili GO k oddělení výpisů do různých dávek. Všimněte si, jak se výstup změní, když to uděláme:

EXEC [Sales].[usp_CustomerTransactionInfo] 490;
GO
 
SELECT [c].[CustomerID], [c].[CustomerName], [p].[FullName], [o].[OrderID]
    FROM [Application].[People] [p]
    JOIN [Sales].[Customers] [c] ON [p].[PersonID] = [c].[PrimaryContactPersonID]
    JOIN [Sales].[Orders] [o] ON [c].[CustomerID] = [o].[CustomerID]
    WHERE [p].[FullName] = 'Naseem Radan';
GO

Stále máme stejný počet celkových řádků, ale nyní máme tři GUID. Jeden pro SELECT @@SPID (E8D136B8-092F-439D-84D6-D4EF794AE753), jeden pro tři dotazy představující uloženou proceduru (F962B9A4-0665-4802-9E6C-B217634D8787) a jeden dotaz6634D8787 -9702-4DE5-8467-8D7CF55B5D80).

To je to, co s největší pravděpodobností uvidíte, když se díváte na data z vaší aplikace, ale záleží na tom, jak aplikace funguje. Pokud používá sdružování připojení a připojení jsou pravidelně resetována (což se očekává), každé připojení bude mít svůj vlastní GUID.
Můžete jej znovu vytvořit pomocí ukázkového kódu PowerShell níže:

while(1 -eq 1)
{
 
    $SqlConn = New-Object System.Data.SqlClient.SqlConnection;
    $SqlConn.ConnectionString = "Data Source=Hedwig\SQL2017;Initial Catalog=WideWorldImporters;Integrated Security=True;Application Name = MyCoolApp";
    $SQLConn.Open()
    $SqlCmd = $SqlConn.CreateCommand();
 
    $SqlCmd.CommandText = "SELECT TOP 1 CustomerID FROM Sales.Customers ORDER BY NEWID();"
    $SqlCmd.CommandType = [System.Data.CommandType]::Text;
 
    $SqlReader = $SqlCmd.ExecuteReader();
    $Results = New-Object System.Collections.ArrayList;
 
    while ($SqlReader.Read())
    {
	    $Results.Add($SqlReader.GetSqlInt32(0)) | Out-Null;
    }
 
    $SqlReader.Close();
 
 
	$Value = Get-Random -InputObject $Results;
 
    $SqlCmd = $SqlConn.CreateCommand();
	$SqlCmd.CommandText = "Sales.usp_CustomerTransactionInfo"
	$SqlCmd.CommandType = [System.Data.CommandType]::StoredProcedure;
 
	$SqlParameter = $SqlCmd.Parameters.AddWithValue("@CustomerID", $Value);
	$SqlParameter.SqlDbType = [System.Data.SqlDbType]::Int;
 
	$SqlCmd.ExecuteNonQuery();
 
    $SqlConn.Close();
 
    $Names = New-Object System.Collections.Generic.List``1[System.String]
 
    $SqlConn = New-Object System.Data.SqlClient.SqlConnection
    $SqlConn.ConnectionString = "Data Source=Hedwig\SQL2017;Initial Catalog=WideWorldImporters;User Id=aw_webuser;Password=12345;Application Name=AdventureWorks Online Ordering;Workstation ID=AWWEB01";
    $SqlConn.Open();
 
    $SqlCmd = $SqlConn.CreateCommand();
    $SqlCmd.CommandText = "SELECT FullName FROM Application.People ORDER BY NEWID();";
    $dr = $SqlCmd.ExecuteReader();
 
    while($dr.Read())
    {
          $Names.Add($dr.GetString(0));
    }
 
    $SqlConn.Close();
 
    $name = Get-Random -InputObject $Names;
 
    $query = [String]::Format("SELECT [c].[CustomerID], [c].[CustomerName], [p].[FullName], [o].[OrderID]
    FROM [Application].[People] [p]
    JOIN [Sales].[Customers] [c] ON [p].[PersonID] = [c].[PrimaryContactPersonID]
    JOIN [Sales].[Orders] [o] ON [c].[CustomerID] = [o].[CustomerID]
    WHERE [p].[FullName] = '{0}';", $name);
 
    $SqlConn = New-Object System.Data.SqlClient.SqlConnection
    $SqlConn.ConnectionString = "Data Source=Hedwig\SQL2017;Initial Catalog=WideWorldImporters;User Id=aw_webuser;Password=12345;Application Name=AdventureWorks Online Ordering;Workstation ID=AWWEB01";
    $SqlConn.Open();
 
    $SqlCmd = $sqlconnection.CreateCommand();
    $SqlCmd.CommandText = $query 
 
    $SqlCmd.ExecuteNonQuery();
 
    $SqlConn.Close();
}

Zde je příklad výstupu rozšířených událostí poté, co se kód chvíli nechá běžet:

Pro našich pět příkazů existují čtyři různá GUID, a když se podíváte na kód výše, uvidíte, že existují čtyři různá připojení. Pokud změníte relaci události tak, aby zahrnovala událost rpc_completed, uvidíte položky s exec sp_reset_connection.
Váš výstup XE bude záviset na vašem kódu a vaší aplikaci; Původně jsem zmínil, že to bylo užitečné při řešení problémů se složitějšími uloženými procedurami. Zvažte následující příklad:

DROP PROCEDURE IF EXISTS [Sales].[usp_CustomerTransactionInfo];
GO
 
CREATE PROCEDURE [Sales].[usp_CustomerTransactionInfo]
	@CustomerID INT
AS	
 
	SELECT [CustomerID], SUM([AmountExcludingTax])
	FROM [Sales].[CustomerTransactions]
	WHERE [CustomerID] = @CustomerID
	GROUP BY [CustomerID];
 
	SELECT COUNT([OrderID])
	FROM [Sales].[Orders]
	WHERE [CustomerID] = @CustomerID
 
GO
 
DROP PROCEDURE IF EXISTS [Sales].[usp_GetFullCustomerInfo];
GO
 
CREATE PROCEDURE [Sales].[usp_GetFullCustomerInfo]
	@CustomerID INT
AS	
 
	SELECT 
		[o].[CustomerID], 
		[o].[OrderDate], 
		[ol].[StockItemID], 
		[ol].[Quantity],
		[ol].[UnitPrice]
	FROM [Sales].[Orders] [o]
	JOIN [Sales].[OrderLines] [ol] 
		ON [o].[OrderID] = [ol].[OrderID]
	WHERE [o].[CustomerID] = @CustomerID
	ORDER BY [o].[OrderDate] DESC;
 
	SELECT
		[o].[CustomerID], 
		SUM([ol].[Quantity]*[ol].[UnitPrice])
	FROM [Sales].[Orders] [o]
	JOIN [Sales].[OrderLines] [ol] 
		ON [o].[OrderID] = [ol].[OrderID]
	WHERE [o].[CustomerID] = @CustomerID
	GROUP BY [o].[CustomerID]
	ORDER BY [o].[CustomerID] ASC;
GO
 
DROP PROCEDURE IF EXISTS [Sales].[usp_GetCustomerData];
GO
 
CREATE PROCEDURE [Sales].[usp_GetCustomerData]
	@CustomerID INT
AS
 
BEGIN
 
	SELECT *
	FROM [Sales].[Customers]
 
	EXEC [Sales].[usp_CustomerTransactionInfo] @CustomerID
 
	EXEC [Sales].[usp_GetFullCustomerInfo] @CustomerID
 
END
GO

Zde máme dvě uložené procedury, usp_TransctionInfo a usp_GetFullCustomerInfo, které jsou volány jinou uloženou procedurou, usp_GetCustomerData. Není neobvyklé to vidět nebo dokonce vidět další úrovně vnoření s uloženými procedurami. Pokud spustíme usp_GetCustomerData z Management Studio, uvidíme následující:

EXEC [Sales].[usp_GetCustomerData] 981;

Zde došlo ke všem spuštěním na stejném GUID, BF54CD8F-08AF-4694-A718-D0C47DBB9593, a pomocí sloupce seq můžeme vidět pořadí provádění dotazu od jedné do osmi. V případech, kdy je voláno více uložených procedur, není neobvyklé, že se hodnota sekvence id dostane do stovek nebo tisíců.

A konečně, v případě, kdy se díváte na provádění dotazu a zahrnuli jste sledování příčinnosti a najdete dotaz, který má nízkou výkonnost – protože jste výstup seřadili podle délky trvání nebo nějaké jiné metriky, mějte na paměti, že můžete najít další dotazy seskupením podle GUID:

Výstup byl seřazen podle trvání (nejvyšší hodnota zakroužkována červeně) a přidal jsem jej do záložek (fialově) pomocí tlačítka Přepnout záložku. Pokud chceme vidět ostatní dotazy na GUID, seskupte je podle GUID (klikněte pravým tlačítkem na název sloupce nahoře, vyberte Seskupit podle tohoto sloupce) a poté se pomocí tlačítka Další záložka vraťte k našemu dotazu:

Nyní můžeme vidět všechny dotazy, které byly provedeny v rámci stejného připojení, a v provedeném pořadí.

Závěr

Možnost Track Causality může být nesmírně užitečná při řešení problémů s výkonem dotazů a při pokusu o pochopení pořadí událostí na serveru SQL Server. Je to také užitečné při nastavování relace události, která používá cíl pair_matching, aby se zajistilo, že se shodujete ve správném poli/akci a najdete správnou nepřiřazenou událost. Opět se jedná o nastavení na úrovni relace, takže jej musíte použít před zahájením relace události. U probíhající relace zastavte relaci události, povolte možnost a poté ji znovu spusťte.