Comment suivre les blocages dans Firebird
Alexey Kovyazin, 08-May-2019, (c) IBSurgeon
Les conflits de mise à jour (souvent appelés « deadlocks ») surviennent dans les applications Firebird qui effectuent des mises à jour concurrentes intensives de données.
Comme vous pouvez le voir dans l’article « Transactions in Firebird », il existe 3 types d’erreurs contenant le mot-clé « deadlock » :
deadlock
-update conflicts with concurrent update
-concurrent transaction number is NNN
lock time-out on wait transaction
-deadlock
-update conflicts with concurrent update
-concurrent transaction number is NNN
lock conflict on no wait transaction
-deadlock
-update conflicts with concurrent update
-concurrent transaction number is NNN
Les 3 types de conflits de mise à jour ont en commun le fait que le conflit de mise à jour est généralement le résultat de 2 opérations de modification qui tentent de modifier le même enregistrement.
Les options possibles sont les suivantes : UPDATE, DELETE SELECT WITH LOCK, MERGE, UPDATE OR INSERT.
Il est relativement facile de suivre l’opération « victime », qui reçoit le message d’erreur - il suffit de la placer dans try… catch et de journaliser les paramètres utilisés dans la requête qui échoue sur l’erreur.
Cependant, avec cette approche, il est difficile de suivre le « gagnant » - c’est-à-dire la transaction concurrente où la mise à jour a été effectuée avec succès, sans erreur.
Pour aider les développeurs à enquêter sur les conflits de mise à jour, Firebird place dans les messages d’erreur la référence à la transaction concurrente - c’est-à-dire la transaction où la mise à jour concurrente n’est pas encore validée. Avec l’API Trace, cela nous donne la capacité de suivre les deux opérations conflictuelles.
Examinons les étapes pratiques pour y parvenir.
Tout d’abord, nous devons configurer le tracing. Pour cela, créez le fichier texte (dans notre cas, C:\Temp\mytrace.conf) avec le contenu suivant :
database
{
enabled = true
include_filter="(UPDATE%)|(DELETE%)|(MERGE%)|(SELECT%FROM%WITH LOCK)|(UPDATE OR INSERT%)"
log_statement_finish = true
log_errors = true
include_gds_codes="deadlock"
log_initfini = false
time_threshold = 0
max_sql_length = 65000
}
Le fichier de configuration ci-dessus active le tracing pour toutes les bases de données, donc si vous avez plus d’une base de données active, il est préférable de spécifier le nom de la base de données dans le fichier de configuration, c’est-à-dire :
Database=mydatabase.fdb
{
enabled = true
…
}
Examinons les paramètres les plus importants du fichier de configuration :
Paramètre include filter
include_filter="(UPDATE%)|(DELETE%)|(MERGE%)|(SELECT%FROM%WITH LOCK)|(UPDATE OR INSERT%)"
Cela signifie que nous voulons suivre uniquement les instructions UPDATE et DELETE et ignorer les SELECT. Il est nécessaire de filtrer autant que possible les instructions, car dans un système de production sous forte charge, la quantité d’enregistrements dans le journal texte peut être trop importante pour être analysée.
Habituellement, nous savons quelle table participe au conflit de mise à jour ; la bonne idée sera de la mettre dans le filtre, pour réduire le nombre de mises à jour à analyser :
include_filter="(UPDATE T1%)|(DELETE FROM T1%)|(MERGE INTO T1%)|(SELECT% FROM T1%WITH lock%)|(UPDATE OR INSERT INTO T1%)"
Et si les mises à jour et les suppressions sont effectuées par des procédures stockées ? Eh bien, cela rend le processus plus difficile : ajoutez au filtre toutes les procédures stockées qui peuvent être impliquées dans des mises à jour concurrentes, et activez également la journalisation des procédures :
include_filter="(UPDATE T1%)|(DELETE FROM T1%)|(MERGE INTO T1%)|(SELECT% FROM T1%with lock%)|(UPDATE OR INSERT INTO T1%)|(%SP_UPDATE_T1%)|(%SP_DEL_T1%)"
log_procedures=true
Paramètres de journalisation des erreurs
Ensuite, nous devons spécifier la journalisation des erreurs et la limiter aux deadlocks.
log_errors = true
include_gds_codes="deadlock"
Veuillez noter : le paramètre include_gds_codes n’apparaît qu’à partir de Firebird 3.0.2, donc si vous utilisez 2.5 ou 3.0.0 ou 3.0.1, il n’est pas possible de filtrer uniquement les erreurs de deadlock, donc toutes les erreurs seront imprimées dans le journal.
Démonstration
Pour démontrer le processus global, préparons la base de données de test - pour simplifier, il y aura 1 table avec 1 colonne de clé primaire.
C:\HQbird\Firebird30>isql
Use CONNECT or CREATE DATABASE to specify a database
SQL> create database "c:\temp\testdeadlock.fdb" user "SYSDBA" password "masterkey";
SQL> create table t1(i1 integer not null primary key);
SQL> insert into t1(i1) values(1);
SQL> commit; exit;
Après cela, nous devons démarrer la session de trace :
fbtracemgr.exe -se localhost:service_mgr -start -conf "C:\temp\mytrace.conf" -user SYSDBA -pass masterkey
Dans ce cas, fbtracemgr imprime le journal à l’écran, mais en production, nous devons le rediriger vers un fichier, bien sûr.
Après le démarrage réussi, fbtracemgr imprime quelque chose comme ceci :
Trace session ID 4 started
Ensuite, démarrons 2 sessions isql et essayons de simuler le conflit de mise à jour. Dans le tableau ci-dessous, nous avons 2 colonnes pour 2 sessions isql. Chaque ligne représente un moment dans le temps où les commandes ont été exécutées.
| Temps | session isql 1 | session isql 2 |
| T1 | <br>isql -user SYSDBA -pass masterkey localhost:c:\temp\testdeadlock.fdb<br>Database: localhost:c:\temp\testdeadlock.fdb, User: SYSDBA<br>SQL> set transaction wait;<br>Commit current transaction (y/n)?y<br>Committing.<br>SQL> select current_transaction from rdb$database;<br> CURRENT_TRANSACTION<br>=====================<br> 15<br>SQL> select * from t1;<br> I1<br>============<br> 2<br>SQL><br> |
|
| T2 | <br>isql -user SYSDBA -pass masterkey localhost:c:\temp\testdeadlock.fdb<br>Database: localhost:c:\temp\testdeadlock.fdb, User: SYSDBA<br>SQL> set transaction wait;<br>Commit current transaction (y/n)?y<br>Committing.<br>SQL> select current_transaction from rdb$database;<br> CURRENT_TRANSACTION<br>=====================<br> 20<br>SQL> select * from t1;<br> I1<br>============<br> 2<br>SQL><br> |
|
| Donc, au point de départ, nous pouvons voir que 2 transactions sont démarrées, #15 et #20. Ensuite, essayons d’effectuer la mise à jour concurrente du même enregistrement : | ||
| T3 | <br>SQL> UPDATE T1 SET i1=5 where i1=2;<br> |
|
| T4 | <br>SQL> UPDATE T1 SET i1=100 where i1=2;<br> |
|
| T5 | <br>SQL> commit;<br>SQL><br> |
<br>Statement failed, SQLSTATE = 40001<br>deadlock<br>-update conflicts with concurrent update<br>-concurrent transaction number is 15<br>SQL><br> |
Nous avons démarré UPDATE dans la session 1 mais ne l’avons pas validé.
Dans la session 2, UPDATE « s’est bloqué » - il a attendu la fin de la transaction concurrente, et lorsque nous avons validé UPDATE dans la session 1, la session 2 a reçu l’erreur :
Statement failed, SQLSTATE = 40001
deadlock
-update conflicts with concurrent update
-concurrent transaction number is 15
SQL>
Nous avons donc une situation typique en cas de conflit de mise à jour avec transaction en attente.
Examinons le journal de trace pour trouver les preuves du conflit de mise à jour.
Dans ce cas, le journal de trace est très court, mais dans le cas d’un système de production, il peut être beaucoup plus long, mais l’approche pour trouver les deadlocks est la même.
fbtracemgr.exe -se localhost:service_mgr -start -conf "C:\temp\fbtrace.conf" -user SYSDBA -pass masterkey
Trace session ID 4 started
2019-05-07T11:28:43.9850 (2692:00000000018C1940) EXECUTE_STATEMENT_FINISH
C:\TEMP\TESTDEADLOCK.FDB (ATT_12, SYSDBA:NONE, NONE, TCPv6:::1/52938)
C:\HQbird\Firebird30\isql.exe:8828
(TRA_15, CONCURRENCY | WAIT | READ_WRITE)
Statement 52:
-------------------------------------------------------------------------------
UPDATE T1 SET i1=5 where i1=2
0 records fetched
0 ms, 2 read(s), 21 fetch(es), 3 mark(s)
2019-05-07T11:29:45.0190 (2692:00000000018C0040) FAILED EXECUTE_STATEMENT_FINISH
C:\TEMP\TESTDEADLOCK.FDB (ATT_13, SYSDBA:NONE, NONE, TCPv6:::1/52968)
C:\HQbird\Firebird30\isql.exe:7032
(TRA_20, CONCURRENCY | WAIT | READ_WRITE)
Statement 55:
-------------------------------------------------------------------------------
UPDATE T1 SET i1=100 where i1=2
0 records fetched
40242 ms, 19 fetch(es), 2 mark(s)
2019-05-07T11:29:45.0190 (2692:00000000018C0040) ERROR AT JStatement::execute
C:\TEMP\TESTDEADLOCK.FDB (ATT_13, SYSDBA:NONE, NONE, TCPv6:::1/52968)
C:\HQbird\Firebird30\isql.exe:7032
335544336 : deadlock
335544451 : update conflicts with concurrent update
335544878 : concurrent transaction number is 15
Comme vous pouvez le voir, nous avons des enregistrements dans le journal concernant les deux mises à jour - réussie et échouée - et un message d’erreur concernant le deadlock.
Examinons comment analyser le journal :
Dans le message d’erreur, localisons l’identifiant de la transaction :
2019-05-07T11:29:45.0190 (2692:00000000018C0040) ERROR AT JStatement::execute
C:\TEMP\TESTDEADLOCK.FDB (ATT_13, SYSDBA:NONE, NONE, TCPv6:::1/52968)
C:\HQbird\Firebird30\isql.exe:7032
335544336 : deadlock
335544451 : update conflicts with concurrent update
335544878 : concurrent transaction number is 15
Près de l’enregistrement concernant l’erreur (généralement juste au-dessus), vous verrez l’instruction échouée :
2019-05-07T11:29:45.0190 (2692:00000000018C0040) FAILED EXECUTE_STATEMENT_FINISH
C:\TEMP\TESTDEADLOCK.FDB (ATT_13, SYSDBA:NONE, NONE, TCPv6:::1/52968)
C:\HQbird\Firebird30\isql.exe:7032
(TRA_20, CONCURRENCY | WAIT | READ_WRITE)
Statement 55:
-------------------------------------------------------------------------------
UPDATE T1 SET i1=100 where i1=2
0 records fetched
40242 ms, 19 fetch(es), 2 mark(s)
Notez que le temps d’exécution est énorme (~40 secondes) - cela indique le temps pendant lequel l’opération a attendu le résultat de la transaction concurrente.
Et enfin, recherchez le numéro de transaction avec l’opération UPDATE réussie : pour cela, localisez TRA_NNN, où NNN est le numéro de transaction. Dans notre cas, ce sera TRA_15 :
2019-05-07T11:28:43.9850 (2692:00000000018C1940) EXECUTE_STATEMENT_FINISH
C:\TEMP\TESTDEADLOCK.FDB (ATT_12, SYSDBA:NONE, NONE, TCPv6:::1/52938)
C:\HQbird\Firebird30\isql.exe:8828
(TRA_15, CONCURRENCY | WAIT | READ_WRITE)
Statement 52:
-------------------------------------------------------------------------------
UPDATE T1 SET i1=5 where i1=2
0 records fetched
0 ms, 2 read(s), 21 fetch(es), 3 mark(s)
Voilà, c’est tout - nous avons trouvé les deux parties du conflit de mise à jour - la réussie et l’échouée.
Outils pour identifier les deadlocks
Comme vous pouvez le voir, il peut être assez difficile d’identifier la source racine du conflit de verrouillage/deadlock : puisque le conflit a toujours 2 côtés, et qu’un côté « gagne » (se termine sans messages d’erreur), il peut être délicat d’identifier le gagnant. Par exemple, le conflit peut survenir à l’intérieur d’EXECUTE STATEMENT, ou dans une procédure stockée imbriquée, ou à l’intérieur d’un déclencheur, ou il pourrait s’agir d’une combinaison de toutes ces choses.
Afin d’identifier les deadlocks, IBSurgeon a développé l’outil « Deadlock Analyzer », qui analyse le journal de trace et crée des diagrammes faciles à comprendre avec les détails des appels qui ont conduit aux deadlocks. Cet outil est disponible dans le cadre de l’Enterprise Subscription (il a un essai) - inscrivez-vous sur cc.ib-aid.com.
De plus, HQbird introduit une version étendue du plugin fbtrace, qui peut être configurée pour enregistrer uniquement les modifications et les tentatives de modifications (c’est-à-dire les opérations échouées et les conflits de verrouillage et les deadlocks).
Contactez le support IBSurgeon pour obtenir plus d’informations à ce sujet : [email protected].
Comment éviter les deadlocks ?
Maintenant, vous devez identifier la meilleure solution pour votre application afin d’éviter les deadlocks - cela peut être un changement des paramètres de transaction, ou il est possible d’ajouter un traitement d’erreur supplémentaire et de répéter l’opération ou d’effectuer des vérifications supplémentaires au niveau métier de l’application.