Si vous administrez un tant soit peu un serveur SQL, il vous est probablement arrivé de devoir traiter d’une problématique de DeadLock.
pour mémoire, le DeadLock est le stade utile d’un situation de verrouillage où il n’existe pas de solution car chacun des processus impliqués attend que l’autre se termine afin de pouvoir continuer son traitement. L’histoire du serpent qui se mort la queue pour faire simple.
Dans des version « préhistoriques » de SQL Server, on faisait appel à des Trace Flags afin d’enregistrer els informations dans le fichier errorlog, afin de pouvoir comprendre et dépanner ces sutuations.
Avec l’arrivée des xEvents, et principalement de la sessionSystem_health, nul besoin des TF 3605, 1204 et 1205. Par défaut tout est enregistré ….
Voici le bout de code que je vais utiliser afin de provoquer le dead lock sur la base AdventureWorks
-- Session 1
Use AdventureWorks
GO
BEGIN TRAN
update Production.Product
set name = 'Session 1 - Product 722'
where ProductID = 722
-- Session 2
Use AdventureWorks
GO
BEGIN TRAN
update Production.Product
set name = 'Session 2 - Product 512'
where ProductID = 512
-- Session 1
update Production.Product
set name = 'Session 1 - Product 512'
where ProductID = 512
A ce stade, rien de particulier, simple situation de blocage, il suffit qu’une des session fasse un COMMIT ou un ROLLBACK, les verrous seront levés et donc la seconde session pourra se terminer normalement. La commande UPDATE de la session 1 est bloquée par l’update de la session 2. Le verrou Exclusif de la session 2, qui a été posé sur l’enregistrement 512 est incompatible avec le verrou exclusif demandé par la session 1 sur ce même enregistrement.
Tout se complique lorsque la session 2 veut accéder à la ressource qui est déjà verrouillée par la session 1, l’enregistrement 722.
-- Session 2
update Production.Product
set name = 'Session 2 - Product 722'
where ProductID = 722
La situation est inextricable, car chacune des sessions attend que l’autre ait terminé pour se terminer.
SQL Server doit prendre une décision et tuer un des processus.
le xEvent System_Health enregistre l’évènement dans le ring buffer et dans un fichier xel afin de résister à un restart de SQL Server.
L’onglet Deadlock nous permet de visualiser la situation :
Si l’on s’attarde avec la souris sur les processus, on peut visualiser les requêtes mises en cause. Dans notre exemple, le deadlock est simple, mais il peut arriver que le nombre de process impliqués soit plus important. La requête nous renseigne sur les ressources lockées, mais si cela se produit avec des index noncluster (ah….les index avec colonne incluse et les index composites …), le troubleshooting est un peu plus complexe.
En creusant un peu, toutes les informations sont présentes afin de découvrir quels sont les enregistrements impliqués. Nous allons donc décoder les informations renvoyées.
Nous allons nous plonger dans la version XML du deadlock.
<deadlock>
<victim-list>
<victimProcess id="process22fa607d848" />
</victim-list>
<process-list>
<process id="process22fa607d848" taskpriority="0" logused="2076"
waitresource="KEY: 5:72057594045136896 (4637a194cfd9)" waittime="138859" ownerId="246372"
transactionname="user_transaction" lasttranstarted="2021-02-15T16:40:45.307" XDES="0x22f970fc428"
lockMode="U" schedulerid="6" kpid="7164" status="suspended" spid="76" sbid="0" ecid="0" priority="0"
trancount="2" lastbatchstarted="2021-02-15T16:41:00.320" lastbatchcompleted="2021-02-15T16:41:00.307"
lastattention="1900-01-01T00:00:00.307" clientapp="Microsoft SQL Server Management Studio - Query"
hostname="X1CARBON7TH" hostpid="1620" loginname="X1CARBON7TH\chris" isolationlevel="read committed (2)"
xactid="246372" currentdb="5" currentdbname="AdventureWorks" lockTimeout="4294967295"
clientoption1="671090784" clientoption2="390200">
<executionStack>
<frame procname="adhoc" line="1" stmtstart="2" stmtend="176" sqlhandle="0x020000003c46ff230e8ad1d8bbb3b8dea1a668590c8e06da0000000000000000000000000000000000000000">
unknown </frame>
<frame procname="adhoc" line="1" stmtstart="2" stmtend="176" sqlhandle="0x020000009f4c85181b7afcb14ee5aa3466b9df887ae827bf0000000000000000000000000000000000000000">
unknown </frame>
</executionStack>
<inputbuf>
update Production.Product
set name = 'Session 1 - Product 512'
where ProductID = 512 </inputbuf>
</process>
<process id="process22f8d89c4e8" taskpriority="0" logused="6304"
waitresource="KEY: 5:72057594045136896 (b147776edda1)" waittime="4401" ownerId="246434"
transactionname="user_transaction" lasttranstarted="2021-02-15T16:40:53.210" XDES="0x22f8cfac428"
lockMode="U" schedulerid="2" kpid="2892" status="suspended" spid="87" sbid="0" ecid="0" priority="0"
trancount="2" lastbatchstarted="2021-02-15T16:43:14.723" lastbatchcompleted="2021-02-15T16:43:14.710"
lastattention="1900-01-01T00:00:00.710" clientapp="Microsoft SQL Server Management Studio - Query"
hostname="X1CARBON7TH" hostpid="1620" loginname="X1CARBON7TH\chris" isolationlevel="read committed (2)"
xactid="246434" currentdb="5" currentdbname="AdventureWorks" lockTimeout="4294967295"
clientoption1="671090784" clientoption2="390200">
<executionStack>
<frame procname="adhoc" line="1" stmtstart="2" stmtend="176" sqlhandle="0x020000003c46ff230e8ad1d8bbb3b8dea1a668590c8e06da0000000000000000000000000000000000000000">
unknown </frame>
<frame procname="adhoc" line="1" stmtstart="2" stmtend="176" sqlhandle="0x0200000060843c2be9d50655cbffbb6a0c183e87382ea3b20000000000000000000000000000000000000000">
unknown </frame>
</executionStack>
<inputbuf>
update Production.Product
set name = 'Session 2 - Product 722'
where ProductID = 722 </inputbuf>
</process>
</process-list>
<resource-list>
<keylock hobtid="72057594045136896" dbid="5" objectname="AdventureWorks.Production.Product" indexname="PK_Product_ProductID" id="lock22f904aae80" mode="X" associatedObjectId="72057594045136896">
<owner-list>
<owner id="process22f8d89c4e8" mode="X" />
</owner-list>
<waiter-list>
<waiter id="process22fa607d848" mode="U" requestType="wait" />
</waiter-list>
</keylock>
<keylock hobtid="72057594045136896" dbid="5" objectname="AdventureWorks.Production.Product" indexname="PK_Product_ProductID" id="lock22fa0a1ee00" mode="X" associatedObjectId="72057594045136896">
<owner-list>
<owner id="process22fa607d848" mode="X" />
</owner-list>
<waiter-list>
<waiter id="process22f8d89c4e8" mode="U" requestType="wait" />
</waiter-list>
</keylock>
</resource-list>
</deadlock>
Nous allons nous intéresser à la propriété WaitRessource qui détient la clé (sans jeu de mot !) du problème.
La base de données N°5 correspond effectivement au numéro de la base AdventureWorks.
L’information suivante est un HOBT (Heap or BTree). Et l’on retrouve notre table Production.Product.
SELECT c.name as schema_name,
o.name as object_name,
i.name as index_name,
p.object_id,p.index_id,p.partition_id,p.hobt_id
FROM sys.partitions AS p
INNER JOIN sys.objects as o on p.object_id=o.object_id
INNER JOIN sys.indexes as i on p.index_id=i.index_id and p.object_id=i.object_id
INNER JOIN sys.schemas AS c on o.schema_id=c.schema_id
WHERE p.hobt_id = 72057594045136896;
Bon, OK, trouver la table n’était pas vraiment compliqué.
On va faire appel à une commande magique afin de trouver les enregistrements impliqués dans le Deadlock. Il suffit de recopier la valeur entre parenthèses de la propriété WaitRessource que nous allons appeler KeyHashValue.
Grâce à la fonction non documentée %%lockres%%, il devient simple de retrouver les enregistrements concernés.
On retrouve par ailleurs cette information lorsque l’on visualise les données de la page via DBCC PAGE.
Grâce à une seconde fonction magique, sys.fn_physlocFormatter, nous pouvons retrouver quelle datapage contient l’enregistrement en question. Nous allons nous focaliser sur le productID 512 qui est donc présent dans la page 788 du fichier n°1, à l’emplacement 0.
DBCC TRACEON(3604)
DBCC PAGE('Adventureworks',1,788,3)
Je ne vais pas détailler dans ce post les information renvoyées par DBCC PAGE, la partie Header en particulier. Ensuite, on va trouver les enregistrements, donc l’enregistrement slot 0. Attention, Slot 0 ne signifie pas forcément le premier enregistrement de la datapage, il faut se référer au tableau d’offset en bas de page pour connaitre à quel emplacement retrouver l’enregistrement.
On retrouve la valeur KeyHashValue qui était présente dans le xml_deadlock_report. Nous somme donc bien sur l’enregistrement qui est impliqué dans le verrou. Enregistrement d’un index cluster, les données donc, ou bien d’un index non cluster, cela ne changerait rien.
Il suffit de procéder de même avec le second enregistrement pour terminer la résolution de cet incident.
Pour les adeptes du journal de transactions, il est possible d’y retrouver les informations de verrouillage directement. Il est possible de visualiser le contenu du journal actif avec fn_dblog() ou bien dans une sauvegardes au travers de fn_dump_dblog().
Si l’on repart des transactions, identifiées par les paramètres xactid dans le xml_deadlock_report, il est possible de retrouver les mêmes informations.
SELECT [Operation],[Context,SPID],[Transaction SID],[Xact ID],[Transaction ID],[Page ID],
[Slot ID],AllocUnitName,[Lock Information],[Begin Time],[End Time]
FROM sys.fn_dblog(null,null)
WHERE [Transaction ID] in (
SELECT [Transaction ID]
FROM sys.fn_dblog(null,null)
WHERE [Xact ID] IN (246372,246434)
)
On retrouve les numéros de page dans lesquelles trouver les enregistrements, notée en hexadécimal, 314 et 318 correspondant respectivement aux valeurs 788 et 789. On retrouve ensuite la propriété KeyHashValue dans la colonne LockInformation.
Au passage, si vous souhaitez savoir qui a passé la commande, la colonne [Transaction SID] correspond au SID que vous trouvez dans server_principal et/ou database_principal.
Au travers de quelques lignes de code il a été relativement simple de déterminer quels étaient les enregistrements impliqués dans un deadlock.
Comment éviter cette situation d’interblocage ? Cette fois, la réponse est loin d’être simple. Peu de possibilités côté DBA : on peut essayer de positionner des index nonclustered afin de permettre à SQL Server d’accéder aux enregistrements de manière différente, mais rien de garanti. On peut faire usage du RCSI ou bien du niveau d’isolation SNAPSHOT, mais cela peut aussi changer le comportement de l’application. Généralement, le problème se situe au niveau du code client, accéder aux tables dans le même ordre, limiter au maximum la durée et les ressources consommées par les transactions, éviter toute interaction utilisateur durant une transaction.
Pensez également à bien clore vos transactions, durant mes audits, je constate malheureusement trop souvent des sessions sleeping durant des heures avec des transactions ouvertes. Là, désolé, je ne peux plus rien faire pour vous. Toutes les actions en base de données doivent être réalisées de la sorte:
– Ouvrir une connexion
– Optionnellement créer une transaction
– Exécuter la requête
– Si une transaction a été ouverte, COMMITER ou ROLLBACKer la transaction
– Fermer la connexion.
Le pool de connexion se chargera de maintenir la connexion ouverte pour être réutilisée. A cela pensez à ajouter une logique de Retry, avec un délai constant ou croissant entre chaque tentative et vous vous rapprochez des bonnes pratiques.
Happy xml_deadlock_report !
Christophe LAPORTE - Consultant SQL Server 