Identifier les problèmes de blocages

Comment reconnaître un problème de blocages, mettre en place la collecte des rapports de processus bloqués, et transmettre les fichiers pour analyse.

Categories:

SQL Server

TL;DR

Un blocage se produit quand une session attend un verrou détenu par une autre session. Pour savoir qui bloque quoi, on active le seuil de processus bloqués (blocked process threshold) et on démarre une session d’évènements étendus qui enregistre un rapport à chaque blocage dépassant ce seuil. Vous laissez tourner quelques jours, vous compressez les fichiers .xel et vous les transmettez pour analyse. L’impact sur la production est négligeable.

Cette page est une procédure à suivre de bout en bout. Si vous êtes pressé, les cinq étapes sont : définir le seuil, créer la session, laisser tourner, récupérer les fichiers, nettoyer.

À quoi sert cette collecte

Les blocages proviennent de verrous maintenus sur les mêmes ressources par des sessions différentes. Une session qui attend un verrou ne consomme pas de CPU : elle attend, et l’utilisateur devant son écran attend avec elle. Du point de vue de l’application, cela ressemble à une « lenteur SQL Server », alors que le serveur ne fait rien du tout.

Le diagnostic est difficile après coup, parce que le blocage ne laisse aucune trace : quand vous regardez, il est déjà terminé. C’est pourquoi il faut instrumenter le serveur avant que le problème se reproduise.

Le rapport de processus bloqué (blocked process report) répond exactement aux questions utiles :

quelle session attendait, et depuis combien de temps ;
quelle session la bloquait, quelle requête elle exécutait, et depuis quelle machine ;
sur quel objet, quel index, et avec quel mode de verrouillage ;
si la session bloquante était en train de travailler, ou simplement endormie avec une transaction ouverte — le cas de loin le plus fréquent.

Avant de commencer : est-ce bien un problème de blocages ?

Inutile d’instrumenter si le problème est ailleurs. Deux vérifications rapides.

Les statistiques d’attente

Les attentes accumulées depuis le démarrage de l’instance vous disent si le verrouillage pèse réellement. Exécutez la requête d’analyse des attentes :

Statistiques d'attente

Voir le fichier

---------------------------------------------------------------------------------------------------------
-- copied from https://www.sqlskills.com/blogs/paul/wait-statistics-or-please-tell-me-where-it-hurts/
-- please refer to the original query!
-- copied here for my own usage, selecting wait types I want to filter out.
---------------------------------------------------------------------------------------------------------

SET NOCOUNT ON;
SET TRANSACTION ISOLATION LEVEL READ UNCOMMITTED;
GO

WITH [Waits] AS
    (SELECT
        [wait_type],
        [wait_time_ms] / 1000.0 AS [WaitS],
        ([wait_time_ms] - [signal_wait_time_ms]) / 1000.0 AS [ResourceS],
        [signal_wait_time_ms] / 1000.0 AS [SignalS],
        [waiting_tasks_count] AS [WaitCount],
        100.0 * [wait_time_ms] / SUM ([wait_time_ms]) OVER() AS [Percentage],
        ROW_NUMBER() OVER(ORDER BY [wait_time_ms] DESC) AS [RowNum]
    FROM sys.dm_os_wait_stats
    WHERE [wait_type] NOT IN (
        N'BROKER_EVENTHANDLER',
        N'BROKER_RECEIVE_WAITFOR',
        N'BROKER_TASK_STOP',
        N'BROKER_TO_FLUSH',
        N'BROKER_TRANSMITTER',
        N'CHECKPOINT_QUEUE',
        N'CHKPT',
        N'CLR_AUTO_EVENT',
        N'CLR_MANUAL_EVENT',
        N'CLR_SEMAPHORE',
        N'KSOURCE_WAKEUP',
        N'LAZYWRITER_SLEEP',
        N'LOGMGR_QUEUE',
        N'MEMORY_ALLOCATION_EXT',
        N'ONDEMAND_TASK_QUEUE',
        N'PARALLEL_REDO_DRAIN_WORKER',
        N'PARALLEL_REDO_LOG_CACHE',
        N'PARALLEL_REDO_TRAN_LIST',
        N'PARALLEL_REDO_WORKER_SYNC',
        N'PARALLEL_REDO_WORKER_WAIT_WORK',
        N'PREEMPTIVE_OS_FLUSHFILEBUFFERS',
        N'PREEMPTIVE_XE_GETTARGETSTATE',
        N'PWAIT_ALL_COMPONENTS_INITIALIZED',
        N'PWAIT_DIRECTLOGCONSUMER_GETNEXT',
        N'QDS_PERSIST_TASK_MAIN_LOOP_SLEEP',
        N'QDS_ASYNC_QUEUE',
        N'QDS_CLEANUP_STALE_QUERIES_TASK_MAIN_LOOP_SLEEP',
        N'QDS_SHUTDOWN_QUEUE',
        N'REDO_THREAD_PENDING_WORK',
        N'REQUEST_FOR_DEADLOCK_SEARCH',
        N'RESOURCE_QUEUE',
        N'SERVER_IDLE_CHECK',
        N'SLEEP_BPOOL_FLUSH',
        N'SLEEP_DBSTARTUP',
        N'SLEEP_DCOMSTARTUP',
        N'SLEEP_MASTERDBREADY',
        N'SLEEP_MASTERMDREADY',
        N'SLEEP_MASTERUPGRADED',
        N'SLEEP_MSDBSTARTUP',
        N'SLEEP_SYSTEMTASK',
        N'SLEEP_TASK',
        N'SLEEP_TEMPDBSTARTUP',
        N'SNI_HTTP_ACCEPT',
        N'SOS_WORK_DISPATCHER',
        N'SP_SERVER_DIAGNOSTICS_SLEEP',
        N'SQLTRACE_BUFFER_FLUSH',
        N'SQLTRACE_INCREMENTAL_FLUSH_SLEEP',
        N'SQLTRACE_WAIT_ENTRIES',
        N'VDI_CLIENT_OTHER',
        N'WAIT_FOR_RESULTS',
        N'WAITFOR',
        N'WAITFOR_TASKSHUTDOWN',
        N'WAIT_XTP_RECOVERY',
        N'WAIT_XTP_HOST_WAIT',
        N'WAIT_XTP_OFFLINE_CKPT_NEW_LOG',
        N'WAIT_XTP_CKPT_CLOSE',
        N'XE_DISPATCHER_JOIN',
        N'XE_DISPATCHER_WAIT',
        N'XE_TIMER_EVENT',
        N'XE_LIVE_TARGET_TVF', -- xevents target
        N'CXCONSUMER' -- Just the consumer of exchange events in //
        )
	AND [wait_type] NOT IN ( -- mirroring
        
        N'DBMIRROR_DBM_EVENT',
        N'DBMIRROR_EVENTS_QUEUE',
        N'DBMIRROR_WORKER_QUEUE',
        N'DBMIRRORING_CMD',
        N'DIRTY_PAGE_POLL',
        N'DISPATCHER_QUEUE_SEMAPHORE',
        N'EXECSYNC',
        N'FSAGENT',
        N'FT_IFTS_SCHEDULER_IDLE_WAIT',
        N'FT_IFTSHC_MUTEX'
	)
	AND [wait_type] NOT IN ( -- AlwaysOn
        N'HADR_CLUSAPI_CALL', 
        N'HADR_FILESTREAM_IOMGR_IOCOMPLETION', 
        N'HADR_LOGCAPTURE_WAIT', 
        N'HADR_NOTIFICATION_DEQUEUE', 
        N'HADR_TIMER_TASK',
        N'HADR_WORK_QUEUE'
	)
    AND [wait_type] NOT IN ( -- 2012 only ?
        -- N'PREEMPTIVE_HADR_LEASE_MECHANISM', -- sign of lease timeout ...
        N'PREEMPTIVE_SP_SERVER_DIAGNOSTICS',
        N'PREEMPTIVE_XE_DISPATCHER'
    )
    AND [wait_type] NOT IN ( -- 2019
        N'PWAIT_EXTENSIBILITY_CLEANUP_TASK'
    )
    AND [waiting_tasks_count] > 0
    )
SELECT
    MAX ([W1].[wait_type]) AS [WaitType],
    CAST (MAX ([W1].[WaitS]) AS DECIMAL (16,2)) AS [Wait_S],
    CAST (MAX ([W1].[ResourceS]) AS DECIMAL (16,2)) AS [Resource_S],
    CAST (MAX ([W1].[SignalS]) AS DECIMAL (16,2)) AS [Signal_S],
    MAX ([W1].[WaitCount]) AS [WaitCount],
    CAST (MAX ([W1].[Percentage]) AS DECIMAL (5,2)) AS [Percentage],
    CAST ((MAX ([W1].[WaitS]) / MAX ([W1].[WaitCount])) AS DECIMAL (16,4)) AS [AvgWait_S],
    CAST ((MAX ([W1].[ResourceS]) / MAX ([W1].[WaitCount])) AS DECIMAL (16,4)) AS [AvgRes_S],
    CAST ((MAX ([W1].[SignalS]) / MAX ([W1].[WaitCount])) AS DECIMAL (16,4)) AS [AvgSig_S]
FROM [Waits] AS [W1]
INNER JOIN [Waits] AS [W2] ON [W2].[RowNum] <= [W1].[RowNum]
GROUP BY [W1].[RowNum]
HAVING SUM ([W2].[Percentage]) - MAX( [W1].[Percentage] ) < 95 -- percentage threshold
OPTION (RECOMPILE, MAXDOP 1);

Vous pouvez aussi utiliser la version de référence de Paul Randal, tell me where it hurts.

Cherchez les attentes dont le wait_type commence par LCK_M_. Si elles figurent dans les premières lignes du résultat, ou si elles représentent une part significative du temps d’attente total, la collecte décrite ci-dessous en vaut la peine.

Les statistiques d’attente sont cumulées depuis le dernier redémarrage de l’instance (ou depuis la dernière remise à zéro). Si l’instance vient de redémarrer, les chiffres ne sont pas représentatifs : attendez quelques jours d’activité normale.

Les blocages en cours, à un instant T

Si le problème est en train de se produire pendant que vous lisez ces lignes, vous pouvez voir la situation immédiatement :

Sessions bloquées à un instant T

Voir le fichier

-----------------------------------------------------------------
-- blocking sessions

-- rudi@babaluga.com, go ahead license
-----------------------------------------------------------------

SET NOCOUNT ON;
SET TRANSACTION ISOLATION LEVEL READ UNCOMMITTED;
GO

;WITH
    cte
    AS
    (
        SELECT DISTINCT
            CAST(ws1.wait_duration_ms / 1000.0 as decimal(10, 2)) as wait_duration_sec,
            ws1.wait_type as wait_type,
            ws1.session_id as session_id,
            ws1.blocking_session_id as blocking_session_id,
            ws1.resource_description,
            CHARINDEX('objid=',ws1.resource_description) + 6 AS resource_description_start,
            der.command,
            CASE 
            WHEN der.statement_start_offset > 0 AND der.statement_end_offset > 0 THEN 
                SUBSTRING(txt.text, 
                    der.statement_start_offset / 2, 
                    (der.statement_end_offset - der.statement_start_offset) / 2) 
            ELSE txt.text END as text_offset,
            OBJECT_NAME(txt.objectid, der.database_id) as [proc],
            der.database_id
        FROM sys.dm_os_waiting_tasks ws1
            JOIN sys.dm_exec_sessions ses ON ws1.blocking_session_id = ses.session_id
            JOIN sys.dm_exec_requests der ON ws1.session_id = der.session_id
            OUTER APPLY sys.dm_exec_sql_text (der.sql_handle) txt

        WHERE ws1.blocking_session_id > 0
            AND ws1.blocking_session_id <> ws1.session_id
            AND ws1.wait_type LIKE 'LCK%'
            AND ses.session_id NOT IN (SELECT ws2.session_id
            FROM sys.dm_os_waiting_tasks ws2
            WHERE ws2.blocking_session_id > 0)
    ),
    cte2
    AS
    (
        SELECT wait_duration_sec
        , wait_type
        , session_id
        , blocking_session_id
        , resource_description
        , resource_description_start
        , command
        , text_offset
        , [proc]
        , database_id
        , TRY_CAST(SUBSTRING(resource_description, resource_description_start,
        CHARINDEX(' ', resource_description, resource_description_start)-resource_description_start) AS INT) AS [object_id]
        FROM cte
    )
SELECT 
    *
    , DB_NAME(database_id) as [db]
	, OBJECT_NAME(object_id, database_id) AS [table]
FROM cte2
OPTION (RECOMPILE, MAXDOP 1);

La colonne wait_duration_sec indique depuis combien de secondes chaque session attend, et blocking_session_id désigne la session responsable.

C’est utile pour éteindre un incendie, mais cela ne remplace pas la collecte : vous n’aurez jamais la requête au bon moment.

Prérequis

Point	Détail
Version	SQL Server 2008 et ultérieur. Pour Azure SQL Database, voir l’encadré en fin de page.
Permissions	`ALTER ANY EVENT SESSION` et `VIEW SERVER STATE` sur l’instance, plus `ALTER SETTINGS` (ou `sysadmin`) pour exécuter `sp_configure`.
Redémarrage	Aucun. Ni la modification du seuil, ni la création de la session ne nécessitent de redémarrer SQL Server ni de couper les connexions.
Espace disque	500 Mo au maximum dans le répertoire des journaux de SQL Server, avec les valeurs proposées ici (10 fichiers de 50 Mo).

Est-ce que cela va ralentir la production ?

Non, dans des proportions mesurables. Le moniteur de processus bloqués s’exécute sur le thread qui détecte déjà les verrous mortels, à intervalle de quelques secondes. Il ne pose aucun verrou supplémentaire et n’ajoute rien au chemin d’exécution des requêtes.

Le seul coût réel est l’écriture des évènements sur disque, et un rapport n’est produit que lorsqu’un blocage dépasse le seuil que vous définissez. Sur une instance saine, la session ne génère quasiment rien. Sur une instance qui souffre de blocages, elle produit exactement ce que l’on cherche à mesurer.

Évitez simplement un seuil très bas (moins de 5 secondes) sur une instance déjà fortement bloquée : vous produiriez un volume d’évènements inutilement important, sans information supplémentaire.

Étape 1 — Définir le seuil de processus bloqués

Le seuil détermine à partir de combien de secondes d’attente un blocage mérite d’être enregistré. Tant qu’il vaut 0, aucun rapport n’est produit, même si la session d’évènements tourne. C’est l’oubli le plus courant.

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';
RECONFIGURE WITH OVERRIDE;
GO
EXEC sys.sp_configure N'show advanced options', N'0';
RECONFIGURE WITH OVERRIDE;
GO

Quelle valeur choisir ?

Valeur	Effet
`0`	Fonctionnalité désactivée. C’est la valeur par défaut.
`5`	Valeur minimale utile. Verbeux sur une instance chargée, mais pertinent si vos utilisateurs se plaignent de micro-attentes.
`10`	Le bon choix par défaut pour une collecte de diagnostic. Un blocage de dix secondes est déjà perceptible par un utilisateur.
`30`	Ne remonte que les blocages longs et douloureux. À utiliser si le seuil de 10 secondes produit trop de bruit.

Commencez à 10. Vous pourrez toujours l’ajuster ensuite : la modification est prise en compte immédiatement, sans toucher à la session d’évènements.

Vous pouvez aussi configurer ce seuil dans SSMS, dans les propriétés de l’instance, onglet Advanced :

Le paramètre blocked process threshold dans les propriétés de l’instance SSMS

Étape 2 — Créer et démarrer la session d’évènements

Le script suivant contient les trois opérations : le réglage du seuil (identique à l’étape 1), la création de la session, et son démarrage.

Créer la session blocked_processes

Voir le fichier

-----------------------------------------------------------------
-- create the blocked process report event session
--
-- rudi@babaluga.com, go ahead license
-----------------------------------------------------------------
-- Requires: ALTER ANY EVENT SESSION, and ALTER SETTINGS (or sysadmin)
--           for the sp_configure part.
--
-- The blocked_process_report event is ONLY raised if the
-- 'blocked process threshold (s)' setting is greater than 0.
-- Step 1 is therefore mandatory.
-----------------------------------------------------------------

-----------------------------------------------------------------
-- step 1 : set the blocked process threshold
--
-- The event is raised when a session has been blocked for at
-- least this number of seconds, and then once per monitor loop
-- for as long as the block lasts.
--
-- 0  = feature disabled (default)
-- 5  = minimum useful value, verbose on a busy instance
-- 10 = good default for a diagnostic collection
-- 30 = only the long, painful blocks
-----------------------------------------------------------------
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';
RECONFIGURE WITH OVERRIDE;
GO
EXEC sys.sp_configure N'show advanced options', N'0';
RECONFIGURE WITH OVERRIDE;
GO

-----------------------------------------------------------------
-- step 2 : create the session
--
-- The event file is written to the SQL Server error log
-- directory. Replace the filename with a full path
-- (N'D:\xevents\blocked_processes.xel') to write it elsewhere:
-- the SQL Server service account needs write access to it.
--
-- max_file_size    : 50 MB per file
-- max_rollover_files : 10 files kept, so 500 MB at most on disk
-----------------------------------------------------------------
CREATE EVENT SESSION [blocked_processes] ON SERVER
ADD EVENT sqlserver.blocked_process_report
ADD TARGET package0.event_file (
    SET filename = N'blocked_processes',
        max_file_size = (50),
        max_rollover_files = (10)
)
WITH (
    MAX_DISPATCH_LATENCY = 30 SECONDS,
    EVENT_RETENTION_MODE = ALLOW_SINGLE_EVENT_LOSS,
    STARTUP_STATE = OFF
);
GO

-----------------------------------------------------------------
-- step 3 : start the session
-----------------------------------------------------------------
ALTER EVENT SESSION [blocked_processes] ON SERVER STATE = START;
GO

-----------------------------------------------------------------
-- check that the session is running and where it writes
-----------------------------------------------------------------
SELECT s.name,
       s.create_time,
       CAST(t.target_data AS xml).value('(/EventFileTarget/File/@name)[1]', 'nvarchar(max)') AS current_file
FROM sys.dm_xe_sessions AS s
JOIN sys.dm_xe_session_targets AS t
    ON t.event_session_address = s.address
WHERE s.name = N'blocked_processes'
  AND t.target_name = N'event_file';

-- to stop the session and clean everything up,
-- see blocked-processes-cleanup.sql

Si vous avez déjà fait l’étape 1, n’exécutez que la partie CREATE EVENT SESSION, puis le démarrage :

ALTER EVENT SESSION [blocked_processes] ON SERVER STATE = START;

Quelques points à connaître sur cette session :

Les évènements sont écrits dans des fichiers .xel placés dans le répertoire des journaux d’erreur de SQL Server. Pour les écrire ailleurs, remplacez filename = N'blocked_processes' par un chemin complet, sur un disque où le compte de service SQL Server a le droit d’écrire.
max_file_size = 50 et max_rollover_files = 10 bornent l’occupation disque à 500 Mo. Au-delà, les fichiers les plus anciens sont recyclés : vous perdez le début de la collecte, jamais la fin.
STARTUP_STATE = OFF fait que la session ne redémarre pas automatiquement si l’instance redémarre. Si votre collecte doit survivre à un redémarrage planifié, passez cette option à ON.

Vérifiez que la session tourne bien et repérez le fichier courant :

SELECT s.name,
       s.create_time,
       CAST(t.target_data AS xml).value('(/EventFileTarget/File/@name)[1]', 'nvarchar(max)') AS current_file
FROM sys.dm_xe_sessions AS s
JOIN sys.dm_xe_session_targets AS t
    ON t.event_session_address = s.address
WHERE s.name = N'blocked_processes'
  AND t.target_name = N'event_file';

Si cette requête ne renvoie aucune ligne, la session existe mais n’est pas démarrée.

Étape 3 — Laisser tourner la collecte

C’est l’étape qui demande le plus de patience, et celle qu’on écourte le plus souvent à tort.

Laissez la session tourner au minimum une semaine complète, et dans tous les cas suffisamment longtemps pour couvrir :

plusieurs journées ouvrées entières, aux horaires où les utilisateurs se plaignent ;
au moins un cycle de traitements de nuit (sauvegardes, imports, réindexation) ;
si vos blocages sont liés à un rythme métier — clôture mensuelle, inventaire, fin de trimestre — la période concernée.

Une collecte de deux heures un mardi matin calme ne contient généralement rien d’exploitable.

Pendant cette période, vous n’avez rien à surveiller de particulier. Si vous voulez vérifier que des évènements sont bien capturés, exécutez la requête de lecture :

Lire les blocages capturés

Voir le fichier

-----------------------------------------------------------------
-- read the blocked process report event session
-- from the event_file target of the running session
--
-- rudi@babaluga.com, go ahead license
-----------------------------------------------------------------
-- To read .xel files collected on another instance, use
-- blocked-processes-read-file.sql instead.
-----------------------------------------------------------------

SET NOCOUNT ON;
SET TRANSACTION ISOLATION LEVEL READ UNCOMMITTED;

DECLARE @last int = 100;

-- resolve the file name pattern configured on the session,
-- so that all rollover files are read, running or not
DECLARE @configured nvarchar(1000) = (
    SELECT CAST(f.value AS nvarchar(1000))
    FROM sys.server_event_sessions AS s
    JOIN sys.server_event_session_targets AS t
        ON t.event_session_id = s.event_session_id AND t.name = N'event_file'
    JOIN sys.server_event_session_fields AS f
        ON f.event_session_id = t.event_session_id AND f.object_id = t.target_id AND f.name = N'filename'
    WHERE s.name = N'blocked_processes');

IF @configured IS NULL
BEGIN
    RAISERROR(N'The blocked_processes session does not exist, or has no event_file target.', 16, 1);
    RETURN;
END

DECLARE @file nvarchar(max) =
    CASE WHEN @configured LIKE N'%.xel' THEN REPLACE(@configured, N'.xel', N'*.xel')
         ELSE CONCAT(@configured, N'*.xel')
    END;

-- a relative file name lands in the SQL Server error log directory
IF CHARINDEX(CHAR(92), @file) = 0
    SET @file = CONCAT(
        LEFT(CAST(SERVERPROPERTY('ErrorLogFileName') AS nvarchar(max)),
             LEN(CAST(SERVERPROPERTY('ErrorLogFileName') AS nvarchar(max))) - LEN('ERRORLOG')),
        @file);

;WITH xe AS (
    SELECT ts_utc,
           XMLData,
           XMLData.query('(/event/data[@name="blocked_process"]/value/blocked-process-report)[1]') AS report
    FROM (
        SELECT timestamp_utc          AS ts_utc,
               CONVERT(xml, event_data) AS XMLData
        FROM sys.fn_xe_file_target_read_file(@file, NULL, NULL, NULL)
    ) AS src
)
SELECT TOP (@last)
       DATEADD(MINUTE, DATEDIFF(MINUTE, GETUTCDATE(), GETDATE()), xe.ts_utc) AS [local_time],
       xe.XMLData.value('(/event/data[@name="duration"]/value)[1]', 'bigint') / 1000000 AS duration_sec,
       xe.XMLData.value('(/event/data[@name="lock_mode"]/text)[1]', 'varchar(20)')      AS lock_mode,
       DB_NAME(xe.XMLData.value('(/event/data[@name="database_id"]/value)[1]', 'smallint')) AS [database],
       CONCAT(QUOTENAME(OBJECT_SCHEMA_NAME(
                  xe.XMLData.value('(/event/data[@name="object_id"]/value)[1]', 'int'),
                  xe.XMLData.value('(/event/data[@name="database_id"]/value)[1]', 'smallint')), N'.',
              QUOTENAME(OBJECT_NAME(
                  xe.XMLData.value('(/event/data[@name="object_id"]/value)[1]', 'int'),
                  xe.XMLData.value('(/event/data[@name="database_id"]/value)[1]', 'smallint')))) AS [object],
       xe.XMLData.value('(/event/data[@name="index_id"]/value)[1]', 'int')            AS index_id,
       -- victim
       xe.report.value('(blocked-process/process/@spid)[1]', 'int')                   AS blocked_spid,
       xe.report.value('(blocked-process/process/@waittime)[1]', 'bigint') / 1000     AS blocked_wait_sec,
       xe.report.value('(blocked-process/process/@waitresource)[1]', 'nvarchar(500)') AS blocked_wait_resource,
       xe.report.value('(blocked-process/process/@isolationlevel)[1]', 'nvarchar(100)') AS blocked_isolation,
       xe.report.value('(blocked-process/process/@loginname)[1]', 'nvarchar(128)')    AS blocked_login,
       xe.report.value('(blocked-process/process/@hostname)[1]', 'nvarchar(128)')     AS blocked_host,
       xe.report.value('(blocked-process/process/@clientapp)[1]', 'nvarchar(128)')    AS blocked_app,
       xe.report.value('(blocked-process/process/inputbuf)[1]', 'nvarchar(max)')      AS blocked_input_buffer,
       -- culprit
       xe.report.value('(blocking-process/process/@spid)[1]', 'int')                  AS blocking_spid,
       -- 'sleeping' with an open transaction means the application
       -- opened a transaction and did not commit it
       xe.report.value('(blocking-process/process/@status)[1]', 'nvarchar(30)')       AS blocking_status,
       xe.report.value('(blocking-process/process/@trancount)[1]', 'int')             AS blocking_trancount,
       xe.report.value('(blocking-process/process/@transactionname)[1]', 'nvarchar(128)') AS blocking_transaction,
       xe.report.value('(blocking-process/process/@lastbatchstarted)[1]', 'nvarchar(30)')   AS blocking_last_batch_started,
       xe.report.value('(blocking-process/process/@lastbatchcompleted)[1]', 'nvarchar(30)') AS blocking_last_batch_completed,
       xe.report.value('(blocking-process/process/@loginname)[1]', 'nvarchar(128)')   AS blocking_login,
       xe.report.value('(blocking-process/process/@hostname)[1]', 'nvarchar(128)')    AS blocking_host,
       xe.report.value('(blocking-process/process/@clientapp)[1]', 'nvarchar(128)')   AS blocking_app,
       xe.report.value('(blocking-process/process/inputbuf)[1]', 'nvarchar(max)')     AS blocking_input_buffer,
       xe.report                                                                      AS blocked_process_report
FROM xe
ORDER BY xe.ts_utc DESC
OPTION (RECOMPILE, MAXDOP 1);

Notez au fil de l’eau les moments où les utilisateurs signalent une lenteur, avec l’heure et si possible l’écran ou la fonction concernée. Ces quelques lignes valent souvent autant que les fichiers de trace : elles permettent de relier un rapport technique à un symptôme métier.

Étape 4 — Récupérer et transmettre les fichiers

Localiser les fichiers

Par défaut, les fichiers se trouvent dans le répertoire des journaux d’erreur de SQL Server. Pour en connaître le chemin exact :

SELECT SERVERPROPERTY('ErrorLogFileName');

Le résultat ressemble à C:\Program Files\Microsoft SQL Server\MSSQL16.MSSQLSERVER\MSSQL\Log\ERRORLOG. Le répertoire est tout ce qui précède ERRORLOG.

Vous y trouvez les fichiers nommés blocked_processes_0_<horodatage>.xel, dix au maximum.

Arrêter la session, puis compresser

Le fichier en cours d’écriture peut être copié pendant que la session tourne, mais il est plus propre d’arrêter la session d’abord : vous êtes certain que tous les évènements ont été écrits sur disque.

ALTER EVENT SESSION [blocked_processes] ON SERVER STATE = STOP;

Ensuite, depuis PowerShell sur le serveur, en adaptant les deux premiers chemins :

$log  = 'C:\Program Files\Microsoft SQL Server\MSSQL16.MSSQLSERVER\MSSQL\Log'
$dest = 'C:\temp\blocages'

New-Item -ItemType Directory -Path $dest -Force | Out-Null
Copy-Item -Path (Join-Path $log 'blocked_processes*.xel') -Destination $dest

Compress-Archive -Path (Join-Path $dest '*.xel') -DestinationPath 'C:\temp\blocages.zip' -Force

Get-Item 'C:\temp\blocages.zip' |
    Select-Object Name, @{ Name = 'Mo'; Expression = { [math]::Round($_.Length / 1MB, 1) } }

Le taux de compression de ces fichiers est très élevé : 500 Mo de .xel se réduisent couramment à quelques mégaoctets. L’archive est donc facile à transmettre par courriel ou par un lien de partage.

Ce que vous devez transmettre

L’archive blocages.zip produite ci-dessus.
La version exacte de l’instance, obtenue par SELECT @@VERSION;.
La période couverte par la collecte : date et heure de début, date et heure de fin.
Vos notes d’incidents : les moments où les utilisateurs ont signalé une lenteur, et ce qu’ils faisaient.

Les points 3 et 4 sont ceux qui font gagner le plus de temps à l’analyse. Les horodatages contenus dans les fichiers sont en UTC : précisez le fuseau horaire du serveur si celui-ci n’est pas en heure de Paris.

Les rapports contiennent le texte des requêtes exécutées, ce qui peut inclure des valeurs de paramètres — donc potentiellement des données de production. Traitez l’archive comme une donnée sensible et transmettez-la par un canal approprié.

Étape 5 — Nettoyer

Une fois les fichiers récupérés et transmis, retirez l’instrumentation. Ne le faites pas avant d’avoir copié les fichiers.

Arrêter et supprimer la session

Voir le fichier

-----------------------------------------------------------------
-- stop and remove the blocked process report event session
--
-- rudi@babaluga.com, go ahead license
-----------------------------------------------------------------
-- Run this once the .xel files have been collected.
-- Do NOT run it before you have copied the files: dropping the
-- session does not delete them, but you lose the easy way to
-- locate them.
-----------------------------------------------------------------

-----------------------------------------------------------------
-- step 1 : stop the session
-----------------------------------------------------------------
IF EXISTS (SELECT * FROM sys.dm_xe_sessions WHERE name = N'blocked_processes')
    ALTER EVENT SESSION [blocked_processes] ON SERVER STATE = STOP;
GO

-----------------------------------------------------------------
-- step 2 : drop the session definition
-----------------------------------------------------------------
IF EXISTS (SELECT * FROM sys.server_event_sessions WHERE name = N'blocked_processes')
    DROP EVENT SESSION [blocked_processes] ON SERVER;
GO

-----------------------------------------------------------------
-- step 3 : disable the blocked process monitor
--
-- Leave this out if you want to keep raising the event for
-- another session, or for a SQL Server Agent alert.
-----------------------------------------------------------------
EXEC sys.sp_configure N'show advanced options', N'1';
RECONFIGURE WITH OVERRIDE;
GO
EXEC sys.sp_configure N'blocked process threshold (s)', N'0';
RECONFIGURE WITH OVERRIDE;
GO
EXEC sys.sp_configure N'show advanced options', N'0';
RECONFIGURE WITH OVERRIDE;
GO

-----------------------------------------------------------------
-- step 4 : the .xel files are still on disk. Delete them from
-- the operating system, or use management/delete-event-files.sql
-----------------------------------------------------------------

Ce script arrête la session, supprime sa définition, et remet le seuil de processus bloqués à 0. Les fichiers .xel restent sur le disque : supprimez-les depuis le système d’exploitation quand vous n’en avez plus besoin.

Si vous souhaitez au contraire conserver la surveillance en place de façon permanente, n’exécutez pas ce script du tout : laissez le seuil configuré et la session enregistrer en continu. Les fichiers se recyclent d’eux-mêmes une fois les 500 Mo atteints, le coût reste faible, et vous disposerez toujours de l’historique des derniers blocages le jour où le problème se reproduit. Pensez alors à passer STARTUP_STATE à ON pour que la session survive aux redémarrages de l’instance.

Annexes

Lire soi-même les fichiers

Vous pouvez ouvrir un fichier .xel directement dans SQL Server Management Studio (Fichier → Ouvrir → Fichier), ce qui affiche les évènements dans une grille. Le rapport complet se trouve dans la colonne blocked_process, au format XML.

Pour une lecture plus lisible sous forme de tableau, avec les colonnes utiles extraites du XML :

Lire des fichiers .xel collectés ailleurs

Voir le fichier

-----------------------------------------------------------------
-- read blocked process report .xel files collected elsewhere
--
-- rudi@babaluga.com, go ahead license
-----------------------------------------------------------------
-- Use this to analyse files sent by a customer, on your own
-- instance. To read the files of a session running on the local
-- instance, use blocked-processes-read.sql instead.
--
-- Unzip the files in a directory readable by the SQL Server
-- service account of the instance you are running this on.
--
-- database_id and object_id are NOT resolved, since the metadata
-- belongs to the source instance. Use the report XML and the
-- database_id / object_id columns, or run the resolution on the
-- source instance.
-----------------------------------------------------------------

SET NOCOUNT ON;
SET TRANSACTION ISOLATION LEVEL READ UNCOMMITTED;

-------------------------------------------------------------
-- SET THE PATH TO THE .xel FILES HERE (wildcard is supported)
DECLARE @file nvarchar(max) = N'C:\temp\blocked_processes*.xel';
-------------------------------------------------------------

DECLARE @last int = 500;

-- the timestamps below are UTC, as recorded on the source
-- instance; set the offset of the source server to convert them
DECLARE @utc_offset_hours int = 0;

;WITH xe AS (
    SELECT ts_utc,
           XMLData,
           XMLData.query('(/event/data[@name="blocked_process"]/value/blocked-process-report)[1]') AS report
    FROM (
        SELECT timestamp_utc          AS ts_utc,
               CONVERT(xml, event_data) AS XMLData
        FROM sys.fn_xe_file_target_read_file(@file, NULL, NULL, NULL)
    ) AS src
)
SELECT TOP (@last)
       DATEADD(HOUR, @utc_offset_hours, xe.ts_utc)                                    AS [source_time],
       xe.XMLData.value('(/event/data[@name="duration"]/value)[1]', 'bigint') / 1000000 AS duration_sec,
       xe.XMLData.value('(/event/data[@name="lock_mode"]/text)[1]', 'varchar(20)')    AS lock_mode,
       xe.XMLData.value('(/event/data[@name="database_id"]/value)[1]', 'smallint')    AS database_id,
       xe.XMLData.value('(/event/data[@name="object_id"]/value)[1]', 'int')           AS object_id,
       xe.XMLData.value('(/event/data[@name="index_id"]/value)[1]', 'int')            AS index_id,
       xe.report.value('(blocked-process/process/@currentdbname)[1]', 'nvarchar(128)') AS blocked_database,
       -- victim
       xe.report.value('(blocked-process/process/@spid)[1]', 'int')                   AS blocked_spid,
       xe.report.value('(blocked-process/process/@waittime)[1]', 'bigint') / 1000     AS blocked_wait_sec,
       xe.report.value('(blocked-process/process/@waitresource)[1]', 'nvarchar(500)') AS blocked_wait_resource,
       xe.report.value('(blocked-process/process/@isolationlevel)[1]', 'nvarchar(100)') AS blocked_isolation,
       xe.report.value('(blocked-process/process/@loginname)[1]', 'nvarchar(128)')    AS blocked_login,
       xe.report.value('(blocked-process/process/@hostname)[1]', 'nvarchar(128)')     AS blocked_host,
       xe.report.value('(blocked-process/process/@clientapp)[1]', 'nvarchar(128)')    AS blocked_app,
       xe.report.value('(blocked-process/process/inputbuf)[1]', 'nvarchar(max)')      AS blocked_input_buffer,
       -- culprit
       xe.report.value('(blocking-process/process/@spid)[1]', 'int')                  AS blocking_spid,
       -- 'sleeping' with an open transaction means the application
       -- opened a transaction and did not commit it
       xe.report.value('(blocking-process/process/@status)[1]', 'nvarchar(30)')       AS blocking_status,
       xe.report.value('(blocking-process/process/@trancount)[1]', 'int')             AS blocking_trancount,
       xe.report.value('(blocking-process/process/@transactionname)[1]', 'nvarchar(128)') AS blocking_transaction,
       xe.report.value('(blocking-process/process/@lastbatchstarted)[1]', 'nvarchar(30)')   AS blocking_last_batch_started,
       xe.report.value('(blocking-process/process/@lastbatchcompleted)[1]', 'nvarchar(30)') AS blocking_last_batch_completed,
       xe.report.value('(blocking-process/process/@loginname)[1]', 'nvarchar(128)')   AS blocking_login,
       xe.report.value('(blocking-process/process/@hostname)[1]', 'nvarchar(128)')    AS blocking_host,
       xe.report.value('(blocking-process/process/@clientapp)[1]', 'nvarchar(128)')   AS blocking_app,
       xe.report.value('(blocking-process/process/inputbuf)[1]', 'nvarchar(max)')     AS blocking_input_buffer,
       xe.report                                                                      AS blocked_process_report
FROM xe
ORDER BY xe.ts_utc DESC
OPTION (RECOMPILE, MAXDOP 1);

Ce script lit des fichiers déposés dans un répertoire quelconque, y compris ceux provenant d’une autre instance. Le compte de service de SQL Server doit avoir accès au répertoire où vous les avez décompressés.

Comprendre les modes de verrouillage

Dans les statistiques d’attente, les modes apparaissent avec le préfixe LCK_M_. Dans le rapport de processus bloqué, le champ lock_mode utilise la forme courte, sans préfixe : S, X, IX…

Mode	Signification	Ce que cela indique en général
`S` (`LCK_M_S`)	Verrou partagé	Une lecture attend qu’une écriture se termine. Candidat classique pour le RCSI.
`U` (`LCK_M_U`)	Verrou de mise à jour	Une modification cherche les lignes à modifier. Souvent le signe d’un balayage faute d’index.
`X` (`LCK_M_X`)	Verrou exclusif	Une écriture attend une autre écriture sur la même ligne ou la même page.
`IS`, `IU`, `IX`	Verrous d’intention	Verrous posés aux niveaux supérieurs (page, table) pour annoncer une intention. `IX` signifie qu’une session veut écrire quelque part dans l’objet.
`SCH_S`	Stabilité de schéma	Une requête empêche la modification de la structure d’un objet pendant qu’elle l’utilise.
`SCH_M`	Modification de schéma	Un DDL, une reconstruction d’index ou un `TRUNCATE TABLE` bloque tout le monde sur l’objet. Regardez l’heure : c’est souvent un traitement de maintenance.
`RangeS-S`, `RangeS-U`, `RangeX-X`	Verrous de plage	Niveau d’isolation `SERIALIZABLE`. Une plage de clés entière est verrouillée.
`BU`	Bulk update	Import en masse avec `TABLOCK`.

Un mode IX ou X attendu au niveau de la table, alors que la requête ne modifie qu’une poignée de lignes, est le symptôme d’une escalade de verrous : SQL Server a converti des milliers de verrous de ligne en un seul verrou de table.

Que faire des résultats

Les causes les plus fréquentes, par ordre décroissant de probabilité :

Une transaction laissée ouverte par l’application. Dans le rapport, la session bloquante a le statut sleeping avec un trancount supérieur à zéro : elle ne fait plus rien mais détient toujours ses verrous. Le problème est dans le code client, pas dans SQL Server.
Une transaction trop longue, qui enchaîne des allers-retours avec le client, ou qui exécute des traitements sans rapport entre le BEGIN TRANSACTION et le COMMIT.
Un index manquant, qui force un balayage complet et donc la pose de verrous sur des lignes qui n’ont rien à voir avec la requête.
Des lectures qui bloquent des écritures, en niveau d’isolation READ COMMITTED classique. C’est le cas où l’activation de RCSI apporte le plus, souvent sans modifier une ligne de code applicatif.
Une maintenance mal planifiée : réindexation, mise à jour de statistiques ou import en masse pendant les heures ouvrées.

Pour la démarche de diagnostic globale, voir Diagnostiquer les problèmes de performances.

Le cas d’Azure SQL Database

Sur Azure SQL Database, la procédure diffère sur trois points :

sp_configure n’est pas disponible, et le seuil de processus bloqués est fixé à 20 secondes, sans possibilité de le modifier ;
la session se crée au niveau de la base (ON DATABASE) et non de l’instance ;
la cible est un ring_buffer en mémoire, ou un fichier dans un conteneur Azure Blob Storage.

Créer la session sur Azure SQL Database

Voir le fichier

--------------------------------------------------------------------
-- create blocked process report event session on Azure SQL Database 
-- Blocked process threshold is set at 20, no way to change it on 
-- Azure SQL.
--
-- rudi@babaluga.com, go ahead license
--------------------------------------------------------------------

CREATE EVENT SESSION [blocked_processes] ON DATABASE 
ADD EVENT sqlserver.blocked_process_report
ADD TARGET package0.ring_buffer
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=OFF,STARTUP_STATE=OFF)
GO

-- start the session
ALTER EVENT SESSION [blocked_processes] ON DATABASE STATE=START;

-- stop the sesison
ALTER EVENT SESSION [blocked_processes] ON DATABASE STATE=STOP;

Sur Azure SQL Managed Instance, la procédure de cette page s’applique telle quelle.

Expertise SQL Server Besoin de services avec SQL Server ? Contactez-moi et parlons de votre projet