En af de mest populære InnoDB's fejl er, at InnoDB-låsens ventetid er overskredet, for eksempel:
SQLSTATE[HY000]: General error: 1205 Lock wait timeout exceeded; try restarting transactionOvenstående betyder ganske enkelt, at transaktionen har nået innodb_lock_wait_timeout, mens den ventede på at få en eksklusiv lås, som som standard er 50 sekunder. De almindelige årsager er:
- Den stødende transaktion er ikke hurtig nok til at begå eller tilbageføre transaktionen inden for innodb_lock_wait_timeout-varigheden.
- Den stødende transaktion venter på, at rækkelåsen frigives af en anden transaktion.
Effekterne af en InnoDB-lås-ventetimeout
InnoDB-låseventetimeout kan forårsage to store konsekvenser:
- Den mislykkede sætning rulles ikke tilbage som standard.
- Selv hvis innodb_rollback_on_timeout er aktiveret, når en erklæring fejler i en transaktion, er ROLLBACK stadig en dyrere operation end COMMIT.
Lad os lege med et simpelt eksempel for bedre at forstå effekten. Overvej følgende to tabeller i databasen mydb:
mysql> CREATE SCHEMA mydb;
mysql> USE mydb;Den første tabel (tabel1):
mysql> CREATE TABLE table1 ( id INT PRIMARY KEY AUTO_INCREMENT, data VARCHAR(50));
mysql> INSERT INTO table1 SET data = 'data #1';Den anden tabel (tabel2):
mysql> CREATE TABLE table2 LIKE table1;
mysql> INSERT INTO table2 SET data = 'data #2';Vi udførte vores transaktioner i to forskellige sessioner i følgende rækkefølge:
| Bestilling | Transaktion #1 (T1) | Transaktion #2 (T2) |
| 1 | VÆLG * FRA tabel1; (OK) | VÆLG * FRA tabel1; (OK) |
| 2 | OPDATERING tabel1 SET data ='T1 opdaterer rækken' WHERE id =1; (OK) | |
| 3 | OPDATERING tabel2 SET data ='T2 opdaterer rækken' WHERE id =1; (OK) | |
| 4 | OPDATERING tabel1 SET data ='T2 opdaterer rækken' WHERE id =1; (Hænger et stykke tid og returnerer til sidst fejlen "Lås ventetid overskredet; prøv at genstarte transaktionen") | |
| 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 |
+----+-----------------------------------+Efter at T2 var blevet gennemført med succes, ville man forvente at få det samme output "T2 opdaterer rækken" for både tabel1 og tabel2, men resultaterne viser, at kun tabel2 blev opdateret. Man kunne tro, at hvis der opstår en fejl inden for en transaktion, vil alle udsagn i transaktionen automatisk blive rullet tilbage, eller hvis en transaktion er gennemført med succes, blev hele udsagn udført atomisk. Dette er sandt for deadlock, men ikke for InnoDB-låsens ventetimeout.
Medmindre du indstiller innodb_rollback_on_timeout=1 (standard er 0 - deaktiveret), vil automatisk tilbagerulning ikke ske for InnoDB-lås-ventetimeout-fejl. Dette betyder, at ved at følge standardindstillingen, vil MySQL ikke fejle og rulle hele transaktionen tilbage, og heller ikke prøve igen den timeout-erklæring og bare behandle de næste sætninger, indtil den når COMMIT eller ROLLBACK. Dette forklarer, hvorfor transaktion T2 blev delvist forpligtet!
InnoDB-dokumentationen siger tydeligt "InnoDB ruller kun den sidste erklæring tilbage på en transaktionstimeout som standard". I dette tilfælde får vi ikke den transaktionsatomicitet, som InnoDB tilbyder. Atomiciteten i ACID-kompatibel er enten vi får alt eller intet af transaktionen, hvilket betyder, at en delvis transaktion blot er uacceptabel.
Håndtering af en InnoDB-lås-ventetimeout
Så hvis du forventer, at en transaktion automatisk ruller tilbage, når du støder på en InnoDB-lås-vent-fejl, på samme måde som hvad der ville ske i dødvande, skal du indstille følgende indstilling i MySQL-konfigurationsfilen:
innodb_rollback_on_timeout=1En MySQL-genstart er påkrævet. Når du implementerer en MySQL-baseret klynge, vil ClusterControl altid indstille innodb_rollback_on_timeout=1 på hver node. Uden denne mulighed skal din applikation prøve den mislykkede erklæring igen eller udføre ROLLBACK eksplicit for at opretholde transaktionens atomicitet.
For at kontrollere, om konfigurationen er indlæst korrekt:
mysql> SHOW GLOBAL VARIABLES LIKE 'innodb_rollback_on_timeout';
+----------------------------+-------+
| Variable_name | Value |
+----------------------------+-------+
| innodb_rollback_on_timeout | ON |
+----------------------------+-------+For at kontrollere, om den nye konfiguration virker, kan vi spore com_rollback-tælleren, når denne fejl opstår:
mysql> SHOW GLOBAL STATUS LIKE 'com_rollback';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| Com_rollback | 1 |
+---------------+-------+Sporing af blokeringstransaktionen
Der er flere steder, vi kan se for at spore den blokerende transaktion eller kontoudtog. Lad os starte med at se på InnoDB-motorstatus under afsnittet TRANSAKTIONER:
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 < 3097Ud fra ovenstående information kan vi få et overblik over de transaktioner, der i øjeblikket er aktive på serveren. Transaktion 3097 låser i øjeblikket en række, der skal tilgås af transaktion 3100. Ovenstående output fortæller os dog ikke den faktiske forespørgselstekst, der kunne hjælpe os med at finde ud af, hvilken del af forespørgslen/erklæringen/transaktionen, vi skal undersøge nærmere . Ved at bruge blockeren MySQL tråd ID 48, lad os se, hvad vi kan indsamle fra MySQL proceslisten:
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> |
+----+-----------------+-----------------+--------------------+---------+------+------------------------+-----------------------+Tråd ID 48 viser kommandoen som 'Sleep'. Alligevel hjælper det os ikke meget at vide, hvilke udsagn der blokerer for den anden transaktion. Dette skyldes, at erklæringen i denne transaktion er blevet udført, og denne åbne transaktion gør stort set ingenting i øjeblikket. Vi skal dykke længere ned for at se, hvad der foregår med denne tråd.
For MySQL 8.0 er InnoDB lock wait-instrumenteringen tilgængelig under data_lock_waits-tabellen inde i performance_schema-databasen (eller innodb_lock_waits-tabellen inde i sys-databasen). Hvis der sker en låsevent hændelse, bør vi se noget som dette:
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 | 139887487548648Bemærk, at i MySQL 5.6 og 5.7 er den lignende information gemt i tabellen innodb_lock_waits under informationsskema-databasen. Vær opmærksom på BLOCKING_THREAD_ID-værdien. Vi kan bruge denne information til at lede efter alle udsagn, der udføres af denne tråd i tabellen begivenheder_udsagn_historie:
mysql> SELECT * FROM performance_schema.events_statements_history WHERE `THREAD_ID` = 87;
0 rows in setDet ser ud til, at trådinformationen ikke længere er der. Vi kan verificere ved at kontrollere minimums- og maksimumværdien af thread_id-kolonnen i tabellen events_statements_history med følgende forespørgsel:
mysql> SELECT min(`THREAD_ID`), max(`THREAD_ID`) FROM performance_schema.events_statements_history;
+------------------+------------------+
| min(`THREAD_ID`) | max(`THREAD_ID`) |
+------------------+------------------+
| 98 | 129 |
+------------------+------------------+Tråden, som vi ledte efter (87), er blevet afkortet fra tabellen. Vi kan bekræfte dette ved at se på størrelsen af tabellen begivenhed_udsagn_historie:
mysql> SELECT @@performance_schema_events_statements_history_size;
+-----------------------------------------------------+
| @@performance_schema_events_statements_history_size |
+-----------------------------------------------------+
| 10 |
+-----------------------------------------------------+Ovenstående betyder, at event_statements_history kun kan gemme de sidste 10 tråde. Heldigvis har performance_schema en anden tabel til at gemme flere rækker kaldet events_statements_history_long, som gemmer lignende information, men for alle tråde, og den kan indeholde meget flere rækker:
mysql> SELECT @@performance_schema_events_statements_history_long_size;
+----------------------------------------------------------+
| @@performance_schema_events_statements_history_long_size |
+----------------------------------------------------------+
| 10000 |
+----------------------------------------------------------+Du vil dog få et tomt resultat, hvis du forsøger at forespørge i tabellen hændelser_udsagn_historik for første gang. Dette forventes, fordi denne instrumentering som standard er deaktiveret i MySQL, som vi kan se i følgende 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 |
+----------------------------------+---------+For at aktivere table events_statements_history_long skal vi opdatere tabellen setup_consumers som nedenfor:
mysql> UPDATE performance_schema.setup_consumers SET enabled = 'YES' WHERE name = 'events_statements_history_long';Bekræft, om der er rækker i tabellen begivenheder_udsagn_historie_lange nu:
mysql> SELECT count(`THREAD_ID`) FROM performance_schema.events_statements_history_long;
+--------------------+
| count(`THREAD_ID`) |
+--------------------+
| 4 |
+--------------------+Fedt nok. Nu kan vi vente, indtil InnoDB lock wait-hændelsen rejser sig igen, og når den sker, bør du se følgende række i data_lock_waits-tabellen:
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 | 139887487548648Igen bruger vi værdien BLOCKING_THREAD_ID til at filtrere alle udsagn, der er blevet udført af denne tråd mod begivenheds_udsagn_historie_lang tabel:
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 |
+-----------+----------+-----------------------+----------------+----------------------------------------------------------------+Endelig fandt vi den skyldige. Vi kan se ved at se på rækkefølgen af begivenheder i tråd 57, hvor ovenstående transaktion (T1) stadig ikke er afsluttet endnu (ingen COMMIT eller ROLLBACK), og vi kan se, at den allersidste erklæring har opnået en eksklusiv lås til rækken for opdatering operation, som er nødvendig for den anden transaktion (T2) og bare hænger der. Det forklarer, hvorfor vi ser 'Sleep' i MySQL-proceslistens output.
Som vi kan se, kræver ovenstående SELECT-sætning, at du får thread_id-værdien på forhånd. For at forenkle denne forespørgsel kan vi bruge IN-sætning og en underforespørgsel til at forbinde begge tabeller. Følgende forespørgsel giver et identisk resultat som ovenstående:
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 |
+-----------+----------+-----------------------+----------------+----------------------------------------------------------------+Det er dog ikke praktisk for os at udføre ovenstående forespørgsel, hver gang InnoDB låsevent hændelse opstår. Bortset fra fejlen fra applikationen, hvordan ville du vide, at låsevent-hændelsen finder sted? Vi kan automatisere denne forespørgselsudførelse med følgende simple Bash-script, kaldet 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
doneAnvend eksekverbar tilladelse og dæmoniser scriptet i baggrunden:
$ chmod 755 track_lockwait.sh
$ nohup ./track_lockwait.sh &Nu skal vi bare vente på, at rapporterne bliver genereret under mappen /root/lockwait. Afhængigt af databasens arbejdsbyrde og rækkeadgangsmønstre kan du sandsynligvis se mange filer under denne mappe. Overvåg mappen nøje, ellers ville den blive oversvømmet med for mange rapportfiler.
Hvis du bruger ClusterControl, kan du aktivere funktionen Transaktionslog under Performance -> Transaktionslog, hvor ClusterControl vil levere en rapport om dødvande og langvarige transaktioner, som vil lette dit liv med at finde den skyldige.
Konklusion
Hvis vi står over for en "Lås ventetimeout overskredet"-fejl i MySQL, skal vi først forstå de virkninger, en sådan fejl kan have på vores infrastruktur, derefter spore den stødende transaktion og handle på det enten med shell-scripts som track_lockwait.sh eller databasestyringssoftware som ClusterControl.
Hvis du beslutter dig for at gå med shell-scripts, skal du bare huske på, at de kan spare dig penge, men vil koste dig tid, da du skal vide en ting eller to om, hvordan de fungerer, ansøg tilladelser, og muligvis få dem til at køre i baggrunden, og hvis du farer vild i shelljunglen, kan vi hjælpe.
Uanset hvad du beslutter dig for at implementere, skal du sørge for at følge os på Twitter eller abonnere på vores RSS-feed for at få flere tips til at forbedre ydeevnen af både din software og de databaser, der understøtter den, såsom dette indlæg, der dækker 6 almindelige fejlscenarier i MySQL.