Uno degli errori più comuni di InnoDB è il superamento del timeout di attesa del blocco di InnoDB, ad esempio:
SQLSTATE[HY000]: General error: 1205 Lock wait timeout exceeded; try restarting transactionQuanto sopra significa semplicemente che la transazione ha raggiunto innodb_lock_wait_timeout in attesa di ottenere un blocco esclusivo che per impostazione predefinita è 50 secondi. Le cause comuni sono:
- La transazione offensiva non è abbastanza veloce per eseguire il commit o il rollback della transazione entro la durata di innodb_lock_wait_timeout.
- La transazione offensiva è in attesa che il blocco delle righe venga rilasciato da un'altra transazione.
Gli effetti di un timeout di attesa del blocco di InnoDB
Il timeout di attesa del blocco di InnoDB può causare due importanti implicazioni:
- L'istruzione non riuscita non viene ripristinata per impostazione predefinita.
- Anche se innodb_rollback_on_timeout è abilitato, quando un'istruzione non riesce in una transazione, ROLLBACK è comunque un'operazione più costosa di COMMIT.
Giochiamo con un semplice esempio per capire meglio l'effetto. Considera le seguenti due tabelle nel database mydb:
mysql> CREATE SCHEMA mydb;
mysql> USE mydb;La prima tabella (tabella1):
mysql> CREATE TABLE table1 ( id INT PRIMARY KEY AUTO_INCREMENT, data VARCHAR(50));
mysql> INSERT INTO table1 SET data = 'data #1';La seconda tabella (tabella2):
mysql> CREATE TABLE table2 LIKE table1;
mysql> INSERT INTO table2 SET data = 'data #2';Abbiamo eseguito le nostre transazioni in due sessioni diverse nel seguente ordine:
| Ordine | Transazione n. 1 (T1) | Transazione n. 2 (T2) |
| 1 | SELECT * FROM table1; (OK) | SELECT * FROM table1; (OK) |
| 2 | UPDATE table1 SET data ='T1 sta aggiornando la riga' WHERE id =1; (OK) | |
| 3 | UPDATE table2 SET data ='T2 sta aggiornando la riga' WHERE id =1; (OK) | |
| 4 | UPDATE table1 SET data ='T2 sta aggiornando la riga' WHERE id =1; (Si blocca per un po' e alla fine restituisce un errore "Timeout di attesa blocco superato; prova a riavviare la transazione") | |
| 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 |
+----+-----------------------------------+Dopo che T2 è stato eseguito correttamente, ci si aspetterebbe di ottenere lo stesso output "T2 sta aggiornando la riga" sia per la tabella1 che per la tabella2, ma i risultati mostrano che solo la tabella2 è stata aggiornata. Si potrebbe pensare che se si verifica un errore all'interno di una transazione, tutte le istruzioni nella transazione verrebbero automaticamente ripristinate o se una transazione viene eseguita correttamente, tutte le istruzioni vengono eseguite atomicamente. Questo è vero per il deadlock, ma non per il timeout di attesa del blocco di InnoDB.
A meno che tu non imposti innodb_rollback_on_timeout=1 (il valore predefinito è 0 - disabilitato), il rollback automatico non avverrà per l'errore di timeout di attesa del blocco di InnoDB. Ciò significa che, seguendo l'impostazione predefinita, MySQL non fallirà e non eseguirà il rollback dell'intera transazione, né riprova l'istruzione scaduta ed elaborerà semplicemente le istruzioni successive finché non raggiunge COMMIT o ROLLBACK. Questo spiega perché la transazione T2 è stata parzialmente impegnata!
La documentazione di InnoDB dice chiaramente "InnoDB ripristina solo l'ultima istruzione su un timeout di transazione per impostazione predefinita". In questo caso, non otteniamo l'atomicità della transazione offerta da InnoDB. L'atomicità in ACID compliant è che otteniamo tutto o niente della transazione, il che significa che una transazione parziale è semplicemente inaccettabile.
Gestire un timeout di attesa per il blocco di InnoDB
Quindi, se ti aspetti che una transazione venga ripristinata automaticamente quando si verifica un errore di attesa del blocco InnoDB, in modo simile a quanto accadrebbe in deadlock, imposta la seguente opzione nel file di configurazione di MySQL:
innodb_rollback_on_timeout=1È necessario un riavvio di MySQL. Quando si distribuisce un cluster basato su MySQL, ClusterControl imposterà sempre innodb_rollback_on_timeout=1 su ogni nodo. Senza questa opzione, l'applicazione deve riprovare l'istruzione non riuscita o eseguire ROLLBACK in modo esplicito per mantenere l'atomicità della transazione.
Per verificare se la configurazione è stata caricata correttamente:
mysql> SHOW GLOBAL VARIABLES LIKE 'innodb_rollback_on_timeout';
+----------------------------+-------+
| Variable_name | Value |
+----------------------------+-------+
| innodb_rollback_on_timeout | ON |
+----------------------------+-------+Per verificare se la nuova configurazione funziona, possiamo tenere traccia del contatore com_rollback quando si verifica questo errore:
mysql> SHOW GLOBAL STATUS LIKE 'com_rollback';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| Com_rollback | 1 |
+---------------+-------+Tracciamento della transazione bloccante
Ci sono diversi posti in cui possiamo cercare per tenere traccia della transazione o delle istruzioni di blocco. Iniziamo esaminando lo stato del motore InnoDB nella sezione TRANSAZIONI:
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 < 3097Dalle informazioni di cui sopra, possiamo ottenere una panoramica delle transazioni attualmente attive nel server. La transazione 3097 sta attualmente bloccando una riga a cui deve accedere la transazione 3100. Tuttavia, l'output di cui sopra non ci dice il testo della query effettivo che potrebbe aiutarci a capire quale parte della query/dichiarazione/transazione dobbiamo indagare ulteriormente . Usando il blocco thread MySQL ID 48, vediamo cosa possiamo raccogliere da 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> |
+----+-----------------+-----------------+--------------------+---------+------+------------------------+-----------------------+Il thread ID 48 mostra il comando come 'Sleep'. Tuttavia, questo non ci aiuta molto a sapere quali affermazioni bloccano l'altra transazione. Questo perché l'istruzione in questa transazione è stata eseguita e questa transazione aperta non sta praticamente facendo nulla al momento. Dobbiamo immergerci più in basso per vedere cosa sta succedendo con questo thread.
Per MySQL 8.0, la strumentazione InnoDB lock wait è disponibile nella tabella data_lock_waits all'interno del database performance_schema (o nella tabella innodb_lock_waits all'interno del database sys). Se si verifica un evento di attesa di blocco, dovremmo vedere qualcosa del genere:
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 | 139887487548648Nota che in MySQL 5.6 e 5.7, le informazioni simili sono memorizzate all'interno della tabella innodb_lock_waits nel database information_schema. Presta attenzione al valore BLOCKING_THREAD_ID. Possiamo usare queste informazioni per cercare tutte le istruzioni eseguite da questo thread nella tabella events_statements_history:
mysql> SELECT * FROM performance_schema.events_statements_history WHERE `THREAD_ID` = 87;
0 rows in setSembra che le informazioni sul thread non siano più presenti. Possiamo verificare controllando il valore minimo e massimo della colonna thread_id nella tabella events_statements_history con la seguente query:
mysql> SELECT min(`THREAD_ID`), max(`THREAD_ID`) FROM performance_schema.events_statements_history;
+------------------+------------------+
| min(`THREAD_ID`) | max(`THREAD_ID`) |
+------------------+------------------+
| 98 | 129 |
+------------------+------------------+Il thread che stavamo cercando (87) è stato troncato dalla tabella. Possiamo confermarlo osservando la dimensione della tabella event_statements_history:
mysql> SELECT @@performance_schema_events_statements_history_size;
+-----------------------------------------------------+
| @@performance_schema_events_statements_history_size |
+-----------------------------------------------------+
| 10 |
+-----------------------------------------------------+Quanto sopra significa che events_statements_history può memorizzare solo gli ultimi 10 thread. Fortunatamente, performance_schema ha un'altra tabella per memorizzare più righe chiamata events_statements_history_long, che memorizza informazioni simili ma per tutti i thread e può contenere molte più righe:
mysql> SELECT @@performance_schema_events_statements_history_long_size;
+----------------------------------------------------------+
| @@performance_schema_events_statements_history_long_size |
+----------------------------------------------------------+
| 10000 |
+----------------------------------------------------------+Tuttavia, otterrai un risultato vuoto se provi a interrogare la tabella events_statements_history_long per la prima volta. Questo è previsto perché per impostazione predefinita, questa strumentazione è disabilitata in MySQL, come possiamo vedere nella seguente tabella setup_consumers:
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 |
+----------------------------------+---------+Per attivare la tabella events_statements_history_long, dobbiamo aggiornare la tabella setup_consumers come segue:
mysql> UPDATE performance_schema.setup_consumers SET enabled = 'YES' WHERE name = 'events_statements_history_long';Verifica se ci sono righe nella tabella events_statements_history_long ora:
mysql> SELECT count(`THREAD_ID`) FROM performance_schema.events_statements_history_long;
+--------------------+
| count(`THREAD_ID`) |
+--------------------+
| 4 |
+--------------------+Freddo. Ora possiamo aspettare fino a quando l'evento di attesa del blocco di InnoDB si solleva di nuovo e quando si verifica, dovresti vedere la seguente riga nella tabella 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 | 139887487548648Ancora una volta, utilizziamo il valore BLOCKING_THREAD_ID per filtrare tutte le istruzioni che sono state eseguite da questo thread rispetto alla tabella 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 |
+-----------+----------+-----------------------+----------------+----------------------------------------------------------------+Alla fine abbiamo trovato il colpevole. Possiamo dire guardando la sequenza di eventi del thread 57 in cui la transazione sopra (T1) non è ancora terminata (nessun COMMIT o ROLLBACK), e possiamo vedere che l'ultima istruzione ha ottenuto un blocco esclusivo alla riga per l'aggiornamento operazione necessaria per l'altra transazione (T2) e semplicemente appesa lì. Questo spiega perché vediamo 'Sleep' nell'output di MySQL processlist.
Come possiamo vedere, l'istruzione SELECT precedente richiede di ottenere in anticipo il valore thread_id. Per semplificare questa query, possiamo usare la clausola IN e una sottoquery per unire entrambe le tabelle. La seguente query produce un risultato identico a quello precedente:
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 |
+-----------+----------+-----------------------+----------------+----------------------------------------------------------------+Tuttavia, non è pratico per noi eseguire la query di cui sopra ogni volta che si verifica un evento di attesa del blocco di InnoDB. A parte l'errore dell'applicazione, come faresti a sapere che si sta verificando l'evento di attesa del blocco? Possiamo automatizzare questa esecuzione di query con il seguente semplice script Bash, chiamato 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
doneApplica l'autorizzazione eseguibile e demonizza lo script in background:
$ chmod 755 track_lockwait.sh
$ nohup ./track_lockwait.sh &Ora, dobbiamo solo aspettare che i rapporti vengano generati nella directory /root/lockwait. A seconda del carico di lavoro del database e dei modelli di accesso alle righe, potresti probabilmente vedere molti file in questa directory. Monitora attentamente la directory, altrimenti verrebbe inondata da troppi file di report.
Se stai utilizzando ClusterControl, puoi abilitare la funzione Registro transazioni in Prestazioni -> Registro transazioni in cui ClusterControl fornirà un rapporto sui deadlock e sulle transazioni di lunga durata che ti faciliteranno la vita nel trovare il colpevole.
Conclusione
In sintesi, se affrontiamo un errore "Lock Wait Timeout Exceeded" in MySQL, dobbiamo prima capire gli effetti che un tale errore può avere sulla nostra infrastruttura, quindi tracciare la transazione offensiva e agire su con script di shell come track_lockwait.sh o software di gestione di database come ClusterControl.
Se decidi di utilizzare gli script di shell, tieni presente che potrebbero farti risparmiare denaro ma ti costeranno tempo, poiché avresti bisogno di sapere una o due cose su come funzionano, applica permessi e possibilmente farli funzionare in background, e se ti perdi nella giungla di conchiglie, possiamo aiutarti.
Qualunque cosa tu decida di implementare, assicurati di seguirci su Twitter o iscriviti al nostro feed RSS per ottenere ulteriori suggerimenti su come migliorare le prestazioni del tuo software e dei database che lo supportano, come questo post che copre 6 scenari di errore comuni in MySQL.
