Verwenden von Track Causality zum Verständnis der Abfrageausführung

Wenn Sie intensiv mit der Behebung eines Problems in SQL Server beschäftigt sind, möchten Sie manchmal die genaue Reihenfolge wissen, in der Abfragen ausgeführt wurden. Ich sehe dies bei komplizierteren gespeicherten Prozeduren, die Logikebenen enthalten, oder in Szenarien, in denen viel redundanter Code vorhanden ist. Erweiterte Ereignisse sind hier eine natürliche Wahl, da sie normalerweise verwendet werden, um Informationen über die Ausführung von Abfragen zu erfassen. Sie können oft session_id und den Zeitstempel verwenden, um die Reihenfolge der Ereignisse zu verstehen, aber es gibt eine Sitzungsoption für XE, die noch zuverlässiger ist:Kausalität verfolgen.

Wenn Sie Kausalität verfolgen für eine Sitzung aktivieren, fügt es jedem Ereignis eine GUID und eine Sequenznummer hinzu, die Sie dann verwenden können, um die Reihenfolge, in der Ereignisse aufgetreten sind, schrittweise durchzugehen. Der Overhead ist minimal und kann in vielen Fehlerbehebungsszenarien eine erhebliche Zeitersparnis darstellen.

Einrichten

Unter Verwendung der WideWorldImporters-Datenbank erstellen wir eine gespeicherte Prozedur zur Verwendung:

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

Dann erstellen wir eine Ereignissitzung:

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

Wir werden auch Ad-hoc-Abfragen ausführen, also erfassen wir sowohl sp_statement_completed (in einer gespeicherten Prozedur abgeschlossene Anweisungen) als auch sql_statement_completed (abgeschlossene Anweisungen, die sich nicht in einer gespeicherten Prozedur befinden). Beachten Sie, dass die TRACK_CAUSALITY-Option für die Sitzung auf ON gesetzt ist. Auch diese Einstellung ist spezifisch für die Ereignissitzung und muss vor dem Start aktiviert werden. Sie können die Einstellung nicht spontan aktivieren, genauso wie Sie Ereignisse und Ziele hinzufügen oder entfernen können, während die Sitzung läuft.

Um die Ereignissitzung über die Benutzeroberfläche zu starten, klicken Sie einfach mit der rechten Maustaste darauf und wählen Sie Sitzung starten aus.

Testen

In Management Studio führen wir den folgenden Code aus:

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

Hier ist unsere XE-Ausgabe:

Beachten Sie, dass die erste ausgeführte Abfrage, die hervorgehoben ist, SELECT @@SPID ist und die GUID FDCCB1CF-CA55-48AA-8FBA-7F5EBF870674 hat. Wir haben diese Abfrage nicht ausgeführt, sie trat im Hintergrund auf, und obwohl die XE-Sitzung so eingerichtet ist, dass Systemabfragen herausgefiltert werden, wird diese – aus welchen Gründen auch immer – immer noch erfasst.

Die nächsten vier Zeilen stellen den Code dar, den wir tatsächlich ausgeführt haben. Es gibt die beiden Abfragen der gespeicherten Prozedur, die gespeicherte Prozedur selbst und dann unsere Ad-hoc-Abfrage. Alle haben dieselbe GUID, ACBFFD99-2400-4AFF-A33F-351821667B24. Neben der GUID befindet sich die Sequenz-ID (seq), und die Abfragen sind von eins bis vier nummeriert.

In unserem Beispiel haben wir GO nicht verwendet, um die Anweisungen in verschiedene Stapel zu unterteilen. Beachten Sie, wie sich die Ausgabe ändert, wenn wir das tun:

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

Wir haben immer noch die gleiche Anzahl an Gesamtzeilen, aber jetzt haben wir drei GUIDs. Eine für SELECT @@SPID (E8D136B8-092F-439D-84D6-D4EF794AE753), eine für die drei Abfragen, die die gespeicherte Prozedur darstellen (F962B9A4-0665-4802-9E6C-B217634D8787), und eine für die Ad-hoc-Abfrage (5DD6A5FE -9702-4DE5-8467-8D7CF55B5D80).

Dies werden Sie höchstwahrscheinlich sehen, wenn Sie sich Daten aus Ihrer Anwendung ansehen, aber es hängt davon ab, wie die Anwendung funktioniert. Wenn Verbindungspooling verwendet wird und Verbindungen regelmäßig zurückgesetzt werden (was zu erwarten ist), hat jede Verbindung ihre eigene GUID.
Sie können diese mithilfe des folgenden PowerShell-Codes neu erstellen:

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

Hier ist ein Beispiel für die Ausgabe erweiterter Ereignisse, nachdem der Code eine Weile ausgeführt wurde:

Es gibt vier verschiedene GUIDs für unsere fünf Anweisungen, und wenn Sie sich den obigen Code ansehen, sehen Sie, dass vier verschiedene Verbindungen hergestellt wurden. Wenn Sie die Ereignissitzung so ändern, dass sie das Ereignis rpc_completed enthält, können Sie Einträge mit exec sp_reset_connection sehen.
Ihre XE-Ausgabe hängt von Ihrem Code und Ihrer Anwendung ab; Ich habe eingangs erwähnt, dass dies bei der Fehlersuche bei komplexeren gespeicherten Prozeduren nützlich ist. Betrachten Sie das folgende Beispiel:

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

Hier haben wir zwei gespeicherte Prozeduren, usp_TransctionInfo und usp_GetFullCustomerInfo, die von einer anderen gespeicherten Prozedur, usp_GetCustomerData, aufgerufen werden. Es ist nicht ungewöhnlich, dies zu sehen oder sogar zusätzliche Verschachtelungsebenen mit gespeicherten Prozeduren zu sehen. Wenn wir usp_GetCustomerData von Management Studio ausführen, sehen wir Folgendes:

EXEC [Sales].[usp_GetCustomerData] 981;

Hier erfolgten alle Ausführungen auf derselben GUID, BF54CD8F-08AF-4694-A718-D0C47DBB9593, und wir können die Reihenfolge der Abfrageausführung von eins bis acht anhand der seq-Spalte sehen. In Fällen, in denen mehrere gespeicherte Prozeduren aufgerufen werden, ist es nicht ungewöhnlich, dass der Sequenz-ID-Wert in die Hunderte oder Tausende geht.

Wenn Sie sich schließlich die Abfrageausführung ansehen und Track Causality eingeschlossen haben und eine Abfrage mit schlechter Leistung finden, weil Sie die Ausgabe basierend auf der Dauer oder einer anderen Metrik sortiert haben, beachten Sie, dass Sie die andere finden können Abfragen durch Gruppierung nach GUID:

Die Ausgabe wurde nach Dauer sortiert (höchster Wert rot eingekreist) und ich habe sie mit der Schaltfläche „Lesezeichen umschalten“ mit einem Lesezeichen (in Lila) versehen. Wenn wir die anderen Abfragen für die GUID sehen möchten, gruppieren Sie nach GUID (klicken Sie mit der rechten Maustaste auf den Spaltennamen oben, wählen Sie dann Gruppieren nach dieser Spalte) und verwenden Sie dann die Schaltfläche Nächstes Lesezeichen, um zu unserer Abfrage zurückzukehren:

Jetzt können wir alle Abfragen sehen, die innerhalb derselben Verbindung und in der ausgeführten Reihenfolge ausgeführt wurden.

Schlussfolgerung

Die Option "Kausalität verfolgen" kann bei der Fehlerbehebung bei der Abfrageleistung und beim Versuch, die Reihenfolge der Ereignisse in SQL Server zu verstehen, äußerst nützlich sein. Es ist auch nützlich, wenn Sie eine Ereignissitzung einrichten, die das Ziel pair_matching verwendet, um sicherzustellen, dass Sie das richtige Feld/die richtige Aktion abgleichen und das richtige nicht übereinstimmende Ereignis finden. Auch dies ist eine Einstellung auf Sitzungsebene und muss daher angewendet werden, bevor Sie die Ereignissitzung starten. Beenden Sie für eine laufende Sitzung die Ereignissitzung, aktivieren Sie die Option und starten Sie sie dann erneut.