Monitoring procedur natywnie kompilowanych w In-memory OLTP

Obiekty natywnie kompilowane z całą pewnością mogą dać nam przyrost wydajności związany z faktem, iż cała faza optymalizacji i kompilacji następuje w momencie ich tworzenia. Wynikiem procesu optymalizacji jest plan wykonania, który będzie wykorzystywany przy każdym wywołaniu procedury, aż do momentu wystąpienia rekompilacji. Mamy do dyspozycji pewne możliwości monitorowania statystyk wywołania procedur natywnie kompilowanych, które są domyślnie wyłączone i to właśnie o tym chciałbym dziś parę słów napisać.

Na samym początku stwórzmy sobie bazę danych o nazwie Hekaton_demo, którą będziemy używać. Baza ta nie charakteryzuje się niczym specjalnym i została stworzona przy pomocy poniższego skryptu:

SET NOCOUNT ON
GO
SET STATISTICS TIME OFF 
GO
USE master
GO
DROP DATABASE IF EXISTS Hekaton_Demo
GO

CREATE DATABASE [Hekaton_demo]
 ON  PRIMARY 
( 
NAME = N'Hekaton_demo', 
FILENAME = N'C:\Program Files\Microsoft SQL Server\MSSQL13.MSSQLSERVER\MSSQL\DATA\Hekaton_demo.mdf' , 
SIZE = 524288KB , 
FILEGROWTH = 65536KB 
)
 LOG ON 
( 
NAME = N'Hekaton_demo_log', 
FILENAME = N'C:\Program Files\Microsoft SQL Server\MSSQL13.MSSQLSERVER\MSSQL\DATA\Hekaton_demo_log.ldf' , 
SIZE = 131072KB , 
FILEGROWTH = 65536KB 
)
GO


ALTER DATABASE Hekaton_demo
ADD FILEGROUP AWMemGroup CONTAINS MEMORY_OPTIMIZED_DATA
GO

ALTER DATABASE [Hekaton_demo] 
ADD FILE 
( 
NAME = N'Hekaton_demo_inmem', 
FILENAME = N'C:\Program Files\Microsoft SQL Server\MSSQL13.MSSQLSERVER\MSSQL\DATA\Hekaton_demo_inmem' 
) 
TO FILEGROUP [AWMemGroup]
GO

W następnym kroku stworzymy sobie nietrwałą tabelę in-memory  o nazwie UserSession, którą następnie wypełnimy 100 tysiącami rekordów używając pętli. Tabela ta będzie posiadała indeks typu hash na polu SessionID będącym jednocześnie kulczem głównym całej tabeli ze wskazaniem 180 tysięcy bucketów na wartości:

 CREATE TABLE dbo.UserSession (   
   SessionId INT IDENTITY(1,1) PRIMARY KEY NONCLUSTERED HASH WITH (BUCKET_COUNT=180000),   
   UserId int NOT NULL, 
   LoginGUID nvarchar(50),  
   CreatedDate DATETIME2 NOT NULL,    
 )   
 WITH (MEMORY_OPTIMIZED=ON, DURABILITY=SCHEMA_ONLY)   
 GO

 DECLARE  @Counter INT=0
 DECLARE  @NoOfRows INT=100000
 
WHILE @Counter<@NoOfRows
BEGIN
	 INSERT dbo.UserSession(UserId,LoginGUID,CreatedDate)
	 VALUES (
		CAST(RAND()*10000 AS INT), 
		CAST(NEWID() AS NVARCHAR(50)),
		DATEADD(DAY,-CAST(RAND()*1000 AS INT),GETDATE())
		)   
SET @Counter=@Counter+1
END

W kolejnym kroku stwórzmy sobie procedurę natywnie kompilowaną, która będzie zwracała identyfikator użytkowników, którzy byli przypisani do podanych jako parametr numerów sesji:

CREATE PROCEDURE dbo.GetUserIdentifiersForSessions
	@StartSessionID INT, @EndSessionID INT
WITH NATIVE_COMPILATION, SCHEMABINDING
AS BEGIN ATOMIC 
WITH
(
 TRANSACTION ISOLATION LEVEL = SNAPSHOT, LANGUAGE = N'us_english'
)
SELECT DISTINCT
	UserId
FROM
	dbo.UserSession AS US
WHERE US.SessionId BETWEEN @StartSessionID AND @EndSessionID
END

Mając już zestaw testowy wywołajmy sobie naszą procedurę dla określonych numerów sesji przy włączonym jednocześnie Actual Execution Plan:

EXEC dbo.GetUserIdentifiersForSessions @StartSessionID=1,@EndSessionID=10

Wszystko wydaje się w porządku jednak nasz aktualny plan wykonania nie został dołączony. Dzieje się tak dlatego, że narzędzie to nie jest dla nas dostępne dla procedur natywnie kompilowanych! Gdy chcemy zobaczyć jaki plan został wykorzystany możemy użyć Estimated Execution Plan, który dla naszej procedury przedstawia się następująco:

Mamy troszeczkę ograniczony wachlarz możliwości monitorowania problemów wydajnościowych bez aktualnego planu wykonania, ale na powyższym zrzucie już możemy zaobserwować kilka przydatnych informacji na temat sposobu wykonania naszej procedury. Przede wszystkim nie został wykorzystany stworzony przez nas indeks – dzieje się tak ze względu na fakt, iż indeks typu Hash nie obsługuje operacji opartych na zakresach takich jak właśnie BETWEEN. Indeks tego typu służy niemal wyłącznie do tzw. POINT LOOKUP czyli wyszukiwania wierszy na podstawie warunku z operatorem równości na selektywnych kolumnach np. WHERE SessionID=1. Przechodząc dalej na naszym planie widzimy, iż wystąpił DISTINCT SORT, który jest odzwierciedleniem operacji SELECT DISTINCT naszego zapytania.

Gdy podejrzymy sobie właściwości operatora SELECT zobaczymy tam właściwie jedną użyteczna informację – chodzi mianowicie o powód dlaczego nasz plan nie jest wykonywany równolegle:

W taki właśnie sposób mamy dowód na to, że przetwarzanie równoległe nie jest dostępne dla opisywanego typu procedur…

Wiemy, że nasz indeks nie może być wykorzystywany ponieważ nie obsługuje operacji takiej jaka występuje w naszym zapytaniu. Do dyspozycji mamy również drugi typ indeksu – chodzi mianowicie o indeks typu RANGE. Nic nie stoi na przeszkodzie aby mieć dwa indeksy różnego typu na tej samej kolumnie – w in-memory OLTP nie ma koncepcji indeksu pokrywającego – każdy indeks zawiera wskazania bezpośrednio do wiersza danych! Dodajmy sobie zatem taki indeks do naszej tabeli:

ALTER TABLE dbo.UserSession 
ADD INDEX IX_RANGE_SessionID (SessionID)

Następnie podejrzyjmy estymowany plan wykonania przy wywołaniu naszej procedury:

Tym razem dzięki nowemu indeksowi mamy Index Seek, czyli nie musimy skanować całej tabeli. W momencie dodania indeksu procedura została rekompilowana dzięki czemu plan został zbudowany na nowo. W przypadku gdy zaaktualizowane zostaną statystyki nasza procedura nie zostanie rekompilowana – musimy to zrobić ręcznie używając sp_recompile. Pamiętajmy, że w przypadku występowania parametrów to optymalizator przyjmuje, że ich wartość jest nieznana i niejako uśrednia liczebność tak więc wpływ statystyk na kształt planu będzie miał duże znaczenie w przypadku gdy mamy do czynienia ze skośnym rozkładem częstości.

W porządku, wiemy jak wyświetlać estymowany plan wykonania, a co z aktualnymi statystykami wykonania? Tutaj odpowiedź może Was zdziwić ponieważ aktualne statystyki wykonania nie są domyślnie zbierane ze względu, iż mogło by to negatywnie wpłynąć na wydajność wykonania. Zachowanie to możemy zmienić wywołując odpowiednie procedury. Pierwszą z nich jest sp_xtp_control_proc_exec_stats, którą możemy wywołać w następujący sposób:

exec [sys].[sp_xtp_control_proc_exec_stats] @new_collection_value = 1

Następnie wywołajmy naszą procedurę:

EXEC dbo.GetUserIdentifiersForSessions @StartSessionID=10,@EndSessionID=100

W dalszym kroku odpytajmy sys.dm_exec_procedure_stats przefiltrowując ten widok w taki sposób aby pokazywał jedynie procedury natywnie kompilowane z bieżącej bazy:

select object_id,  
       object_name(object_id) as 'object name',  
       cached_time,  
       last_execution_time,  
       execution_count,  
       total_worker_time,  
       last_worker_time,  
       min_worker_time,  
       max_worker_time,  
       total_elapsed_time,  
       last_elapsed_time,  
       min_elapsed_time,  
       max_elapsed_time   
from sys.dm_exec_procedure_stats  
where database_id=db_id() and object_id in (select object_id   
from sys.sql_modules where uses_native_compilation=1)  
order by total_worker_time desc

Widok ten zawiera skumulowane informacje takie jak ilość wywołań, czy też statystyki czasowe związane z wykonaniem całej procedury. Oczywiście procedura może zawierać więcej niż jedno zapytanie – w momencie gdy chcemy widzieć bardziej granularne dane możemy to zrobić włączając odpowiednią procedurę – tym razem sys.sp_xtp_control_query_exec_stats. Zanim przetestujemy ten mechanizm zmodyfikujmy naszą procedurę tak aby zawierała dwa zapytania:

ALTER PROCEDURE dbo.GetUserIdentifiersForSessions
	@StartSessionID INT, @EndSessionID INT
WITH NATIVE_COMPILATION, SCHEMABINDING
AS BEGIN ATOMIC 
WITH
(
 TRANSACTION ISOLATION LEVEL = SNAPSHOT, LANGUAGE = N'us_english'
)
DECLARE @NumberOfRecords int =(
SELECT COUNT(*) FROM
	dbo.UserSession AS US
WHERE US.SessionId BETWEEN @StartSessionID AND @EndSessionID
)
SELECT DISTINCT
	UserId
FROM
	dbo.UserSession AS US
WHERE US.SessionId BETWEEN @StartSessionID AND @EndSessionID
END

Następnie włączmy kolekcjonowanie statystyk i wywołajmy nasze zapytanie:

EXEC [sys].[sp_xtp_control_query_exec_stats] @new_collection_value = 1;  

Wywołajmy naszą procedurę:

EXEC dbo.GetUserIdentifiersForSessions @StartSessionID=10,@EndSessionID=100

Odpytajmy widok systemowy sys.dm_exec_query_stats:

select st.objectid,   
       object_name(st.objectid) as 'object name',   
       SUBSTRING(st.text, (qs.statement_start_offset/2) + 1, ((qs.statement_end_offset-qs.statement_start_offset)/2) + 1) as 'query text',   
       qs.creation_time,  
       qs.last_execution_time,  
       qs.execution_count,  
       qs.total_worker_time,  
       qs.last_worker_time,  
       qs.min_worker_time,  
       qs.max_worker_time,  
       qs.total_elapsed_time,  
       qs.last_elapsed_time,  
       qs.min_elapsed_time,  
       qs.max_elapsed_time  
from sys.dm_exec_query_stats qs cross apply sys.dm_exec_sql_text(sql_handle) st  
where  st.dbid=db_id() and st.objectid in (select object_id   
from sys.sql_modules where uses_native_compilation=1)  
order by qs.total_worker_time desc  

Statystyki mogą być dla nas przydatne – jednakże nie powinniśmy mieć ich zawsze włączonych ze względu na fakt, iż tak jak wspomniałem mają one wpływ na wydajność (niewielki ale zawsze). Aby sprawdzić czy kolekcjonujemy dane czy też nie wystarczy użyć konstrukcji jak została przedstawiona poniżej tj. z parametrem ustawionym jako output – dzięki temu otrzymamy 1 gdy kolekcjonowanie jest włączone lub 0 gdy nie jest:

declare @c bit  
exec sp_xtp_control_query_exec_stats @old_collection_value=@c output  
select @c as 'collection status'

Aby móc kontrolować ten mechanizm musimy pamiętać o tym, że musimy być członkami sysadmin gdyż jest to ustawienie na poziomie instancji, a nie pojedynczej bazy danych. Mamy jednak możliwość włączenia kolekcji dla pojedynczej procedury – ustawienie to jest niezależne od ustawienia na poziomie instancji. Oprócz samych statystyk, do monitorowania procedur natywnie kompilowanych możemy użyć nowej funkcjonalności wprowadzonej w SQL Server 2016 czyli Query Store (o którym miałem okazję opisać w dwóch artykułach tutaj oraz tutaj). Możemy go włączyć następującym poleceniem ALTER DATABASE:

ALTER DATABASE Hekaton_Demo SET QUERY_STORE = ON;

Następnie wywołajmy nasze zapytanie:

EXEC dbo.GetUserIdentifiersForSessions @StartSessionID=10,@EndSessionID=100

Dane zostały zapisane w specjalnych tabelach mechanizmu Query Store do których mamy dostęp poprzez widoki dynamiczne:

SELECT q.query_id, plan_id, OBJECT_NAME(object_id), query_hash, p.query_plan,  
    p.initial_compile_start_time, p.last_compile_start_time,   
    p.last_execution_time, p.avg_compile_duration,  
    p.last_force_failure_reason, p.force_failure_count  
FROM sys.query_store_query AS q  
JOIN sys.query_store_plan AS p   
    ON q.query_id = p.plan_id  
WHERE q.object_id = OBJECT_ID('GetUserIdentifiersForSessions');

Powyższy SELECT zwrócił dane na temat samego procesu kompilacji w podziale na pojedyncze zapytania :

Do dyspozycji mamy również statystyki samego wykonania:

SELECT q.query_id, p.plan_id, OBJECT_NAME(object_id), rsi.start_time, rsi.end_time,    
    p.last_force_failure_reason, p.force_failure_count, rs.*  
FROM sys.query_store_query AS q  
JOIN sys.query_store_plan AS p   
    ON q.query_id = p.plan_id  
JOIN sys.query_store_runtime_stats AS rs   
    ON rs.plan_id = p.plan_id  
JOIN sys.query_store_runtime_stats_interval AS rsi   
    ON rs.runtime_stats_interval_id = rsi.runtime_stats_interval_id  
WHERE q.object_id = OBJECT_ID('GetUserIdentifiersForSessions'); 

Tutaj mamy do dyspozycji całkiem sporo informacji jak np. ile wierszy zwracało zapytanie czy jego czas trwania. Może to być przydatne w przypadku gdy chcemy zlokalizować najbardziej kosztowne procedury i zapytania wchodzące w ich skład.

Ostatnią metodą o jakiej chciałbym wspomnieć jeśli chodzi o monitoring procedur natywnie kompilowanych jest sesja Extended Events. Przykładowa sesja tego mechanizmu została przedstawiona poniżej:

CREATE EVENT SESSION [XTP_NSP_Trace] ON SERVER 
ADD EVENT sqlserver.sp_statement_completed(
    ACTION(
			sqlserver.database_name,
			sqlserver.is_system,sqlserver.nt_username,
			sqlserver.plan_handle,
			sqlserver.query_hash,
			sqlserver.query_hash_signed,
			sqlserver.query_plan_hash,
			sqlserver.query_plan_hash_signed,
			sqlserver.request_id,
			sqlserver.server_instance_name,
			sqlserver.server_principal_name,
			sqlserver.server_principal_sid,
			sqlserver.session_id,
			sqlserver.session_nt_username,
			sqlserver.session_resource_group_id,
			sqlserver.session_resource_pool_id,
			sqlserver.session_server_principal_name,
			sqlserver.sql_text,sqlserver.transaction_id,
			sqlserver.transaction_sequence,
			sqlserver.tsql_frame,
			sqlserver.tsql_stack,
			sqlserver.username)
    WHERE ([sqlserver].[database_name]=N'Hekaton_demo'))
WITH (STARTUP_STATE=OFF)
GO

Daje nam ona możliwość śledzenia dosyć dokładnych informacji na temat czasu trwania wykonania procedury czy chociażby dane o użytkowniku, który wykonał daną procedurę – oczywiście możliwości wykorzystania powyższych informacji jest dużo więcej. Poniżej przykładowy zrzut danych XEvents podejrzany za pomocą podglądu na żywo:

Jak możecie zauważyć monitorowanie procedur natywnie kompilowanych nieco różni się od monitorowania tradycyjnych modułów. Niestety mamy dużo mniej możliwości,a brak możliwości podejrzenia np. aktualnego planu wykonania skutkuje tym, że sam troubleshooting może być nieco utrudniony. Istnieją jednak pewne możliwości i należy zdawać sobie z nich sprawę i wybrać ten sposób, który będzie dla nas najwygodniejszy i najlepiej spełniał nasze oczekiwania.