Използване на причинно-следствената връзка за разбиране на изпълнението на заявка

Когато сте дълбоко ангажирани с отстраняването на проблем в SQL Server, понякога се оказвате, че искате да знаете точния ред, в който се изпълняват заявките. Виждам това при по-сложни съхранени процедури, които съдържат слоеве от логика, или в сценарии, при които има много излишен код. Разширените събития са естествен избор тук, тъй като обикновено се използва за улавяне на информация за изпълнението на заявка. Често можете да използвате session_id и времевата марка, за да разберете реда на събитията, но има опция за сесия за XE, която е още по-надеждна:Проследяване на причинно-следствената връзка.

Когато активирате Track Causality за сесия, той добавя GUID и пореден номер към всяко събитие, които след това можете да използвате, за да преминете през реда, в който са възникнали събитията. Разходите са минимални и могат значително да спестят време в много сценарии за отстраняване на неизправности.

Настройване

Използвайки базата данни WideWorldImporters, ще създадем съхранена процедура, която да използваме:

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

След това ще създадем сесия за събитие:

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
);

Ние също така ще изпълняваме ad-hoc заявки, така че улавяме както sp_statement_completed (изявления, завършени в рамките на съхранена процедура), така и sql_statement_completed (завършени оператори, които не са в рамките на съхранена процедура). Имайте предвид, че опцията TRACK_CAUSALITY за сесията е настроена на ON. Отново тази настройка е специфична за сесията на събитието и трябва да бъде активирана, преди да я стартирате. Не можете да активирате настройката в движение, например можете да добавяте или премахвате събития и цели, докато сесията е в ход.

За да стартирате сесията на събитието през потребителския интерфейс, просто щракнете с десния бутон върху нея и изберете Стартиране на сесията.

Тестване

В рамките на Management Studio ще изпълним следния код:

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';

Ето нашия XE изход:

Обърнете внимание, че първата изпълнена заявка, която е маркирана, е SELECT @@SPID и има GUID от FDCCB1CF-CA55-48AA-8FBA-7F5EBF870674. Не изпълнихме тази заявка, тя се случи на заден план и въпреки че сесията XE е настроена да филтрира системни заявки, тази – по някаква причина – все още се улавя.

Следващите четири реда представляват кода, който всъщност изпълнихме. Има двете заявки от съхранената процедура, самата съхранена процедура и след това нашата ad-hoc заявка. Всички имат един и същ GUID, ACBFFD99-2400-4AFF-A33F-351821667B24. До GUID е идентификаторът на последователността (seq), а заявките са номерирани от едно до четири.

В нашия пример не използвахме GO, за да разделим изявленията на различни партиди. Забележете как изходът се променя, когато направим това:

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

Все още имаме същия брой общи редове, но сега имаме три GUID. Една за SELECT @@SPID (E8D136B8-092F-439D-84D6-D4EF794AE753), една за трите заявки, представляващи съхранената процедура (F962B9A4-0665-4802-9E6C-B217634D8787), и една за DDA the56query (56) -9702-4DE5-8467-8D7CF55B5D80).

Това най-вероятно ще видите, когато разглеждате данни от приложението си, но зависи от това как работи приложението. Ако използва пул на връзки и връзките се нулират редовно (което се очаква), тогава всяка връзка ще има собствен GUID.
Можете да го създадете отново, като използвате примерния код на PowerShell по-долу:

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();
}

Ето пример за изхода на разширени събития, след като оставите кода да работи за малко:

Има четири различни GUID за нашите пет изявления и ако погледнете кода по-горе, ще видите, че са направени четири различни връзки. Ако промените сесията на събитието, за да включи събитието rpc_completed, можете да видите записи с exec sp_reset_connection.
Вашият XE изход ще зависи от вашия код и вашето приложение; Първоначално споменах, че това е полезно при отстраняване на по-сложни съхранени процедури. Помислете за следния пример:

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

Тук имаме две съхранени процедури, usp_TransctionInfo и usp_GetFullCustomerInfo, които се извикват от друга съхранена процедура, usp_GetCustomerData. Не е необичайно да видите това или дори да видите допълнителни нива на гнездене със съхранени процедури. Ако изпълним usp_GetCustomerData от Management Studio, виждаме следното:

EXEC [Sales].[usp_GetCustomerData] 981;

Тук всички изпълнения са се случили на един и същ GUID, BF54CD8F-08AF-4694-A718-D0C47DBB9593, и можем да видим реда на изпълнение на заявката от едно до осем, използвайки колоната seq. В случаите, когато има няколко извикани съхранени процедури, не е необичайно стойността на идентификатора на последователността да достига до стотици или хиляди.

И накрая, в случай, че разглеждате изпълнението на заявка и сте включили Проследяване на причинно-следствената връзка и откриете заявка с лоша ефективност – тъй като сте сортирали изхода въз основа на продължителност или някакъв друг показател, имайте предвид, че можете да намерите другия заявки чрез групиране по GUID:

Резултатът е сортиран по продължителност (най-високата стойност е оградена в червено) и аз го маркирах (в лилаво) с помощта на бутона Превключване на отметка. Ако искаме да видим другите заявки за GUID, групирайте по GUID (Щракнете с десния бутон върху името на колоната в горната част, след това изберете Групиране по тази колона) и след това използвайте бутона Next Bookmark, за да се върнете към нашата заявка:

Сега можем да видим всички заявки, изпълнени в рамките на една и съща връзка и в реда на изпълнение.

Заключение

Опцията Проследяване на причинно-следствената връзка може да бъде изключително полезна при отстраняване на неизправности в производителността на заявката и при опит да се разбере реда на събитията в SQL Server. Също така е полезно, когато настройвате сесия на събитие, която използва целта на pair_matching, за да ви помогне да сте сигурни, че отговаряте на правилното поле/действие и намирате правилното несравнимо събитие. Отново, това е настройка на ниво сесия, така че трябва да се приложи преди да започнете сесията на събитието. За сесия, която се изпълнява, спрете сесията на събитието, активирайте опцията и след това я стартирайте отново.