Jednou z nejoblíbenějších chyb InnoDB je překročení doby čekání na zámek InnoDB, například:
SQLSTATE[HY000]: General error: 1205 Lock wait timeout exceeded; try restarting transactionVýše uvedené jednoduše znamená, že transakce dosáhla innodb_lock_wait_timeout při čekání na získání exkluzivního zámku, který je standardně nastaven na 50 sekund. Běžné příčiny jsou:
- Útočná transakce není dostatečně rychlá na potvrzení nebo vrácení transakce během trvání innodb_lock_wait_timeout.
- Urážlivá transakce čeká na uvolnění zámku řádku jinou transakcí.
Účinky časového limitu čekání na zámek InnoDB
Časový limit čekání na zámek InnoDB může způsobit dva hlavní důsledky:
- Neúspěšný příkaz není ve výchozím nastavení vrácen zpět.
- I když je povolena funkce innodb_rollback_on_timeout, když příkaz selže v transakci, ROLLBACK je stále dražší operace než COMMIT.
Pojďme si pohrát s jednoduchým příkladem, abychom lépe porozuměli účinku. Zvažte následující dvě tabulky v databázi mydb:
mysql> CREATE SCHEMA mydb;
mysql> USE mydb;První tabulka (tabulka1):
mysql> CREATE TABLE table1 ( id INT PRIMARY KEY AUTO_INCREMENT, data VARCHAR(50));
mysql> INSERT INTO table1 SET data = 'data #1';Druhá tabulka (tabulka2):
mysql> CREATE TABLE table2 LIKE table1;
mysql> INSERT INTO table2 SET data = 'data #2';Provedli jsme transakce ve dvou různých relacích v následujícím pořadí:
| Objednávání | Transakce č. 1 (T1) | Transakce č. 2 (T2) |
| 1 | VYBRAT * Z tabulky1; (OK) | VYBRAT * Z tabulky1; (OK) |
| 2 | UPDATE table1 SET data ='T1 aktualizuje řádek' WHERE id =1; (OK) | |
| 3 | UPDATE table2 SET data ='T2 aktualizuje řádek' WHERE id =1; (OK) | |
| 4 | UPDATE table1 SET data ='T2 aktualizuje řádek' WHERE id =1; (Na chvíli se zablokuje a nakonec vrátí chybu „Vypršel časový limit čekání na zámek; zkuste transakci restartovat“) | |
| 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 |
+----+-----------------------------------+Po úspěšném potvrzení T2 by se dalo očekávat, že dostanete stejný výstup „T2 aktualizuje řádek“ pro tabulku1 i tabulku2, ale výsledky ukazují, že byla aktualizována pouze tabulka2. Někdo by si mohl myslet, že pokud v transakci dojde k jakékoli chybě, všechny příkazy v transakci budou automaticky vráceny zpět, nebo pokud je transakce úspěšně potvrzena, byly celé příkazy provedeny atomicky. To platí pro zablokování, ale ne pro časový limit čekání na zámek InnoDB.
Pokud nenastavíte innodb_rollback_on_timeout=1 (výchozí je 0 – vypnuto), automatické vrácení se neprovede kvůli chybě prodlevy čekání na zámek InnoDB. To znamená, že při dodržení výchozího nastavení MySQL neselže a nevrátí celou transakci zpět, ani se znovu nepokusí o vypršení časového limitu a pouze zpracuje další příkazy, dokud nedosáhne COMMIT nebo ROLLBACK. To vysvětluje, proč byla transakce T2 částečně potvrzena!
Dokumentace InnoDB jasně říká:„InnoDB vrátí zpět pouze poslední příkaz o vypršení časového limitu transakce standardně". V tomto případě nezískáme atomičnost transakce nabízenou InnoDB. Atomicita v ACID je buď dostaneme celou transakci, nebo nic, což znamená, že částečná transakce je pouze nepřijatelná.
Zacházení s prodlevou čekání na zámek InnoDB
Pokud tedy očekáváte, že se transakce automaticky vrátí zpět, když narazí na chybu čekání zámku InnoDB, podobně jako to, co by se stalo v uváznutí, nastavte v konfiguračním souboru MySQL následující možnost:
innodb_rollback_on_timeout=1Je vyžadován restart MySQL. Při nasazení clusteru založeného na MySQL nastaví ClusterControl vždy na každém uzlu innodb_rollback_on_timeout=1. Bez této možnosti musí vaše aplikace opakovat neúspěšný příkaz nebo explicitně provést ROLLBACK, aby byla zachována atomičnost transakce.
Chcete-li ověřit, zda je konfigurace načtena správně:
mysql> SHOW GLOBAL VARIABLES LIKE 'innodb_rollback_on_timeout';
+----------------------------+-------+
| Variable_name | Value |
+----------------------------+-------+
| innodb_rollback_on_timeout | ON |
+----------------------------+-------+Chcete-li zkontrolovat, zda nová konfigurace funguje, můžeme sledovat počítadlo com_rollback, když dojde k této chybě:
mysql> SHOW GLOBAL STATUS LIKE 'com_rollback';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| Com_rollback | 1 |
+---------------+-------+Sledování blokující transakce
Existuje několik míst, kam se můžeme podívat, abychom mohli sledovat blokující transakci nebo výpisy. Začněme tím, že se podíváme na stav enginu InnoDB v sekci TRANSAKCE:
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 < 3097Z výše uvedených informací můžeme získat přehled o transakcích, které jsou aktuálně na serveru aktivní. Transakce 3097 aktuálně zamyká řádek, ke kterému je potřeba přistupovat pomocí transakce 3100. Výše uvedený výstup nám však neříká skutečný text dotazu, který by nám mohl pomoci zjistit, kterou část dotazu/výpisu/transakce potřebujeme dále prozkoumat. . Pomocí blokovacího vlákna MySQL ID 48 se podívejme, co můžeme získat ze seznamu procesů MySQL:
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> |
+----+-----------------+-----------------+--------------------+---------+------+------------------------+-----------------------+ID vlákna 48 zobrazuje příkaz jako 'Sleep'. To nám však příliš nepomůže, abychom věděli, které příkazy blokují další transakci. Důvodem je, že výpis v této transakci byl proveden a tato otevřená transakce v tuto chvíli v podstatě nic nedělá. Musíme se ponořit dále, abychom viděli, co se děje s tímto vláknem.
Pro MySQL 8.0 je instrumentace čekání na zámek InnoDB dostupná pod tabulkou data_lock_waits v databázi performance_schema (nebo tabulkou innodb_lock_waits v databázi sys). Pokud probíhá událost lock wait, měli bychom vidět něco takového:
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 | 139887487548648Všimněte si, že v MySQL 5.6 a 5.7 jsou podobné informace uloženy v tabulce innodb_lock_waits pod databází information_schema. Věnujte pozornost hodnotě BLOCKING_THREAD_ID. Tyto informace můžeme použít k vyhledání všech příkazů prováděných tímto vláknem v tabulce events_statements_history:
mysql> SELECT * FROM performance_schema.events_statements_history WHERE `THREAD_ID` = 87;
0 rows in setZdá se, že informace o vláknu zde již nejsou. Můžeme to ověřit kontrolou minimální a maximální hodnoty sloupce thread_id v tabulce events_statements_history pomocí následujícího dotazu:
mysql> SELECT min(`THREAD_ID`), max(`THREAD_ID`) FROM performance_schema.events_statements_history;
+------------------+------------------+
| min(`THREAD_ID`) | max(`THREAD_ID`) |
+------------------+------------------+
| 98 | 129 |
+------------------+------------------+Vlákno, které jsme hledali (87), bylo z tabulky zkráceno. Můžeme to potvrdit pohledem na velikost tabulky event_statements_history:
mysql> SELECT @@performance_schema_events_statements_history_size;
+-----------------------------------------------------+
| @@performance_schema_events_statements_history_size |
+-----------------------------------------------------+
| 10 |
+-----------------------------------------------------+Výše uvedené znamená, že events_statements_history může ukládat pouze posledních 10 vláken. Naštěstí performance_schema má další tabulku pro ukládání více řádků nazvanou events_statements_history_long, která ukládá podobné informace, ale pro všechna vlákna a může obsahovat mnohem více řádků:
mysql> SELECT @@performance_schema_events_statements_history_long_size;
+----------------------------------------------------------+
| @@performance_schema_events_statements_history_long_size |
+----------------------------------------------------------+
| 10000 |
+----------------------------------------------------------+Pokud se však poprvé pokusíte dotazovat tabulku events_statements_history_long, dostanete prázdný výsledek. To se očekává, protože ve výchozím nastavení je tato instrumentace v MySQL zakázána, jak můžeme vidět v následující tabulce 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 |
+----------------------------------+---------+Chcete-li aktivovat tabulku events_statements_history_long, musíme aktualizovat tabulku setup_consumers, jak je uvedeno níže:
mysql> UPDATE performance_schema.setup_consumers SET enabled = 'YES' WHERE name = 'events_statements_history_long';Ověřte, zda jsou v tabulce events_statements_history_long nyní řádky:
mysql> SELECT count(`THREAD_ID`) FROM performance_schema.events_statements_history_long;
+--------------------+
| count(`THREAD_ID`) |
+--------------------+
| 4 |
+--------------------+Chladný. Nyní můžeme počkat, dokud se událost čekání na zámek InnoDB znovu nezvýší, a když k ní dojde, měli byste vidět následující řádek v tabulce 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 | 139887487548648Opět používáme hodnotu BLOCKING_THREAD_ID k filtrování všech příkazů, které byly provedeny tímto vláknem, podle tabulky 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 |
+-----------+----------+-----------------------+----------------+----------------------------------------------------------------+Nakonec jsme našli viníka. Můžeme říci, že se podíváme na sekvenci událostí vlákna 57, kde výše uvedená transakce (T1) ještě neskončila (žádný COMMIT nebo ROLLBACK), a můžeme vidět, že úplně poslední příkaz získal exkluzivní zámek na řádek pro aktualizaci. operace, kterou potřebuje jiná transakce (T2) a jen tam visí. To vysvětluje, proč ve výstupu seznamu procesů MySQL vidíme 'Sleep'.
Jak vidíme, výše uvedený příkaz SELECT vyžaduje, abyste předem získali hodnotu thread_id. Pro zjednodušení tohoto dotazu můžeme použít klauzuli IN a poddotaz ke spojení obou tabulek. Následující dotaz poskytuje stejný výsledek jako výše:
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 |
+-----------+----------+-----------------------+----------------+----------------------------------------------------------------+Není však pro nás praktické provádět výše uvedený dotaz, kdykoli dojde k události čekání na zámek InnoDB. Jak byste kromě chyby aplikace věděli, že probíhá událost lock wait? Toto provádění dotazu můžeme automatizovat pomocí následujícího jednoduchého skriptu Bash, nazvaného 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
donePoužijte oprávnění ke spustitelnému souboru a démonizujte skript na pozadí:
$ chmod 755 track_lockwait.sh
$ nohup ./track_lockwait.sh &Nyní musíme počkat, až se zprávy vygenerují v adresáři /root/lockwait. V závislosti na vytížení databáze a vzorech přístupu k řádkům pravděpodobně uvidíte v tomto adresáři mnoho souborů. Adresář bedlivě sledujte, jinak by byl zahlcen příliš mnoha soubory sestav.
Pokud používáte ClusterControl, můžete povolit funkci Transaction Log pod Performance -> Transaction Log, kde ClusterControl poskytne zprávu o uváznutí a dlouhotrvajících transakcích, což vám usnadní život při hledání viníka.
Závěr
Shrnuto, pokud v MySQL čelíme chybě „Překročení časového limitu čekání na zámek“, musíme nejprve porozumět dopadům, které taková chyba může mít na naši infrastrukturu, poté sledovat útočnou transakci a jednat podle to buď pomocí skriptů shellu, jako je track_lockwait.sh, nebo softwaru pro správu databází, jako je ClusterControl.
Pokud se rozhodnete použít skripty shell, mějte na paměti, že vám mohou ušetřit peníze, ale budou vás stát čas, protože byste potřebovali vědět něco o tom, jak fungují, použijte oprávnění a případně je nechat běžet na pozadí, a pokud se ztratíte v džungli skořápek, můžeme vám pomoci.
Ať už se rozhodnete implementovat cokoli, nezapomeňte nás sledovat na Twitteru nebo se přihlaste k odběru našeho RSS kanálu, kde získáte další tipy na zlepšení výkonu vašeho softwaru i databází, které jej podporují, jako je tento příspěvek o 6 běžných scénářích selhání v MySQL.