トラック因果関係を使用したクエリ実行の理解

SQL Serverの問題のトラブルシューティングに深く関わっている場合、クエリが実行された正確な順序を知りたいと思うことがあります。これは、ロジックのレイヤーを含むより複雑なストアドプロシージャで、または冗長なコードがたくさんあるシナリオで見られます。拡張イベントは、通常、クエリの実行に関する情報を取得するために使用されるため、ここでは当然の選択です。多くの場合、session_idとタイムスタンプを使用してイベントの順序を理解できますが、さらに信頼性の高いXEのセッションオプションである因果関係の追跡があります。

セッションで因果関係の追跡を有効にすると、すべてのイベントに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
);

また、アドホッククエリを実行するため、sp_statement_completed（ストアドプロシージャ内で完了したステートメント）とsql_statement_completed（ストアドプロシージャ内にない完了したステートメント）の両方をキャプチャします。セッションのTRACK_CAUSALITYオプションがONに設定されていることに注意してください。この場合も、この設定はイベントセッションに固有であり、開始する前に有効にする必要があります。セッションの実行中にイベントやターゲットを追加または削除できるように、その場で設定を有効にすることはできません。

UIからイベントセッションを開始するには、イベントを右クリックして[セッションの開始]を選択します。

テスト

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セッションはシステムクエリを除外するように設定されていますが、何らかの理由でこのクエリは引き続きキャプチャされます。

次の4行は、実際に実行したコードを表しています。ストアドプロシージャからの2つのクエリ、ストアドプロシージャ自体、およびアドホッククエリがあります。すべて同じGUID、ACBFFD99-2400-4AFF-A33F-351821667B24があります。 GUIDの横にはシーケンスID（seq）があり、クエリには1から4までの番号が付けられています。

この例では、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

合計行数は同じですが、3つのGUIDがあります。 1つはSELECT@@SPID（E8D136B8-092F-439D-84D6-D4EF794AE753）用、1つはストアドプロシージャを表す3つのクエリ用（F962B9A4-0665-4802-9E6C-B217634D8787）、もう1つはアドホッククエリ用（5DD6A5FE）です。 -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();
}

コードを少し実行させた後に出力される拡張イベントの例を次に示します。

5つのステートメントには4つの異なるGUIDがあり、上記のコードを見ると、4つの異なる接続が確立されていることがわかります。 rpc_completedイベントを含むようにイベントセッションを変更すると、execsp_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

ここには、2つのストアドプロシージャusp_TransctionInfoとusp_GetFullCustomerInfoがあり、これらは別のストアドプロシージャusp_GetCustomerDataによって呼び出されます。これを確認したり、ストアドプロシージャを使用した追加レベルのネストを確認したりすることも珍しくありません。 Management Studioからusp_GetCustomerDataを実行すると、次のように表示されます。

EXEC [Sales].[usp_GetCustomerData] 981;

ここでは、すべての実行が同じGUID BF54CD8F-08AF-4694-A718-D0C47DBB9593で行われ、seq列を使用して1から8までのクエリ実行の順序を確認できます。呼び出されるストアドプロシージャが複数ある場合、シーケンスIDの値が数百または数千になることは珍しくありません。

最後に、クエリの実行を調べていて、Track Causalityを含めた場合、パフォーマンスの低いクエリが見つかりました。期間またはその他のメトリックに基づいて出力を並べ替えたため、他のメトリックを見つけることができることに注意してください。 GUIDでグループ化することによるクエリ：

出力は期間（赤で囲まれた最大値）でソートされており、[ブックマークの切り替え]ボタンを使用してブックマーク（紫）しました。 GUIDの他のクエリを表示する場合は、GUIDでグループ化し（上部の列名を右クリックし、[この列でグループ化]を選択します）、[次のブックマーク]ボタンを使用してクエリに戻ります。

これで、同じ接続内で実行された順序で実行されたすべてのクエリを確認できます。

結論

因果関係の追跡オプションは、クエリパフォーマンスのトラブルシューティングを行い、SQLServer内のイベントの順序を理解しようとするときに非常に役立ちます。また、pair_matchingターゲットを使用するイベントセッションを設定するときにも役立ちます。これは、正しいフィールド/アクションで一致していることを確認し、一致しない適切なイベントを見つけるのに役立ちます。繰り返しになりますが、これはセッションレベルの設定であるため、イベントセッションを開始する前に適用する必要があります。実行中のセッションの場合は、イベントセッションを停止し、オプションを有効にしてから、再開します。