Hoe een Lock Wait Time-out overschreden fout in MySQL te repareren

Een van de meest populaire fouten van InnoDB is dat de wachttijd voor de InnoDB-vergrendeling is overschreden, bijvoorbeeld:

SQLSTATE[HY000]: General error: 1205 Lock wait timeout exceeded; try restarting transaction

Het bovenstaande betekent simpelweg dat de transactie de innodb_lock_wait_timeout heeft bereikt tijdens het wachten op het verkrijgen van een exclusieve vergrendeling die standaard is ingesteld op 50 seconden. De meest voorkomende oorzaken zijn:

De aanstootgevende transactie is niet snel genoeg om de transactie vast te leggen of terug te draaien binnen de innodb_lock_wait_timeout duur.
De aanstootgevende transactie wacht tot de rijvergrendeling wordt vrijgegeven door een andere transactie.

De effecten van een InnoDB Lock-wachttime-out

InnoDB lock-wachttime-out kan twee belangrijke gevolgen hebben:

De mislukte instructie wordt standaard niet teruggedraaid.
Zelfs als innodb_rollback_on_timeout is ingeschakeld, is ROLLBACK nog steeds een duurdere operatie dan COMMIT wanneer een instructie mislukt in een transactie.

Laten we wat spelen met een eenvoudig voorbeeld om het effect beter te begrijpen. Beschouw de volgende twee tabellen in database mydb:

mysql> CREATE SCHEMA mydb;
mysql> USE mydb;

De eerste tafel (tabel1):

mysql> CREATE TABLE table1 ( id INT PRIMARY KEY AUTO_INCREMENT, data VARCHAR(50));
mysql> INSERT INTO table1 SET data = 'data #1';

De tweede tafel (tabel 2):

mysql> CREATE TABLE table2 LIKE table1;
mysql> INSERT INTO table2 SET data = 'data #2';

We hebben onze transacties in twee verschillende sessies in de volgende volgorde uitgevoerd:

Bestellen

Transactie #1 (T1)

Transactie #2 (T2)

SELECTEER * UIT tabel1;

(OK)

SELECTEER * UIT tabel1;

(OK)

UPDATE table1 SET data ='T1 werkt de rij bij' WHERE id =1;

(OK)

UPDATE table2 SET data ='T2 werkt de rij bij' WHERE id =1;

(OK)

UPDATE table1 SET data ='T2 werkt de rij bij' WHERE id =1;

(Houdt een tijdje vast en geeft uiteindelijk de foutmelding "Lock wait time-out overschreden; probeer transactie opnieuw te starten")

COMMIT;

(OK)

COMMIT;

(OK)

Het eindresultaat na stap #6 zou echter verrassend kunnen zijn als we de time-out-instructie bij stap #4 niet opnieuw zouden proberen:

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            |
+----+-----------------------------------+

Nadat T2 succesvol was vastgelegd, zou je verwachten dat dezelfde uitvoer "T2 is de rij aan het bijwerken" voor zowel tabel1 als tabel2 zal zijn, maar de resultaten laten zien dat alleen tabel2 is bijgewerkt. Je zou kunnen denken dat als er een fout optreedt in een transactie, alle instructies in de transactie automatisch worden teruggedraaid, of dat als een transactie met succes wordt uitgevoerd, de hele instructies atomair worden uitgevoerd. Dit geldt voor deadlock, maar niet voor InnoDB lock-wachttime-out.

Tenzij u innodb_rollback_on_timeout=1 instelt (standaard is 0 - uitgeschakeld), zal er geen automatische rollback plaatsvinden voor de InnoDB lock-wachttime-outfout. Dit betekent dat, door de standaardinstelling te volgen, MySQL niet zal mislukken en de hele transactie terugdraait, noch de time-outverklaring opnieuw probeert en alleen de volgende instructies verwerkt totdat COMMIT of ROLLBACK wordt bereikt. Dit verklaart waarom transactie T2 gedeeltelijk is vastgelegd!

De InnoDB-documentatie zegt duidelijk:"InnoDB draait alleen de laatste verklaring over een transactie-time-out terug standaard". In dit geval krijgen we niet de transactie-atomiciteit die wordt aangeboden door InnoDB. De atomiciteit in ACID-compatibel is of we alles of niets van de transactie krijgen, wat betekent dat een gedeeltelijke transactie slechts onaanvaardbaar is.

Omgaan met een InnoDB Lock-wachttime-out

Dus, als u verwacht dat een transactie automatisch wordt teruggedraaid wanneer een InnoDB-wachtfout bij vergrendeling wordt aangetroffen, net zoals bij een deadlock, stelt u de volgende optie in het MySQL-configuratiebestand in:

innodb_rollback_on_timeout=1

Een MySQL-herstart is vereist. Bij het implementeren van een op MySQL gebaseerd cluster, stelt ClusterControl altijd innodb_rollback_on_timeout=1 in op elk knooppunt. Zonder deze optie moet uw toepassing de mislukte instructie opnieuw proberen of expliciet ROLLBACK uitvoeren om de transactie-atomiciteit te behouden.

Om te controleren of de configuratie correct is geladen:

mysql> SHOW GLOBAL VARIABLES LIKE 'innodb_rollback_on_timeout';
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| innodb_rollback_on_timeout | ON    |
+----------------------------+-------+

Om te controleren of de nieuwe configuratie werkt, kunnen we de com_rollback-teller volgen wanneer deze fout optreedt:

mysql> SHOW GLOBAL STATUS LIKE 'com_rollback';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| Com_rollback  | 1     |
+---------------+-------+

De blokkerende transactie volgen

Er zijn verschillende plaatsen waar we de blokkerende transactie of afschriften kunnen volgen. Laten we beginnen met het bekijken van de InnoDB-enginestatus onder het gedeelte TRANSACTIES:

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

Uit de bovenstaande informatie kunnen we een overzicht krijgen van de transacties die momenteel actief zijn op de server. Transactie 3097 vergrendelt momenteel een rij die moet worden geopend door transactie 3100. De bovenstaande uitvoer vertelt ons echter niet de daadwerkelijke vraagtekst die ons zou kunnen helpen uit te zoeken welk deel van de vraag/instructie/transactie we verder moeten onderzoeken . Laten we, door de blocker MySQL-thread ID 48 te gebruiken, eens kijken wat we uit de MySQL-proceslijst kunnen halen:

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>                |
+----+-----------------+-----------------+--------------------+---------+------+------------------------+-----------------------+

Thread-ID 48 toont het commando als 'Sleep'. Toch helpt dit ons niet veel om te weten welke uitspraken de andere transactie blokkeren. Dit komt omdat de verklaring in deze transactie is uitgevoerd en deze open transactie op dit moment in principe niets doet. We moeten verder naar beneden duiken om te zien wat er aan de hand is met deze thread.

Voor MySQL 8.0 is de InnoDB lock wait instrumentatie beschikbaar onder data_lock_waits tabel in performance_schema database (of innodb_lock_waits tabel in sys database). Als er een lock wait-gebeurtenis plaatsvindt, zouden we zoiets als dit moeten zien:

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   | 139887487548648

Merk op dat in MySQL 5.6 en 5.7 soortgelijke informatie wordt opgeslagen in de tabel innodb_lock_waits onder de database information_schema. Let op de BLOCKING_THREAD_ID waarde. We kunnen deze informatie gebruiken om te zoeken naar alle instructies die worden uitgevoerd door deze thread in de tabel events_statements_history:

mysql> SELECT * FROM performance_schema.events_statements_history WHERE `THREAD_ID` = 87;
0 rows in set

Het lijkt erop dat de draadinformatie er niet meer is. We kunnen verifiëren door de minimum- en maximumwaarde van de thread_id-kolom in de tabel events_statements_history te controleren met de volgende vraag:

mysql> SELECT min(`THREAD_ID`), max(`THREAD_ID`) FROM performance_schema.events_statements_history;
+------------------+------------------+
| min(`THREAD_ID`) | max(`THREAD_ID`) |
+------------------+------------------+
| 98               | 129              |
+------------------+------------------+

De thread die we zochten (87) is afgekapt uit de tabel. We kunnen dit bevestigen door te kijken naar de grootte van de tabel event_statements_history:

mysql> SELECT @@performance_schema_events_statements_history_size;
+-----------------------------------------------------+
| @@performance_schema_events_statements_history_size |
+-----------------------------------------------------+
| 10                                                  |
+-----------------------------------------------------+

Het bovenstaande betekent dat de events_statements_history alleen de laatste 10 threads kan opslaan. Gelukkig heeft performance_schema een andere tabel om meer rijen op te slaan, genaamd events_statements_history_long, die vergelijkbare informatie opslaat, maar voor alle threads en het kan veel meer rijen bevatten:

mysql> SELECT @@performance_schema_events_statements_history_long_size;
+----------------------------------------------------------+
| @@performance_schema_events_statements_history_long_size |
+----------------------------------------------------------+
| 10000                                                    |
+----------------------------------------------------------+

U krijgt echter een leeg resultaat als u de tabel events_statements_history_long voor de eerste keer probeert op te vragen. Dit wordt verwacht omdat deze instrumentatie standaard is uitgeschakeld in MySQL, zoals we kunnen zien in de volgende setup_consumers-tabel:

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     |
+----------------------------------+---------+

Om tabel events_statements_history_long te activeren, moeten we de setup_consumers tabel bijwerken zoals hieronder:

mysql> UPDATE performance_schema.setup_consumers SET enabled = 'YES' WHERE name = 'events_statements_history_long';

Controleer nu of er rijen zijn in de tabel events_statements_history_long:

mysql> SELECT count(`THREAD_ID`) FROM performance_schema.events_statements_history_long;
+--------------------+
| count(`THREAD_ID`) |
+--------------------+
| 4                  |
+--------------------+

Stoer. Nu kunnen we wachten tot de InnoDB lock-wachtgebeurtenis weer omhoog gaat en wanneer het gebeurt, zou je de volgende rij in de data_lock_waits-tabel moeten zien:

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   | 139887487548648

Nogmaals, we gebruiken de waarde BLOCKING_THREAD_ID om alle instructies die door deze thread zijn uitgevoerd te filteren tegen de tabel 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 |
+-----------+----------+-----------------------+----------------+----------------------------------------------------------------+

Eindelijk hebben we de boosdoener gevonden. We kunnen zien aan de reeks gebeurtenissen van thread 57 waar de bovenstaande transactie (T1) nog steeds niet is voltooid (geen COMMIT of ROLLBACK), en we kunnen zien dat de allerlaatste verklaring een exclusieve vergrendeling van de rij heeft gekregen voor update operatie die nodig was voor de andere transactie (T2) en gewoon daar bleef hangen. Dat verklaart waarom we 'Sleep' zien in de uitvoer van de MySQL-proceslijst.

Zoals we kunnen zien, vereist de bovenstaande SELECT-instructie dat u vooraf de thread_id-waarde ophaalt. Om deze query te vereenvoudigen, kunnen we de IN-component en een subquery gebruiken om beide tabellen samen te voegen. De volgende zoekopdracht levert een identiek resultaat op als het bovenstaande:

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 |
+-----------+----------+-----------------------+----------------+----------------------------------------------------------------+

Het is echter niet praktisch voor ons om de bovenstaande query uit te voeren wanneer de InnoDB lock wait-gebeurtenis optreedt. Afgezien van de fout van de toepassing, hoe zou u weten dat de lock-wachtgebeurtenis plaatsvindt? We kunnen deze query-uitvoering automatiseren met het volgende eenvoudige Bash-script, genaamd 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
done

Pas uitvoerbare toestemming toe en demoniseer het script op de achtergrond:

$ chmod 755 track_lockwait.sh
$ nohup ./track_lockwait.sh &

Nu hoeven we alleen maar te wachten tot de rapporten worden gegenereerd in de directory /root/lockwait. Afhankelijk van de databasewerkbelasting en rijtoegangspatronen, ziet u waarschijnlijk veel bestanden in deze map. Houd de map nauwlettend in de gaten, anders zou deze overspoeld worden met te veel rapportbestanden.

Als u ClusterControl gebruikt, kunt u de functie Transactielogboek inschakelen onder Prestaties -> Transactielogboek, waar ClusterControl een rapport geeft over impasses en langlopende transacties, wat uw leven bij het vinden van de boosdoener zal vergemakkelijken.

Conclusie

Samengevat:als we te maken krijgen met een fout 'Lock Wait Timeout Exceeded' in MySQL, moeten we eerst de effecten begrijpen die een dergelijke fout kan hebben op onze infrastructuur, vervolgens de aanstootgevende transactie volgen en actie ondernemen het ofwel met shell-scripts zoals track_lockwait.sh, of software voor databasebeheer zoals ClusterControl.

Als u besluit om voor shell-scripts te gaan, moet u er rekening mee houden dat ze u geld kunnen besparen, maar u tijd kosten, aangezien u het een en ander moet weten over hoe ze werken. machtigingen, en mogelijk op de achtergrond laten draaien, en als je verdwaalt in de schelpenjungle, kunnen we je helpen.

Wat je ook besluit te implementeren, zorg ervoor dat je ons volgt op Twitter of abonneer je op onze RSS-feed voor meer tips over het verbeteren van de prestaties van zowel je software als de databases die het ondersteunen, zoals dit bericht over 6 veelvoorkomende storingsscenario's in MySQL.