Menggunakan Lacak Kausalitas untuk Memahami Eksekusi Kueri

Ketika sangat terlibat dalam pemecahan masalah di SQL Server, terkadang Anda ingin mengetahui urutan yang tepat dari kueri yang dijalankan. Saya melihat ini dengan prosedur tersimpan yang lebih rumit yang berisi lapisan logika, atau dalam skenario di mana ada banyak kode yang berlebihan. Acara yang Diperpanjang adalah pilihan alami di sini, karena biasanya digunakan untuk menangkap informasi tentang eksekusi kueri. Anda sering dapat menggunakan session_id dan stempel waktu untuk memahami urutan acara, tetapi ada opsi sesi untuk XE yang bahkan lebih andal:Lacak Kausalitas.

Saat Anda mengaktifkan Lacak Kausalitas untuk suatu sesi, itu menambahkan GUID dan nomor urut ke setiap peristiwa, yang kemudian dapat Anda gunakan untuk menelusuri urutan peristiwa yang terjadi. Overhead minimal, dan dapat menghemat waktu secara signifikan dalam banyak skenario pemecahan masalah.

Siapkan

Dengan menggunakan database WideWorldImporters, kami akan membuat prosedur tersimpan untuk digunakan:

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

Kemudian kita akan membuat sesi acara:

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

Kami juga akan menjalankan kueri ad-hoc, jadi kami menangkap sp_statement_completed (pernyataan yang diselesaikan dalam prosedur tersimpan) dan sql_statement_completed (pernyataan selesai yang tidak berada dalam prosedur tersimpan). Perhatikan bahwa opsi TRACK_CAUSALITY untuk sesi disetel ke AKTIF. Sekali lagi, pengaturan ini khusus untuk sesi acara dan harus diaktifkan sebelum memulainya. Anda tidak dapat mengaktifkan pengaturan dengan cepat, seperti Anda dapat menambah atau menghapus acara dan target saat sesi sedang berjalan.

Untuk memulai sesi acara melalui UI, cukup klik kanan padanya dan pilih Mulai Sesi.

Pengujian

Dalam Management Studio kita akan menjalankan kode berikut:

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

Inilah keluaran XE kami:

Perhatikan bahwa kueri pertama yang dieksekusi, yang disorot, adalah SELECT @@SPID, dan memiliki GUID FDCCB1CF-CA55-48AA-8FBA-7F5EBF870674. Kami tidak menjalankan kueri ini, kueri ini terjadi di latar belakang, dan meskipun sesi XE diatur untuk memfilter kueri sistem, kueri ini – untuk alasan apa pun – masih direkam.

Empat baris berikutnya mewakili kode yang sebenarnya kita jalankan. Ada dua kueri dari prosedur tersimpan, prosedur tersimpan itu sendiri, dan kemudian kueri ad-hoc kami. Semua memiliki GUID yang sama, ACBFFD99-2400-4AFF-A33F-351821667B24. Di sebelah GUID adalah id urutan (seq), dan kueri diberi nomor satu sampai empat.

Dalam contoh kami, kami tidak menggunakan GO untuk memisahkan pernyataan ke dalam kumpulan yang berbeda. Perhatikan bagaimana output berubah saat kita melakukannya:

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

Kami masih memiliki jumlah baris yang sama, tetapi sekarang kami memiliki tiga GUID. Satu untuk SELECT @@SPID (E8D136B8-092F-439D-84D6-D4EF794AE753), satu untuk tiga kueri yang mewakili prosedur tersimpan (F962B9A4-0665-4802-9E6C-B217634D8787), dan satu untuk kueri ad-hoc (5DD6A5FE -9702-4DE5-8467-8D7CF55B5D80).

Inilah yang kemungkinan besar akan Anda lihat saat melihat data dari aplikasi Anda, tetapi ini bergantung pada cara kerja aplikasi. Jika menggunakan penyatuan koneksi, dan koneksi disetel ulang secara teratur (yang diharapkan), maka setiap koneksi akan memiliki GUID sendiri.
Anda dapat membuat ulang ini menggunakan contoh kode PowerShell di bawah ini:

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

Berikut ini contoh keluaran peristiwa yang diperluas setelah membiarkan kode berjalan sebentar:

Ada empat GUID berbeda untuk lima pernyataan kami, dan jika Anda melihat kode di atas, Anda akan melihat ada empat koneksi berbeda yang dibuat. Jika Anda mengubah sesi acara untuk menyertakan acara rpc_completed, Anda dapat melihat entri dengan exec sp_reset_connection.
Output XE Anda akan bergantung pada kode dan aplikasi Anda; Saya menyebutkan awalnya bahwa ini berguna ketika memecahkan masalah prosedur tersimpan yang lebih kompleks. Perhatikan contoh berikut:

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

Di sini kita memiliki dua stored procedure, usp_TransctionInfo dan usp_GetFullCustomerInfo, yang dipanggil oleh stored procedure lain, usp_GetCustomerData. Bukan hal yang aneh untuk melihat ini, atau bahkan melihat tingkat tambahan bersarang dengan prosedur tersimpan. Jika kita menjalankan usp_GetCustomerData dari Management Studio, kita akan melihat yang berikut:

EXEC [Sales].[usp_GetCustomerData] 981;

Di sini, semua eksekusi terjadi pada GUID yang sama, BF54CD8F-08AF-4694-A718-D0C47DBB9593, dan kita dapat melihat urutan eksekusi kueri dari satu hingga delapan menggunakan kolom seq. Dalam kasus di mana ada beberapa prosedur tersimpan yang dipanggil, tidak jarang nilai id urutan mencapai ratusan atau ribuan.

Terakhir, jika Anda melihat eksekusi kueri dan Anda telah menyertakan Lacak Kausalitas, dan Anda menemukan kueri yang berkinerja buruk – karena Anda mengurutkan output berdasarkan durasi atau metrik lainnya, perhatikan bahwa Anda dapat menemukan yang lain kueri dengan mengelompokkan pada GUID:

Output telah diurutkan berdasarkan durasi (nilai tertinggi dilingkari merah), dan saya menandainya (berwarna ungu) menggunakan tombol Toggle Bookmark. Jika kita ingin melihat kueri lain untuk GUID, kelompokkan menurut GUID (Klik kanan pada nama kolom di atas, lalu pilih Kelompokkan menurut Kolom ini), lalu gunakan tombol Bookmark Berikutnya untuk kembali ke kueri kita:

Sekarang kita dapat melihat semua kueri yang dieksekusi dalam koneksi yang sama, dan dalam urutan yang dieksekusi.

Kesimpulan

Opsi Lacak Kausalitas bisa sangat berguna saat memecahkan masalah kinerja kueri dan mencoba memahami urutan kejadian dalam SQL Server. Ini juga berguna saat menyiapkan sesi acara yang menggunakan target pencocokan_pasangan, untuk membantu memastikan Anda mencocokkan bidang/tindakan yang benar dan menemukan peristiwa tak tertandingi yang tepat. Sekali lagi, ini adalah pengaturan tingkat sesi, sehingga harus diterapkan sebelum Anda memulai sesi acara. Untuk sesi yang sedang berjalan, hentikan sesi acara, aktifkan opsi, lalu mulai lagi.