Blog

Erreur : Transaction log for database ‘xxx’ is full due to ‘ACTIVE_TRANSACTION’


Qui a fait tomber le sapin de Noël ??? Le fichier de transaction d’une base de données a grossit de façon exponentielle. Dans le cas présent, il s’agit de la base de données tempdb, jusqu’à saturation du disque ( Operating system error 112 (There is not enough space on the disk.) encountered) ou dès que la taille limite du fichier de log est atteinte. L’erreur est bien reportée dans le journal SQL Server. Bien que le journal de transaction soit plein, il est impossible de procéder à un skrink, précisément pour cette raison : une transaction est active. Cela étant, le fait que le fichier de transaction soit plein n’est pas le fond du problème, c’est une conséquence.

Expert SQL Server - Erreur : Transaction log for database 'xxx' is full due to 'ACTIVE_TRANSACTION' - SQL Server  - tempdb_transaction_log_tempdb_is_full

Essayons de reproduire le phénomène. Est-il besoin de le préciser, sait-on jamais : ailleurs qu’en PRODUCTION, idéalement sur une instance bac à sable où vous êtes seul.

Expert SQL Server - Erreur : Transaction log for database 'xxx' is full due to 'ACTIVE_TRANSACTION' - SQL Server  - dynamite_kitty

Créons une table dans tempdb :

Dans la même session, lançons une transaction d’injection de données, plus ou moins longue que nous plaçons en attente pendant 30 secondes (à personnaliser au besoin) pour nous donner le temps d’observer ce qui se passe à l’arrière boutique. Et enfin faisons comme si, nous ne connaissions pas le coupable :

DBCC OPENTRAN

Rien de mieux qu’un DBCC et quelques DMV pour accéder à l’arrière boutique. Comme son nom l’indique DBCC OPENTRAN permet d’obtenir la transaction active la plus ancienne dans le contexte indiqué, en l’occurrence pour la base de données tempdb :

On obtient en sortie : le SPID (55) correspond bien à la session depuis laquelle nous avons lancé l’injection de données. La date supposée de notre transaction est bien le 19 décembre 2017 à 20h59… Dans la vraie vie, la transaction date très souvent de methusalem (Start time), initiée par Duncan MacLeod dans ses jeunes années.

Expert SQL Server - Erreur : Transaction log for database 'xxx' is full due to 'ACTIVE_TRANSACTION' - SQL Server  - dbcc_opentran_msg

La sortie peut être redirigée vers un resultset au besoin en vue d’exploiter les données par la suite, comme ceci :

Ce qui donne :

Expert SQL Server - Erreur : Transaction log for database 'xxx' is full due to 'ACTIVE_TRANSACTION' - SQL Server  - dbcc_opentran_result

Pour lancer un DBCC OPENTRAN sur toutes les bases de données et afficher le résultat en mode classique :

Expert SQL Server - Erreur : Transaction log for database 'xxx' is full due to 'ACTIVE_TRANSACTION' - SQL Server  - dbcc_opentran_tab

 

DBCC INPUTBUFFER

Maintenant qu’on tient un suspect, le but du jeu est d’obtenir le maximum d’informations, typiquement en effectuant un DBCC INPUTBUFFER de la session en cause :

Expert SQL Server - Erreur : Transaction log for database 'xxx' is full due to 'ACTIVE_TRANSACTION' - SQL Server  - dbcc_inputbuffer_logfull

Dans le cas présent le résultat est assez clair : la requête remontée dans EventInfo correspond bien à celle que nous avons lancée précédemment pour l’injection de données.

sys.dm_exec_cursors

Cependant, dans un contexte réel, le résultat n’est pas toujours à la hauteur de nos attentes. Il peut s’agir d’un curseur appelé via une API côté applicatif et dans ce cas EventInfo affichera quelque chose dans le genre :

FETCH API_CURSOR0000000000000004

Expert SQL Server - Erreur : Transaction log for database 'xxx' is full due to 'ACTIVE_TRANSACTION' - SQL Server  - sapin_sans_boule

Comme dirait l’autre, c’est un peu comme se retrouver avec un sapin sans boule ou presque. Dans ce cas on fera appel à la fonction sys.dm_exec_cursors pour obtenir le détail qui nous fait tant défaut :

Un très bon post sur le sujet : https://www.sqlskills.com/blogs/joe/hunting-down-the-origins-of-fetch-api_cursor-and-sp_cursorfetch/

sys.dm_tran_*_transactions

Le niveau de détail est encore faible. On peut clairement faire mieux en interrogeant les DMV liées aux transactions, à savoir sys.dm_tran_database_transactions et sys.dm_tran_session_transactions en pré filtrant sur notre session d’injection de données (55) et l’état des transaction (en cours) :

La requête va nous fournir de précieuses informations sur le contexte de la transaction :

– login_name
– host_name
– program_name
– client_net_address (IP cliente)

Cette requête peut être lancée sans être précédée d’un DBCC OPENTRAN et DBCC INPUTBUFFER. Alors pourquoi ne pas l’avoir dit plus tôt ? On fait semblant de ne pas connaître le coupable ! Le résultat va aussi nous donner des précisions sur la requête (sql_statement), voir l’objet associé (object_name : procédure stockée ou autre) mais également nous permettre de quantifier la consommation dans le journal de transaction, voir colonnes :

– database_transaction_log_record_count
– database_transaction_log_bytes_used
– database_transaction_log_bytes_reserved

Expert SQL Server - Erreur : Transaction log for database 'xxx' is full due to 'ACTIVE_TRANSACTION' - SQL Server  - transaction_infos

On ne va pas énumérer toutes les colonnes en sortie, chacun fait son marché. Le but de cet article était de remonter progressivement le fils pour identifier la transaction susceptible d’être responsable de la croissance inopinée de la base de données tempdb.

Cause(s)

Concrètement, cet incident m’avait été remonté par un client qui avait effectué une migration de version de SQL Server 2008 R2 vers SQL Server 2014. Le driver ODBC n’était pas à jour sur les machines clientes. Il a suffit d’installer la bonne version sur les clients identifiés par leur IP (client_net_address) pour corriger le problème. Ce n’est pas l’unique cause mais c’est relativement courant.

Expert SQL Server - Erreur : Transaction log for database 'xxx' is full due to 'ACTIVE_TRANSACTION' - SQL Server  - chat_noël

Industrialisation

Une fois le problème identifié, un rapport HTML adressé via DatabaseMail a été mis en place pour remonter les machines à l’origine de transactions restant ouvertes, en vue de mettre à jour leur driver ODBC.

1) Le paramètre @TranDelayInMinute (10 minutes par défaut) sert à filtrer sur la durée minium d’une transaction.
2) Il y a une exclusion sur l’objet sp_readrequest qui est appelé en boucle par DatabaseMail

Pour l’envoie de mail embarquant le résultat de la requête, soit la liste des transactions ouvertes dans un tableau HTML, je me suis largement inspirée de cette source pour styliser un peu le contenu :
https://www.sqlshack.com/format-dbmail-with-html-and-css
Attention aux valeurs nulles, elles créent des décalages dans le tableau si elles ne sont pas remplacées. Voici un exemple de rapport :

Expert SQL Server - Erreur : Transaction log for database 'xxx' is full due to 'ACTIVE_TRANSACTION' - SQL Server  - open_tran_mail

Reste à créer le job qui exécutera la procédure stockée comme suit à intervalle régulier :

En cas d’alerte…

Et pour finir, si vous recevez un rapport faisant état de transactions ouvertes sur une période suffisamment critique, lancez les actions suivantes :

– Vérifier si la transaction est toujours en cours
– Vérifier qu’il ne s’agit pas d’une transaction orpheline (mauvaise gestion des transactions, driver ODBC obsolète, etc)
– Transmettez les infos collectées aux équipes de développement et/ou aux métiers  (host_name, client_net_address, etc)
– Analyser la requête en question (durée d’exécution conforme ou non)
– Killer la session en dernier recours

Auteur

Expert SQL Server - Erreur : Transaction log for database 'xxx' is full due to 'ACTIVE_TRANSACTION' - SQL Server  - avatar_ninja_tete-150x150
Sarah Béquet
Archietcte Data Microsoft, les maîtres mots sont : performance, industrialisation, méthodologie & bonne humeur.
error: