Ett av de mest populära InnoDB-felen är att InnoDB-låsets väntetid har överskridits, till exempel:
SQLSTATE[HY000]: General error: 1205 Lock wait timeout exceeded; try restarting transactionOvanstående betyder helt enkelt att transaktionen har nått innodb_lock_wait_timeout i väntan på att få ett exklusivt lås som är standard på 50 sekunder. De vanligaste orsakerna är:
- Den stötande transaktionen är inte tillräckligt snabb för att utföra eller återställa transaktionen inom innodb_lock_wait_timeout-tiden.
- Den stötande transaktionen väntar på att radlåset ska släppas av en annan transaktion.
Effekterna av en InnoDB Lock Wait Timeout
InnoDB lås väntetid kan orsaka två stora konsekvenser:
- Det misslyckade uttalandet återställs inte som standard.
- Även om innodb_rollback_on_timeout är aktiverat, när ett uttalande misslyckas i en transaktion, är ROLLBACK fortfarande en dyrare operation än COMMIT.
Låt oss leka med ett enkelt exempel för att bättre förstå effekten. Tänk på följande två tabeller i databasen mydb:
mysql> CREATE SCHEMA mydb;
mysql> USE mydb;Den första tabellen (tabell1):
mysql> CREATE TABLE table1 ( id INT PRIMARY KEY AUTO_INCREMENT, data VARCHAR(50));
mysql> INSERT INTO table1 SET data = 'data #1';Den andra tabellen (tabell2):
mysql> CREATE TABLE table2 LIKE table1;
mysql> INSERT INTO table2 SET data = 'data #2';Vi utförde våra transaktioner i två olika sessioner i följande ordning:
| Beställning | Transaktion #1 (T1) | Transaktion #2 (T2) |
| 1 | VÄLJ * FRÅN tabell1; (OK) | VÄLJ * FRÅN tabell1; (OK) |
| 2 | UPPDATERA tabell1 SET data ='T1 uppdaterar raden' WHERE id =1; (OK) | |
| 3 | UPPDATERA tabell2 SET data ='T2 uppdaterar raden' WHERE id =1; (OK) | |
| 4 | UPPDATERA tabell1 SET data ='T2 uppdaterar raden' WHERE id =1; (Länger sig ett tag och returnerar så småningom ett felmeddelande "Lås väntan timeout har överskridits; försök starta om transaktionen") | |
| 5 | KOMMITTA; (OK) | |
| 6 | KOMMITTA; (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 att T2 framgångsrikt begåtts skulle man förvänta sig att få samma utdata "T2 uppdaterar raden" för både tabell1 och tabell2 men resultaten visar att endast tabell2 uppdaterades. Man skulle kunna tro att om något fel uppstår i en transaktion, skulle alla uttalanden i transaktionen automatiskt rullas tillbaka, eller om en transaktion framgångsrikt genomfördes, exekverades hela uttalanden atomärt. Detta gäller för dödläge, men inte för InnoDB-låsets väntetid.
Om du inte ställer in innodb_rollback_on_timeout=1 (standard är 0 - inaktiverad), kommer automatisk återställning inte att ske för InnoDB lock wait timeout fel. Detta innebär att, genom att följa standardinställningen, kommer MySQL inte att misslyckas och återställa hela transaktionen, och inte heller försöka igen på timeout-satsen och bara bearbeta nästa sats tills den når COMMIT eller ROLLBACK. Detta förklarar varför transaktion T2 delvis genomfördes!
InnoDB-dokumentationen säger tydligt "InnoDB återställer endast det sista uttalandet på en transaktionstimeout som standard". I det här fallet får vi inte transaktionens atomicitet som erbjuds av InnoDB. Atomiciteten i ACID-kompatibel är antingen att vi får allt eller ingenting av transaktionen, vilket innebär att en deltransaktion bara är oacceptabel.
Hantera en InnoDB-låsväntetid
Så om du förväntar dig att en transaktion ska återställas automatiskt när du stöter på ett InnoDB-låsväntefel, på samma sätt som vad som skulle hända i dödläge, ställ in följande alternativ i MySQL-konfigurationsfilen:
innodb_rollback_on_timeout=1En MySQL-omstart krävs. När ett MySQL-baserat kluster distribueras kommer ClusterControl alltid att ställa in innodb_rollback_on_timeout=1 på varje nod. Utan detta alternativ måste din applikation göra ett nytt försök med det misslyckade uttalandet eller utföra ROLLBACK explicit för att bibehålla transaktionens atomicitet.
Så här kontrollerar du om konfigurationen är korrekt laddad:
mysql> SHOW GLOBAL VARIABLES LIKE 'innodb_rollback_on_timeout';
+----------------------------+-------+
| Variable_name | Value |
+----------------------------+-------+
| innodb_rollback_on_timeout | ON |
+----------------------------+-------+För att kontrollera om den nya konfigurationen fungerar kan vi spåra com_rollback-räknaren när det här felet inträffar:
mysql> SHOW GLOBAL STATUS LIKE 'com_rollback';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| Com_rollback | 1 |
+---------------+-------+Spåra den blockerande transaktionen
Det finns flera ställen som vi kan leta efter för att spåra den blockerande transaktionen eller uttalanden. Låt oss börja med att titta på InnoDB-motorstatus under avsnittet 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 < 3097Från ovanstående information kan vi få en överblick över de transaktioner som för närvarande är aktiva på servern. Transaktion 3097 låser för närvarande en rad som behöver nås av transaktion 3100. Ovanstående utdata berättar dock inte för oss den faktiska frågetexten som kan hjälpa oss att ta reda på vilken del av frågan/påståendet/transaktionen som vi behöver undersöka vidare . Genom att använda blockeraren MySQL tråd ID 48, låt oss se vad vi kan samla in från MySQL processlistan:
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 visar kommandot som 'Sleep'. Ändå hjälper det oss inte mycket att veta vilka uttalanden som blockerar den andra transaktionen. Detta beror på att uttalandet i denna transaktion har utförts och denna öppna transaktion gör i princip ingenting för tillfället. Vi måste dyka längre ner för att se vad som händer med den här tråden.
För MySQL 8.0 är InnoDB lock wait-instrumenteringen tillgänglig under data_lock_waits-tabellen inuti performance_schema-databasen (eller innodb_lock_waits-tabellen i sys-databasen). Om en lås väntande händelse inträffar bör vi se något i stil med detta:
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 | 139887487548648Observera att i MySQL 5.6 och 5.7 lagras liknande information i tabellen innodb_lock_waits under informationsschemadatabasen. Var uppmärksam på BLOCKING_THREAD_ID-värdet. Vi kan använda denna information för att leta efter alla uttalanden som körs av den här tråden i tabellen event_statements_history:
mysql> SELECT * FROM performance_schema.events_statements_history WHERE `THREAD_ID` = 87;
0 rows in setDet verkar som om trådinformationen inte längre finns där. Vi kan verifiera genom att kontrollera det lägsta och högsta värdet för kolumnen thread_id i tabellen events_statements_history med följande fråga:
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 letade efter (87) har trunkerats från tabellen. Vi kan bekräfta detta genom att titta på storleken på tabellen event_statements_history:
mysql> SELECT @@performance_schema_events_statements_history_size;
+-----------------------------------------------------+
| @@performance_schema_events_statements_history_size |
+-----------------------------------------------------+
| 10 |
+-----------------------------------------------------+Ovanstående betyder att event_statements_history endast kan lagra de senaste 10 trådarna. Lyckligtvis har performance_schema en annan tabell för att lagra fler rader som kallas event_statements_history_long, som lagrar liknande information men för alla trådar och den kan innehålla mycket fler rader:
mysql> SELECT @@performance_schema_events_statements_history_long_size;
+----------------------------------------------------------+
| @@performance_schema_events_statements_history_long_size |
+----------------------------------------------------------+
| 10000 |
+----------------------------------------------------------+Du kommer dock att få ett tomt resultat om du försöker fråga den långa tabellen event_statements_history_för första gången. Detta förväntas eftersom denna instrumentering som standard är inaktiverad i MySQL som vi kan se i följande setup_consumers-tabell:
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 |
+----------------------------------+---------+För att aktivera table events_statements_history_long måste vi uppdatera tabellen setup_consumers enligt nedan:
mysql> UPDATE performance_schema.setup_consumers SET enabled = 'YES' WHERE name = 'events_statements_history_long';Verifiera om det finns rader i den långa tabellen events_statements_history_long:
mysql> SELECT count(`THREAD_ID`) FROM performance_schema.events_statements_history_long;
+--------------------+
| count(`THREAD_ID`) |
+--------------------+
| 4 |
+--------------------+Häftigt. Nu kan vi vänta tills InnoDB lock wait-händelsen uppstår igen och när den händer bör du se följande rad 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 | 139887487548648Återigen använder vi BLOCKING_THREAD_ID-värdet för att filtrera alla uttalanden som har körts av den här tråden mot event_statements_history_long tabell:
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 |
+-----------+----------+-----------------------+----------------+----------------------------------------------------------------+Till slut hittade vi den skyldige. Vi kan se genom att titta på händelseförloppet i tråd 57 där ovanstående transaktion (T1) fortfarande inte har avslutats ännu (ingen COMMIT eller ROLLBACK), och vi kan se att det allra sista uttalandet har fått en exklusiv låsning till raden för uppdatering operation som behövs av den andra transaktionen (T2) och bara hänger där. Det förklarar varför vi ser 'Sleep' i MySQL-proceslistans utdata.
Som vi kan se kräver ovanstående SELECT-sats att du skaffar thread_id-värdet i förväg. För att förenkla den här frågan kan vi använda IN-sats och en underfråga för att sammanfoga båda tabellerna. Följande fråga ger ett identiskt resultat som ovan:
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 är dock inte praktiskt för oss att köra ovanstående fråga närhelst InnoDB lock wait-händelse inträffar. Bortsett från felet från applikationen, hur skulle du veta att låsväntehändelsen inträffar? Vi kan automatisera den här frågans körning med följande enkla Bash-skript, kallat 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
doneTillämpa körbar behörighet och demonisera skriptet i bakgrunden:
$ chmod 755 track_lockwait.sh
$ nohup ./track_lockwait.sh &Nu behöver vi bara vänta på att rapporterna ska genereras under katalogen /root/lockwait. Beroende på databasens arbetsbelastning och radåtkomstmönster kan du förmodligen se många filer under den här katalogen. Övervaka katalogen noga, annars skulle den översvämmas av för många rapportfiler.
Om du använder ClusterControl kan du aktivera funktionen Transaktionslogg under Prestanda -> Transaktionslogg där ClusterControl kommer att tillhandahålla en rapport om låsningar och långvariga transaktioner som kommer att underlätta ditt liv när det gäller att hitta den skyldige.
Slutsats
Sammanfattningsvis, om vi står inför ett "Lås väntan timeout överskriden"-fel i MySQL, måste vi först förstå effekterna som ett sådant fel kan ha på vår infrastruktur, sedan spåra den stötande transaktionen och agera på det antingen med skalskript som track_lockwait.sh eller databashanteringsprogram som ClusterControl.
Om du bestämmer dig för att använda skalskript, kom bara ihåg att de kan spara pengar men kommer att kosta dig tid, eftersom du behöver veta en sak eller två om hur de fungerar, ansök behörigheter och eventuellt få dem att köras i bakgrunden, och om du går vilse i skaldjungeln kan vi hjälpa till.
Oavsett vad du bestämmer dig för att implementera, se till att följa oss på Twitter eller prenumerera på vårt RSS-flöde för att få fler tips om hur du förbättrar prestandan för både din programvara och de databaser som stödjer den, till exempel det här inlägget som täcker sex vanliga felscenarier i MySQL.