Diagnostiquer les attentes de verrous avec le blocked process report : xevents et notifications d'évènements
Par Arian Papillon le mardi 14 avril 2015, 23:02 - Lien permanent
Vous avez des attentes de verrous ?
Si vous n'avez pas un outil de monitoring du genre SQLSentry, voici une des
méthodes pour journaliser dans une table les attentes de verrous avec tous les
détails, à des fins de diagnostic...
SQL Server possède un évènement "blocked process" dont on peut configurer le
déclenchement de manière à alerter ou à journaliser tout processus
bloqué.
L'évènement "blocked process report" peut être capturé
- dans une trace profile (évènement "blocked process report" dans "Errors and Warnings"),
- avec des évènements étendus (XEVENTS),
- avec les notifications d'évènements.
Dans les données de l'évènement, nous pourrons ainsi obtenir les informations sur la cause de l'attente : le spid, le type de verrou, la requête en cours, etc...
Nous allons examiner les deux dernières méthodes : xevents et notifications d'évènements.
La configuration du seuil de déclenchement pour le report se situe dans les propriétés du serveur : on doit indiquer le nombre de secondes au delà desquelles l'alerte sera déclenchée si un processus est bloqué. Configurons le avec une requête en ligne de commande :
USE MASTER
GO
EXEC sys.sp_configure N'show advanced options', N'1'
RECONFIGURE WITH OVERRIDE
GO
EXEC sys.sp_configure N'blocked process threshold (s)', N'10'
GO
RECONFIGURE WITH OVERRIDE
GO
EXEC sys.sp_configure N'show advanced options', N'0'
RECONFIGURE WITH OVERRIDE
GO
Evènements étendus (XEVENTS)
Dans ce premier exemple, nous allons récupérer le rapport de blocage grâce à un évènement étendu. Il est possible de stocker les données dans un RING_BUFFER en mémoire comme dans l'exemple ci-après (je ne conserverai que les derniers évènements selon de la taille du ring_buffer, et tout sera perdu si je redémarre mon instance). Il est aussi possible de stocker les données dans un fichier XEL pour les garder de manière persistante.
-- Création de la session XEvent
CREATE EVENT SESSION LocksReporting ON SERVER ADD EVENT sqlserver. blocked_process_report ADD TARGET package0.
ring_buffer ( SET MAX_MEMORY=2048 ) WITH ( MAX_DISPATCH_LATENCY = 5 SECONDS )
GO
ALTER EVENT SESSION LocksReporting
ON SERVER
STATE=START
GO
Dès lors, notre session d'évènement est créée et démarrée. Nous pouvons visualiser le contenu dans l'interface graphique, ou mieux écrire une requête en TSQL pour obtenir tout le contenu sous forme tabulaire :
WITH BPR_Events (event_name, package_name, timestamp, database_id, database_name, duration_seconds, file_handle, transaction_id, resource_owner_type,blocked_process_report)
AS (
SELECT n.value('(event/@name)[1]', 'varchar(50)') AS event_name
,n.value('(event/@package)[1]', 'varchar(50)') AS package_name
,DATEADD(hh, DATEDIFF(hh, GETUTCDATE(), CURRENT_TIMESTAMP), n.value('(event/@timestamp)[1]', 'datetime2')) AS [timestamp]
,ISNULL(n.value('(event/data[@name="database_id"]/value)[1]', 'int'),
n.value('(event/action[@name="database_id"]/value)[1]', 'int')) AS [database_id]
,n.value('(event/data[@name="database_name"]/value)[1]', 'nvarchar(128)') AS [database_name]
,CAST(n.value('(event/data[@name="duration"]/value)[1]', 'bigint') / 1000000.0 AS DECIMAL(6, 2)) AS [duration_seconds]
,n.value('(event/data[@name="lock_mode"]/text)[1]', 'nvarchar(10)') AS [file_handle]
,n.value('(event/data[@name="transaction_id"]/value)[1]', 'bigint') AS [transaction_id]
,n.value('(event/data[@name="resource_owner_type"]/text)[1]', 'nvarchar(10)') AS [resource_owner_type]
,n.query('(event/data[@name="blocked_process"]/value/blocked-process-report)[1]') AS [blocked_process_report]
FROM ( SELECT td.query('.') AS n
FROM ( SELECT CAST(target_data AS XML) AS target_data
FROM sys.dm_xe_sessions AS s
JOIN sys.dm_xe_session_targets AS t ON s.address = t.event_session_address
WHERE s.name = 'LocksReporting'
AND t.target_name = 'ring_buffer'
) AS sub
CROSS APPLY target_data.nodes('RingBufferTarget/event') AS q ( td )
) AS TAB )
SELECT event_name, package_name, timestamp, database_id, database_name, duration_seconds, file_handle, transaction_id, resource_owner_type
, Y.x.value('@spid', 'nvarchar(45)') BlockingSpid
, X.x.value('@spid', 'nvarchar(45)') BlockedSpid
, X.x.value('@id', 'nvarchar(45)') BlockedId
, Y.x.value('@hostname', 'nvarchar(45)') BlockingFromHost
, Y.x.value('@loginname', 'nvarchar(45)') BlockingFromLogin
, Y.x.value('@isolationlevel', 'nvarchar(45)') BlockingFromIso
, Y.x.value('data(.)', 'varchar(5000)') AS BlockingSQLcmd
,
-- Y.x.value('@waitresource', 'nvarchar(45)') BlockingObject ,
DB_NAME(X.x.value('@currentdb', 'int')) Blockeddb
, X.x.value('@waitresource', 'nvarchar(45)') BlockedObject
, X.x.value('@lockMode', 'nvarchar(45)') BlockedBlockLockMode
, X.x.value('@hostname', 'nvarchar(45)') BlockedFromHOst
, X.x.value('@loginname', 'nvarchar(45)') BlockedFromLogin
, X.x.value('@clientapp', 'nvarchar(45)') BlockedClientApp
, X.x.value('@isolationlevel', 'nvarchar(45)') BlockedFromIso
, X.x.value('data(.)', 'varchar(5000)') AS BlockedSQLcmd
, blocked_process_report
from BPR_Events a
CROSS APPLY blocked_process_report.nodes('blocked-process-report/blocked-process/process')
AS X ( x )
CROSS APPLY blocked_process_report.nodes('blocked-process-report/blocking-process/process')
AS Y ( x )
Notifications d'évènements
Autre méthode pour capturer les évènements de blocage dans une table, nous pouvons aussi utiliser les notifications d'évènements. Chaque blocage va ainsi générer un évènement qui sera transmis sous forme de message service broker à notre base de journalisation. Cette méthode fonctionne depuis SQL Server 2005, alors que les xevents ne sont disponibles que depuis SQL 2008 (et avec une interface graphique de depuis SQL 2012...)
Nous allons dans cet exemple journaliser les évènements de blocage dans une nouvelle base de données ADMIN_SQL.
CREATE DATABASE ADMIN_SQL
Les notifications d'évènement sont un mécanisme d'alerting asynchrone, basé sur le service broker. Cette architecture asynchrone va permettre ainsi une montée en charge sans impact sur les transactions des utilisateurs. Nous devons activer le service broker sur notre base ADMIN_SQL, puis créer les différents objets nécessaires : un service, une file d'attente, une procédure stockée de traitement des notifications reçues, une table de journalisation pour recueillir les informations.
USE MASTER
GO
-- Activons le service broker
IF NOT EXISTS ( SELECT *
FROM sys.databases
WHERE name = 'ADMIN_SQL'
AND is_broker_enabled = 1 )
BEGIN
ALTER DATABASE ADMIN_SQL SET ENABLE_BROKER
END
GO
-- Créons les objets nécessaires
USE ADMIN_SQL
GO
IF EXISTS ( SELECT *
FROM sys.services
WHERE name = 'NotifyBlockingService' )
DROP SERVICE NotifyBlockingService
GO
IF OBJECT_ID('[dbo].[NotifyBlockingQueue]') IS NOT NULL
AND EXISTS ( SELECT *
FROM sys.service_queues
WHERE name = 'NotifyBlockingQueue' )
DROP QUEUE [dbo].[NotifyBlockingQueue]
GO
-- Crée la file d'attente, on ne l'active pas pour l'instant
CREATE QUEUE NotifyBlockingQueue
GO
-- Crée le service
CREATE SERVICE NotifyBlockingService ON QUEUE NotifyBlockingQueue
([http://schemas.microsoft.com/SQL/Notifications/PostEventNotification])
GO
-- Table
CREATE TABLE [dbo].[BlockingEventsXML](
[EventNumber] [int] IDENTITY(1,1) NOT NULL,
[EventType] [nvarchar](256) NULL,
[EventTime] [datetime] NULL,
[EventData] [xml] NULL,
PRIMARY KEY CLUSTERED
(
[EventNumber] ASC
) )
GO
IF OBJECT_ID(N'[dbo].[LogBlockingEvents]') IS NOT NULL
AND OBJECTPROPERTY(OBJECT_ID(N'[dbo].[LogBlockingEvents]'), N'IsProcedure') = 1
DROP PROCEDURE [dbo].[LogBlockingEvents]
GO
-- Procédure
SET ANSI_NULLS ON
SET QUOTED_IDENTIFIER ON
GO
CREATE PROCEDURE [dbo].[LogBlockingEvents]
AS
BEGIN
SET NOCOUNT ON
DECLARE @message_body XML
, @message_type_name NVARCHAR(256)
, @dialog UNIQUEIDENTIFIER;
WHILE ( 1 = 1 )
BEGIN
BEGIN TRANSACTION
WAITFOR ( RECEIVE TOP ( 1 ) -- récupère les messages
@message_type_name = message_type_name, -- le type du message
@message_body = message_body, -- le contenu du message
@dialog = conversation_handle -- l'identifiant du dialogue
FROM NotifyBlockingQueue ), TIMEOUT 2000;
IF ( @@ROWCOUNT = 0 )
BEGIN
ROLLBACK TRANSACTION;
BREAK;
END;
IF ( @message_type_name = 'http://schemas.microsoft.com/SQL/ServiceBroker/EndDialog' )
BEGIN
PRINT 'Fin du dialogue # '
+ CAST(@dialog AS NVARCHAR(40));
END CONVERSATION @dialog;
END;
ELSE
BEGIN
-- Insert dans loggedeventsXML
INSERT INTO [dbo].[BlockingEventsXML]
( EventType
, EventTime
, EventData
)
VALUES ( CAST(@message_body.query('/EVENT_INSTANCE/EventType/text()') AS NVARCHAR(256))
, CAST(CAST(@message_body.query('/EVENT_INSTANCE/PostTime/text()') AS NVARCHAR(MAX)) AS DATETIME)
, @message_body
)
END
COMMIT TRANSACTION
END -- WHILE
END
GO
Il ne nous reste plus qu'à activer la file d'attente et à créer la notification pour que tout blocage de plus de 10 secondes sont journalisé dans notre table.
-- Active la file d'attente, ce qui lance la réception des événements
ALTER QUEUE [dbo].[NotifyBlockingQueue] WITH ACTIVATION ( STATUS = ON,
PROCEDURE_NAME = [dbo].[LogBlockingEvents], -- Lance un maximum de 2 instance de la procédure
MAX_QUEUE_READERS = 2, -- En tant que l'utilisateur qui a créé la file d'attente
EXECUTE AS SELF )
-- Crée la notification
IF EXISTS ( SELECT *
FROM sys.server_event_notifications
WHERE name = 'NotifyLocks' )
DROP EVENT NOTIFICATION NotifyLocks ON SERVER
GO
CREATE EVENT NOTIFICATION NotifyLocks ON SERVER
WITH fan_in FOR blocked_process_report TO SERVICE 'NotifyBlockingService', 'current database' ;
GO
La table BlockingEventsXML contient ce que nous renvoie l'évènement dans son format XML d'origine. Améliorons la visualisation en créant une vue qui rende les choses plus lisibles :
/*-------------------------------------------------------------------
[SCRIPT] BlockingEvents
[DATABASE] ADMIN_SQL
[DESCRIPTION] Vue tabulaire de la table BlockingEventsXML
[MAJ PAR] DATAFLY - Arian Papillon
[DATEMAJ]
-------------------------------------------------------------------*/
CREATE VIEW dbo.BlockingEvents
AS
SELECT a.EventTime
, EventData.value('(/EVENT_INSTANCE/StartTime)[1]', 'datetime') StartTime
, DB_NAME(EventData.value('(/EVENT_INSTANCE/DatabaseID)[1]', 'int')) DBName
, Y.x.value('@spid', 'nvarchar(45)') BlockingSpid
, X.x.value('@spid', 'nvarchar(45)') BlockedSpid
, X.x.value('@id', 'nvarchar(45)') BlockedId
, Y.x.value('@hostname', 'nvarchar(45)') BlockingFromHost
, Y.x.value('@loginname', 'nvarchar(45)') BlockingFromLogin
, Y.x.value('@isolationlevel', 'nvarchar(45)') BlockingFromIso
, Y.x.value('data(.)', 'varchar(5000)') AS BlockingSQLcmd
,
-- Y.x.value('@waitresource', 'nvarchar(45)') BlockingObject ,
DB_NAME(X.x.value('@currentdb', 'int')) Blockeddb
, X.x.value('@waitresource', 'nvarchar(45)') BlockedObject
, X.x.value('@lockMode', 'nvarchar(45)') BlockedBlockLockMode
, X.x.value('@hostname', 'nvarchar(45)') BlockedFromHOst
, X.x.value('@loginname', 'nvarchar(45)') BlockedFromLogin
, X.x.value('@clientapp', 'nvarchar(45)') BlockedClientApp
, X.x.value('@isolationlevel', 'nvarchar(45)') BlockedFromIso
, X.x.value('data(.)', 'varchar(5000)') AS BlockedSQLcmd
FROM dbo.BlockingEventsXML a
CROSS APPLY EventData.nodes('EVENT_INSTANCE/TextData/blocked-process-report/blocked-process/process')
AS X ( x )
CROSS APPLY EventData.nodes('EVENT_INSTANCE/TextData/blocked-process-report/blocking-process/process')
AS Y ( x )
Et voici le résultat...
