L'une des erreurs les plus courantes d'InnoDB est le dépassement du délai d'attente du verrouillage InnoDB, par exemple :
SQLSTATE[HY000]: General error: 1205 Lock wait timeout exceeded; try restarting transactionCe qui précède signifie simplement que la transaction a atteint le innodb_lock_wait_timeout en attendant d'obtenir un verrou exclusif qui par défaut est de 50 secondes. Les causes courantes sont :
- La transaction offensante n'est pas assez rapide pour valider ou annuler la transaction dans la durée innodb_lock_wait_timeout.
- La transaction offensive attend que le verrou de ligne soit libéré par une autre transaction.
Les effets d'un délai d'attente de verrouillage InnoDB
Le délai d'attente du verrou InnoDB peut avoir deux conséquences majeures :
- L'instruction ayant échoué n'est pas annulée par défaut.
- Même si innodb_rollback_on_timeout est activé, lorsqu'une instruction échoue dans une transaction, ROLLBACK reste une opération plus coûteuse que COMMIT.
Jouons avec un exemple simple pour mieux comprendre l'effet. Considérez les deux tables suivantes dans la base de données mydb :
mysql> CREATE SCHEMA mydb;
mysql> USE mydb;Le premier tableau (table1) :
mysql> CREATE TABLE table1 ( id INT PRIMARY KEY AUTO_INCREMENT, data VARCHAR(50));
mysql> INSERT INTO table1 SET data = 'data #1';Le deuxième tableau (table2) :
mysql> CREATE TABLE table2 LIKE table1;
mysql> INSERT INTO table2 SET data = 'data #2';Nous avons exécuté nos transactions en deux sessions différentes dans l'ordre suivant :
| Commander | Transaction #1 (T1) | Transaction n° 2 (T2) |
| 1 | SELECT * FROM table1 ; (OK) | SELECT * FROM table1 ; (OK) |
| 2 | UPDATE table1 SET data ='T1 met à jour la ligne' WHERE id =1 ; (OK) | |
| 3 | UPDATE table2 SET data ='T2 met à jour la ligne' WHERE id =1 ; (OK) | |
| 4 | UPDATE table1 SET data ='T2 met à jour la ligne' WHERE id =1 ; (Se bloque pendant un certain temps et finit par renvoyer une erreur "Verrouiller le délai d'attente dépassé ; essayez de redémarrer la transaction") | |
| 5 | COMMIT ; (OK) | |
| 6 | COMMIT ; (OK) |
mysql> SELECT * FROM table1 WHERE id = 1;
+----+-----------------------------------+
| id | data |
+----+-----------------------------------+
| 1 | T1 is updating the row |
+----+-----------------------------------+
mysql> SELECT * FROM table2 WHERE id = 1;
+----+-----------------------------------+
| id | data |
+----+-----------------------------------+
| 1 | T2 is updating the row |
+----+-----------------------------------+Une fois que T2 a été validé avec succès, on s'attendrait à obtenir la même sortie "T2 met à jour la ligne" pour la table1 et la table2, mais les résultats montrent que seule la table2 a été mise à jour. On pourrait penser que si une erreur se produisait dans une transaction, toutes les instructions de la transaction seraient automatiquement annulées, ou si une transaction est validée avec succès, toutes les instructions étaient exécutées de manière atomique. Cela est vrai pour le blocage, mais pas pour le délai d'attente du verrouillage InnoDB.
À moins que vous ne définissiez innodb_rollback_on_timeout=1 (la valeur par défaut est 0 - désactivée), la restauration automatique ne se produira pas pour l'erreur de délai d'attente du verrouillage InnoDB. Cela signifie qu'en suivant le paramètre par défaut, MySQL n'échouera pas et n'annulera pas toute la transaction, ni ne réessayera l'instruction expirée et traitera simplement les instructions suivantes jusqu'à ce qu'elle atteigne COMMIT ou ROLLBACK. Cela explique pourquoi la transaction T2 a été partiellement validée !
La documentation InnoDB indique clairement "InnoDB annule uniquement la dernière instruction sur un délai d'attente de transaction par défaut". Dans ce cas, nous n'obtenons pas l'atomicité de la transaction offerte par InnoDB. L'atomicité dans la conformité ACID est soit que nous obtenons tout ou rien de la transaction, ce qui signifie qu'une transaction partielle est tout simplement inacceptable.
Traitement d'un délai d'attente de verrouillage InnoDB
Ainsi, si vous vous attendez à ce qu'une transaction soit annulée automatiquement lorsqu'elle rencontre une erreur d'attente de verrouillage InnoDB, de la même manière que ce qui se passerait en cas de blocage, définissez l'option suivante dans le fichier de configuration MySQL :
innodb_rollback_on_timeout=1Un redémarrage de MySQL est requis. Lors du déploiement d'un cluster basé sur MySQL, ClusterControl définira toujours innodb_rollback_on_timeout=1 sur chaque nœud. Sans cette option, votre application doit réessayer l'instruction ayant échoué ou exécuter ROLLBACK explicitement pour maintenir l'atomicité de la transaction.
Pour vérifier si la configuration est chargée correctement :
mysql> SHOW GLOBAL VARIABLES LIKE 'innodb_rollback_on_timeout';
+----------------------------+-------+
| Variable_name | Value |
+----------------------------+-------+
| innodb_rollback_on_timeout | ON |
+----------------------------+-------+Pour vérifier si la nouvelle configuration fonctionne, nous pouvons suivre le compteur com_rollback lorsque cette erreur se produit :
mysql> SHOW GLOBAL STATUS LIKE 'com_rollback';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| Com_rollback | 1 |
+---------------+-------+Suivi de la transaction de blocage
Il existe plusieurs endroits où nous pouvons rechercher pour suivre la transaction ou les déclarations bloquantes. Commençons par examiner l'état du moteur InnoDB dans la section TRANSACTIONS :
mysql> SHOW ENGINE INNODB STATUS\G
------------
TRANSACTIONS
------------
...
---TRANSACTION 3100, ACTIVE 2 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 1136, 1 row lock(s)
MySQL thread id 50, OS thread handle 139887555282688, query id 360 localhost ::1 root updating
update table1 set data = 'T2 is updating the row' where id = 1
------- TRX HAS BEEN WAITING 2 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 6 page no 4 n bits 72 index PRIMARY of table `mydb`.`table1` trx id 3100 lock_mode X locks rec but not gap waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
0: len 4; hex 80000001; asc ;;
1: len 6; hex 000000000c19; asc ;;
2: len 7; hex 020000011b0151; asc Q;;
3: len 22; hex 5431206973207570646174696e672074686520726f77; asc T1 is updating the row;;
------------------
---TRANSACTION 3097, ACTIVE 46 sec
2 lock struct(s), heap size 1136, 1 row lock(s), undo log entries 1
MySQL thread id 48, OS thread handle 139887556167424, query id 358 localhost ::1 root
Trx read view will not see trx with id >= 3097, sees < 3097À partir des informations ci-dessus, nous pouvons obtenir un aperçu des transactions actuellement actives sur le serveur. La transaction 3097 verrouille actuellement une ligne qui doit être accessible par la transaction 3100. Cependant, la sortie ci-dessus ne nous indique pas le texte de requête réel qui pourrait nous aider à déterminer quelle partie de la requête/instruction/transaction que nous devons approfondir. . En utilisant le bloqueur MySQL thread ID 48, voyons ce que nous pouvons recueillir à partir de MySQL processlist :
mysql> SHOW FULL PROCESSLIST;
+----+-----------------+-----------------+--------------------+---------+------+------------------------+-----------------------+
| Id | User | Host | db | Command | Time | State | Info |
+----+-----------------+-----------------+--------------------+---------+------+------------------------+-----------------------+
| 4 | event_scheduler | localhost | <null> | Daemon | 5146 | Waiting on empty queue | <null> |
| 10 | root | localhost:56042 | performance_schema | Query | 0 | starting | show full processlist |
| 48 | root | localhost:56118 | mydb | Sleep | 145 | | <null> |
| 50 | root | localhost:56122 | mydb | Sleep | 113 | | <null> |
+----+-----------------+-----------------+--------------------+---------+------+------------------------+-----------------------+L'ID de thread 48 affiche la commande comme "Veille". Pourtant, cela ne nous aide pas beaucoup à savoir quelles instructions bloquent l'autre transaction. C'est parce que l'instruction de cette transaction a été exécutée et que cette transaction ouverte ne fait pratiquement rien pour le moment. Nous devons plonger plus loin pour voir ce qui se passe avec ce fil.
Pour MySQL 8.0, l'instrumentation d'attente de verrouillage InnoDB est disponible sous la table data_lock_waits dans la base de données performance_schema (ou la table innodb_lock_waits dans la base de données sys). Si un événement d'attente de verrouillage se produit, nous devrions voir quelque chose comme ceci :
mysql> SELECT * FROM performance_schema.data_lock_waits\G
***************************[ 1. row ]***************************
ENGINE | INNODB
REQUESTING_ENGINE_LOCK_ID | 139887595270456:6:4:2:139887487554680
REQUESTING_ENGINE_TRANSACTION_ID | 3100
REQUESTING_THREAD_ID | 89
REQUESTING_EVENT_ID | 8
REQUESTING_OBJECT_INSTANCE_BEGIN | 139887487554680
BLOCKING_ENGINE_LOCK_ID | 139887595269584:6:4:2:139887487548648
BLOCKING_ENGINE_TRANSACTION_ID | 3097
BLOCKING_THREAD_ID | 87
BLOCKING_EVENT_ID | 9
BLOCKING_OBJECT_INSTANCE_BEGIN | 139887487548648Notez que dans MySQL 5.6 et 5.7, les informations similaires sont stockées dans la table innodb_lock_waits sous la base de données information_schema. Faites attention à la valeur BLOCKING_THREAD_ID. Nous pouvons utiliser ces informations pour rechercher toutes les instructions exécutées par ce thread dans la table events_statements_history :
mysql> SELECT * FROM performance_schema.events_statements_history WHERE `THREAD_ID` = 87;
0 rows in setIl semble que les informations sur le fil ne soient plus là. Nous pouvons vérifier en vérifiant la valeur minimale et maximale de la colonne thread_id dans la table events_statements_history avec la requête suivante :
mysql> SELECT min(`THREAD_ID`), max(`THREAD_ID`) FROM performance_schema.events_statements_history;
+------------------+------------------+
| min(`THREAD_ID`) | max(`THREAD_ID`) |
+------------------+------------------+
| 98 | 129 |
+------------------+------------------+Le fil que nous recherchions (87) a été tronqué du tableau. Nous pouvons le confirmer en regardant la taille de la table event_statements_history :
mysql> SELECT @@performance_schema_events_statements_history_size;
+-----------------------------------------------------+
| @@performance_schema_events_statements_history_size |
+-----------------------------------------------------+
| 10 |
+-----------------------------------------------------+Ce qui précède signifie que events_statements_history ne peut stocker que les 10 derniers threads. Heureusement, performance_schema a une autre table pour stocker plus de lignes appelée events_statements_history_long, qui stocke des informations similaires mais pour tous les threads et peut contenir beaucoup plus de lignes :
mysql> SELECT @@performance_schema_events_statements_history_long_size;
+----------------------------------------------------------+
| @@performance_schema_events_statements_history_long_size |
+----------------------------------------------------------+
| 10000 |
+----------------------------------------------------------+Cependant, vous obtiendrez un résultat vide si vous essayez d'interroger la table events_statements_history_long pour la première fois. Ceci est normal car par défaut, cette instrumentation est désactivée dans MySQL comme nous pouvons le voir dans la table setup_consumers suivante :
mysql> SELECT * FROM performance_schema.setup_consumers;
+----------------------------------+---------+
| NAME | ENABLED |
+----------------------------------+---------+
| events_stages_current | NO |
| events_stages_history | NO |
| events_stages_history_long | NO |
| events_statements_current | YES |
| events_statements_history | YES |
| events_statements_history_long | NO |
| events_transactions_current | YES |
| events_transactions_history | YES |
| events_transactions_history_long | NO |
| events_waits_current | NO |
| events_waits_history | NO |
| events_waits_history_long | NO |
| global_instrumentation | YES |
| thread_instrumentation | YES |
| statements_digest | YES |
+----------------------------------+---------+Pour activer la table events_statements_history_long, nous devons mettre à jour la table setup_consumers comme ci-dessous :
mysql> UPDATE performance_schema.setup_consumers SET enabled = 'YES' WHERE name = 'events_statements_history_long';Vérifiez s'il y a des lignes dans la table events_statements_history_long maintenant :
mysql> SELECT count(`THREAD_ID`) FROM performance_schema.events_statements_history_long;
+--------------------+
| count(`THREAD_ID`) |
+--------------------+
| 4 |
+--------------------+Frais. Nous pouvons maintenant attendre que l'événement d'attente de verrouillage InnoDB se déclenche à nouveau et lorsqu'il se produit, vous devriez voir la ligne suivante dans la table data_lock_waits :
mysql> SELECT * FROM performance_schema.data_lock_waits\G
***************************[ 1. row ]***************************
ENGINE | INNODB
REQUESTING_ENGINE_LOCK_ID | 139887595270456:6:4:2:139887487555024
REQUESTING_ENGINE_TRANSACTION_ID | 3083
REQUESTING_THREAD_ID | 60
REQUESTING_EVENT_ID | 9
REQUESTING_OBJECT_INSTANCE_BEGIN | 139887487555024
BLOCKING_ENGINE_LOCK_ID | 139887595269584:6:4:2:139887487548648
BLOCKING_ENGINE_TRANSACTION_ID | 3081
BLOCKING_THREAD_ID | 57
BLOCKING_EVENT_ID | 8
BLOCKING_OBJECT_INSTANCE_BEGIN | 139887487548648Encore une fois, nous utilisons la valeur BLOCKING_THREAD_ID pour filtrer toutes les instructions qui ont été exécutées par ce thread par rapport à la table events_statements_history_long :
mysql> SELECT `THREAD_ID`,`EVENT_ID`,`EVENT_NAME`, `CURRENT_SCHEMA`,`SQL_TEXT` FROM events_statements_history_long
WHERE `THREAD_ID` = 57
ORDER BY `EVENT_ID`;
+-----------+----------+-----------------------+----------------+----------------------------------------------------------------+
| THREAD_ID | EVENT_ID | EVENT_NAME | CURRENT_SCHEMA | SQL_TEXT |
+-----------+----------+-----------------------+----------------+----------------------------------------------------------------+
| 57 | 1 | statement/sql/select | <null> | select connection_id() |
| 57 | 2 | statement/sql/select | <null> | SELECT @@VERSION |
| 57 | 3 | statement/sql/select | <null> | SELECT @@VERSION_COMMENT |
| 57 | 4 | statement/com/Init DB | <null> | <null> |
| 57 | 5 | statement/sql/begin | mydb | begin |
| 57 | 7 | statement/sql/select | mydb | select 'T1 is in the house' |
| 57 | 8 | statement/sql/select | mydb | select * from table1 |
| 57 | 9 | statement/sql/select | mydb | select 'some more select' |
| 57 | 10 | statement/sql/update | mydb | update table1 set data = 'T1 is updating the row' where id = 1 |
+-----------+----------+-----------------------+----------------+----------------------------------------------------------------+Enfin, nous avons trouvé le coupable. Nous pouvons dire en regardant la séquence d'événements du thread 57 où la transaction ci-dessus (T1) n'est toujours pas terminée (pas de COMMIT ou ROLLBACK), et nous pouvons voir que la toute dernière instruction a obtenu un verrou exclusif sur la ligne pour la mise à jour opération qui avait besoin de l'autre transaction (T2) et juste accrochée là. Cela explique pourquoi nous voyons 'Sleep' dans la sortie de la liste de processus MySQL.
Comme nous pouvons le voir, l'instruction SELECT ci-dessus vous oblige à obtenir la valeur thread_id au préalable. Pour simplifier cette requête, nous pouvons utiliser la clause IN et une sous-requête pour joindre les deux tables. La requête suivante produit un résultat identique à celui ci-dessus :
mysql> SELECT `THREAD_ID`,`EVENT_ID`,`EVENT_NAME`, `CURRENT_SCHEMA`,`SQL_TEXT` from events_statements_history_long WHERE `THREAD_ID` IN (SELECT `BLOCKING_THREAD_ID` FROM data_lock_waits) ORDER BY `EVENT_ID`;
+-----------+----------+-----------------------+----------------+----------------------------------------------------------------+
| THREAD_ID | EVENT_ID | EVENT_NAME | CURRENT_SCHEMA | SQL_TEXT |
+-----------+----------+-----------------------+----------------+----------------------------------------------------------------+
| 57 | 1 | statement/sql/select | <null> | select connection_id() |
| 57 | 2 | statement/sql/select | <null> | SELECT @@VERSION |
| 57 | 3 | statement/sql/select | <null> | SELECT @@VERSION_COMMENT |
| 57 | 4 | statement/com/Init DB | <null> | <null> |
| 57 | 5 | statement/sql/begin | mydb | begin |
| 57 | 7 | statement/sql/select | mydb | select 'T1 is in the house' |
| 57 | 8 | statement/sql/select | mydb | select * from table1 |
| 57 | 9 | statement/sql/select | mydb | select 'some more select' |
| 57 | 10 | statement/sql/update | mydb | update table1 set data = 'T1 is updating the row' where id = 1 |
+-----------+----------+-----------------------+----------------+----------------------------------------------------------------+Cependant, il n'est pas pratique pour nous d'exécuter la requête ci-dessus chaque fois qu'un événement d'attente de verrouillage InnoDB se produit. Outre l'erreur de l'application, comment sauriez-vous que l'événement d'attente de verrouillage se produit ? Nous pouvons automatiser l'exécution de cette requête avec le simple script Bash suivant, appelé track_lockwait.sh :
$ cat track_lockwait.sh
#!/bin/bash
## track_lockwait.sh
## Print out the blocking statements that causing InnoDB lock wait
INTERVAL=5
DIR=/root/lockwait/
[ -d $dir ] || mkdir -p $dir
while true; do
check_query=$(mysql -A -Bse 'SELECT THREAD_ID,EVENT_ID,EVENT_NAME,CURRENT_SCHEMA,SQL_TEXT FROM events_statements_history_long WHERE THREAD_ID IN (SELECT BLOCKING_THREAD_ID FROM data_lock_waits) ORDER BY EVENT_ID')
# if $check_query is not empty
if [[ ! -z $check_query ]]; then
timestamp=$(date +%s)
echo $check_query > $DIR/innodb_lockwait_report_${timestamp}
fi
sleep $INTERVAL
doneAppliquez l'autorisation exécutable et démonisez le script en arrière-plan :
$ chmod 755 track_lockwait.sh
$ nohup ./track_lockwait.sh &Maintenant, nous n'avons plus qu'à attendre que les rapports soient générés sous le répertoire /root/lockwait. En fonction de la charge de travail de la base de données et des modèles d'accès aux lignes, vous pouvez probablement voir un grand nombre de fichiers sous ce répertoire. Surveillez attentivement le répertoire, sinon il serait inondé de trop de fichiers de rapport.
Si vous utilisez ClusterControl, vous pouvez activer la fonction Journal des transactions sous Performance -> Journal des transactions où ClusterControl fournira un rapport sur les blocages et les transactions de longue durée, ce qui vous facilitera la vie pour trouver le coupable.
Conclusion
En résumé, si nous sommes confrontés à une erreur "Lock Wait Timeout Exceeded" dans MySQL, nous devons d'abord comprendre les effets qu'une telle erreur peut avoir sur notre infrastructure, puis suivre la transaction offensive et agir en conséquence. soit avec des scripts shell comme track_lockwait.sh, soit avec un logiciel de gestion de base de données comme ClusterControl.
Si vous décidez d'utiliser des scripts shell, gardez simplement à l'esprit qu'ils peuvent vous faire économiser de l'argent, mais qu'ils vous feront perdre du temps, car vous devez savoir une ou deux choses sur leur fonctionnement, postulez autorisations, et éventuellement les faire fonctionner en arrière-plan, et si vous vous perdez dans la jungle des coquillages, nous pouvons vous aider.
Quoi que vous décidiez d'implémenter, assurez-vous de nous suivre sur Twitter ou de vous abonner à notre flux RSS pour obtenir plus de conseils sur l'amélioration des performances de votre logiciel et des bases de données qui le soutiennent, comme cet article couvrant 6 scénarios d'échec courants dans MySQL.
