XEvent : Requêtes longues

27 février 2017

Commentaires fermés

Lorsque des lenteurs sont détectées sur une instance ou à des fins proactives, il peut être intéressant de consigner ponctuellement les requêtes qui excédent un certain temps d’exécution. Ces requêtes ne sont pas forcément bloquantes mais coûteuses en ressource CPU, I/O et mémoire.

Etape 1

Nous allons créer une arborescence de répertoires sur laquelle le compte de service SQL Server aura le droit d’écrire. Le répertoire long_queries stockera les traces XEvent concernées.

Etape 2

Création de la trace XEvent en spécifiant le nom long_queries et le chemin D:\XEvent\long_queries\long_queries. Notez qu’il y a un rollover de défini sur 5 fichiers par défaut pour une taille limitée à 5 Mo par fichier, les traces n’étant pas supposée saturer les disques. En aucun cas, cette trace XEvent ne doit être activée en permanence car elle peut être particulièrement consommatrice, le filtrage est aussi un impératif (clause WHERE).

– Processus utilisateurs (VS système)
– Durée : 30 000 millisecondes => 30 sec
– Base de données spécifique

IF EXISTS(SELECT * FROM sys.server_event_sessions WHERE name='long_queries')
	DROP EVENT SESSION [long_queries] ON SERVER
GO

CREATE EVENT SESSION [long_queries] ON SERVER 
ADD EVENT sqlserver.rpc_completed(
    ACTION(sqlserver.client_app_name,sqlserver.client_hostname,sqlserver.database_id,sqlserver.is_system,sqlserver.session_id,sqlserver.sql_text,sqlserver.username)
        WHERE ((([package0].[equal_boolean]([sqlserver].[is_system],(0))) AND ([package0].[greater_than_uint64]([duration],(30000)))) AND ([sqlserver].[database_name]=N'DatabaseName')))
ADD TARGET package0.event_file(SET filename=N'D:\XEvent\long_queries\long_queries.xel',max_file_size=(5))
WITH (STARTUP_STATE=OFF)
GO

IF EXISTS(SELECT * FROM sys.server_event_sessions WHERE name='long_queries')

DROP EVENT SESSION [long_queries] ON SERVER

CREATE EVENT SESSION [long_queries] ON SERVER

ADD EVENT sqlserver.rpc_completed(

ACTION(sqlserver.client_app_name,sqlserver.client_hostname,sqlserver.database_id,sqlserver.is_system,sqlserver.session_id,sqlserver.sql_text,sqlserver.username)

WHERE ((([package0].[equal_boolean]([sqlserver].[is_system],(0))) AND ([package0].[greater_than_uint64]([duration],(30000)))) AND ([sqlserver].[database_name]=N'DatabaseName')))

ADD TARGET package0.event_file(SET filename=N'D:\XEvent\long_queries\long_queries.xel',max_file_size=(5))

WITH (STARTUP_STATE=OFF)

Dans la trace ci-définie précédemment, seules les procédures stockées exécutées à distance (VS module_end) et requêtes paramétrables dont la durée globale d’exécution est d’au moins 30 sec, seront présentes. On peut affiner en remontant la ou les instructions ayant une durée d’exécution individuelle d’au moins 30 sec dans une procédure stockée en utilisant l’évènement sp_statement_completed à la place de rpc_completed selon le besoin. Un relevé des requêtes Ad Hoc pourra être réalisé via l’évènement sql_batch_completed.

Voici quelques équivalences entre le profiler et XEvent :

Classe	Événement Profiler	Événement XEvent
Stored Procedures	RPC:Completed	rpc_completed
Stored Procedures	SP:Completed	module_end
Stored Procedures	SP:StmtCompleted	sp_statement_completed
TSQL	SQL:BatchCompleted	sql_batch_completed
TSQL	SQL:StmtCompleted	sql_statement_completed

Etape 3

Démarrage de la trace XEvent long_queries

ALTER EVENT SESSION [long_queries] ON SERVER
STATE=START
GO

ALTER EVENT SESSION [long_queries] ON SERVER

STATE=START

Consultation des requêtes longues

Le détail des requêtes longues peut être consulté en parsant le XML des traces XEvent générées et le résultat reste à historiser dans une table au besoin. Il est désormais possible d’identifier les requêtes dont le temps d’exécution excède une durée déterminée.

IF OBJECT_ID('tempdb..#Events') IS NOT NULL 
	DROP TABLE #Events

DECLARE	@TopCount Int = 100,
		@SessionName SysName = 'long_queries',
		@Target_File VARCHAR(1000),
		@Target_Dir VARCHAR(1000),
		@Target_File_WildCard VARCHAR(1000)

-- Récupérer le fichier de trace
SELECT	@Target_File = CAST(t.target_data as XML).value('EventFileTarget[1]/File[1]/@name', 'VARCHAR(256)')
FROM	 sys.dm_xe_session_targets t
INNER	JOIN sys.dm_xe_sessions s ON s.address = t.event_session_address
WHERE	s.name = @SessionName
AND		t.target_name = 'event_file'

SET @Target_Dir = LEFT(@Target_File, LEN(@Target_File) - CHARINDEX('\', REVERSE(@Target_File))) 
SET @Target_File_WildCard = @Target_Dir + '\' + @SessionName + '_*.xel'

--SELECT @Target_File_WildCard

-- Récupérer des n Events en XML
SELECT	TOP (@TopCount) CAST(event_data AS XML) AS event_data
INTO	 #Events
FROM	 sys.fn_xe_file_target_read_file(@Target_File_WildCard, null, null, null) AS F
ORDER BY File_name DESC, file_offset DESC 

SELECT  DATEADD(hour, DATEDIFF(hour, GETUTCDATE(), GETDATE())
        , event_data.value('(event/@timestamp)[1]', 'datetime')) AS log_date_time
        , event_data
		, event_data.value('(/event/action  [@name=''database_id'']/value)[1]','BIGINT') AS database_id
		, event_data.value('(/event/action  [@name=''session_id'']/value)[1]','BIGINT') AS session_id
		, event_data.value('(/event/action  [@name=''database_name'']/value)[1]','VARCHAR(80)') AS database_name
		, event_data.value('(/event/data  [@name=''object_id'']/value)[1]','BIGINT') AS object_id
		, event_data.value('(/event/data  [@name=''object_name'']/value)[1]','VARCHAR(80)') AS object_name
		, event_data.value('(/event/action  [@name=''client_app_name'']/value)[1]','VARCHAR(80)') AS client_app_name
		, event_data.value('(/event/action  [@name=''client_hostname'']/value)[1]','VARCHAR(80)') AS client_hostname
		, event_data.value('(/event/data  [@name=''duration'']/value)[1]','BIGINT') AS duration
		, event_data.value('(/event/data [@name=''cpu_time'']/value)[1]','BIGINT') AS cpu_time
		, event_data.value('(/event/data [@name=''physical_reads'']/value)[1]','BIGINT') AS physical_reads
		, event_data.value('(/event/data [@name=''logical_reads'']/value)[1]','BIGINT') AS logical_reads
		, event_data.value('(/event/data [@name=''writes'']/value)[1]','BIGINT') AS writes
		, event_data.value('(/event/data [@name=''row_count'']/value)[1]','BIGINT') AS row_count
		, event_data.value('(/event/action [@name=''tsql_stack'']/value/frames/frame/@handle)[1]','VARCHAR(MAX)') AS sql_handle
		, event_data.value('(/event/action [@name=''tsql_stack'']/value/frames/frame/@offsetStart)[1]','BIGINT') AS offsetStart
		, event_data.value('(/event/action [@name=''tsql_stack'']/value/frames/frame/@offsetEnd)[1]','BIGINT') AS offsetEnd
		, event_data.value('(/event/action[@name="query_hash"]/value)[1]', 'DECIMAL(20,0)' ) AS query_hash
		, event_data.value('(event/@name)[1]', 'varchar(50)') AS event_name
		, event_data.value('(event/@timestamp)[1]', 'varchar(50)') AS event_time
		, event_data.value('(event/action[@name="sql_text"]/value)[1]', 'varchar(max)') AS sql_text
FROM    #Events

IF OBJECT_ID('tempdb..#Events') IS NOT NULL

DROP TABLE #Events

DECLARE @TopCount Int = 100,

@SessionName SysName = 'long_queries',

@Target_File VARCHAR(1000),

@Target_Dir VARCHAR(1000),

@Target_File_WildCard VARCHAR(1000)

-- Récupérer le fichier de trace

SELECT @Target_File = CAST(t.target_data as XML).value('EventFileTarget[1]/File[1]/@name', 'VARCHAR(256)')

FROM sys.dm_xe_session_targets t

INNER JOIN sys.dm_xe_sessions s ON s.address = t.event_session_address

WHERE s.name = @SessionName

AND t.target_name = 'event_file'

SET @Target_Dir = LEFT(@Target_File, LEN(@Target_File) - CHARINDEX('\', REVERSE(@Target_File)))

SET @Target_File_WildCard = @Target_Dir + '\' + @SessionName + '_*.xel'

--SELECT @Target_File_WildCard

-- Récupérer des n Events en XML

SELECT TOP (@TopCount) CAST(event_data AS XML) AS event_data

INTO #Events

FROM sys.fn_xe_file_target_read_file(@Target_File_WildCard, null, null, null) AS F

ORDER BY File_name DESC, file_offset DESC

SELECT DATEADD(hour, DATEDIFF(hour, GETUTCDATE(), GETDATE())

, event_data.value('(event/@timestamp)[1]', 'datetime')) AS log_date_time

, event_data

, event_data.value('(/event/action [@name=''database_id'']/value)[1]','BIGINT') AS database_id

, event_data.value('(/event/action [@name=''session_id'']/value)[1]','BIGINT') AS session_id

, event_data.value('(/event/action [@name=''database_name'']/value)[1]','VARCHAR(80)') AS database_name

, event_data.value('(/event/data [@name=''object_id'']/value)[1]','BIGINT') AS object_id

, event_data.value('(/event/data [@name=''object_name'']/value)[1]','VARCHAR(80)') AS object_name

, event_data.value('(/event/action [@name=''client_app_name'']/value)[1]','VARCHAR(80)') AS client_app_name

, event_data.value('(/event/action [@name=''client_hostname'']/value)[1]','VARCHAR(80)') AS client_hostname

, event_data.value('(/event/data [@name=''duration'']/value)[1]','BIGINT') AS duration

, event_data.value('(/event/data [@name=''cpu_time'']/value)[1]','BIGINT') AS cpu_time

, event_data.value('(/event/data [@name=''physical_reads'']/value)[1]','BIGINT') AS physical_reads

, event_data.value('(/event/data [@name=''logical_reads'']/value)[1]','BIGINT') AS logical_reads

, event_data.value('(/event/data [@name=''writes'']/value)[1]','BIGINT') AS writes

, event_data.value('(/event/data [@name=''row_count'']/value)[1]','BIGINT') AS row_count

, event_data.value('(/event/action [@name=''tsql_stack'']/value/frames/frame/@handle)[1]','VARCHAR(MAX)') AS sql_handle

, event_data.value('(/event/action [@name=''tsql_stack'']/value/frames/frame/@offsetStart)[1]','BIGINT') AS offsetStart

, event_data.value('(/event/action [@name=''tsql_stack'']/value/frames/frame/@offsetEnd)[1]','BIGINT') AS offsetEnd

, event_data.value('(/event/action[@name="query_hash"]/value)[1]', 'DECIMAL(20,0)' ) AS query_hash

, event_data.value('(event/@name)[1]', 'varchar(50)') AS event_name

, event_data.value('(event/@timestamp)[1]', 'varchar(50)') AS event_time

, event_data.value('(event/action[@name="sql_text"]/value)[1]', 'varchar(max)') AS sql_text

FROM #Events

Auteur

Sarah Béquet

Archietcte Data Microsoft, les maîtres mots sont : performance, industrialisation, méthodologie & bonne humeur.

Derniers articles

2019.12.02BI & Big Data Etude des contextes en DAX (4/4) : Transition de contexte
2019.11.25BI & Big Data Etude des contextes en DAX (3/4) : Contexte de requête
2019.11.17BI & Big Data Etude des contextes en DAX (2/4) : Contexte de filtre
2019.11.11BI & Big Data Etude des contextes en DAX (1/4) : Contexte de ligne

Articles liés

Tuning d'instance SQL Server

sp_change_users_login : Utilisateurs orphelins

In-Memory (Hekaton)

Scripter la création et suppression des contraintes (ex : FK)

Blog