Jednym z najpopularniejszych błędów InnoDB jest przekroczenie limitu czasu oczekiwania na blokadę InnoDB, na przykład:
SQLSTATE[HY000]: General error: 1205 Lock wait timeout exceeded; try restarting transactionPowyższe oznacza po prostu, że transakcja osiągnęła innodb_lock_wait_timeout podczas oczekiwania na uzyskanie blokady na wyłączność, która domyślnie wynosi 50 sekund. Najczęstsze przyczyny to:
- Obraźliwa transakcja nie jest wystarczająco szybka, aby zatwierdzić lub wycofać transakcję w czasie trwania innodb_lock_wait_timeout.
- Obraźliwa transakcja czeka na zwolnienie blokady wiersza przez inną transakcję.
Skutki przekroczenia limitu czasu oczekiwania blokady InnoDB
Limit czasu oczekiwania na blokadę InnoDB może mieć dwie główne konsekwencje:
- Nieudana instrukcja nie jest domyślnie wycofywana.
- Nawet jeśli innodb_rollback_on_timeout jest włączone, kiedy instrukcja nie powiedzie się w transakcji, ROLLBACK jest nadal droższą operacją niż COMMIT.
Pobawmy się prostym przykładem, aby lepiej zrozumieć efekt. Rozważ następujące dwie tabele w bazie danych mydb:
mysql> CREATE SCHEMA mydb;
mysql> USE mydb;Pierwszy stół (tabela 1):
mysql> CREATE TABLE table1 ( id INT PRIMARY KEY AUTO_INCREMENT, data VARCHAR(50));
mysql> INSERT INTO table1 SET data = 'data #1';Druga tabela (tabela 2):
mysql> CREATE TABLE table2 LIKE table1;
mysql> INSERT INTO table2 SET data = 'data #2';Zrealizowaliśmy nasze transakcje w dwóch różnych sesjach w następującej kolejności:
| Zamawianie | Transakcja nr 1 (T1) | Transakcja nr 2 (T2) |
| 1 | WYBIERZ * Z tabela1; (OK) | SELECT * FROM table1; (OK) |
| 2 | UPDATE tabela1 SET data ='T1 aktualizuje wiersz' WHERE id =1; (OK) | |
| 3 | UPDATE tabela2 SET data ='T2 aktualizuje wiersz' WHERE id =1; (OK) | |
| 4 | UPDATE tabela1 SET data ='T2 aktualizuje wiersz' WHERE id =1; (Zawiesza się na chwilę i ostatecznie zwraca błąd „Przekroczono limit czasu oczekiwania na blokadę; spróbuj ponownie uruchomić transakcję”) | |
| 5 | ZATWIERDZENIE; (OK) | |
| 6 | ZATWIERDZENIE; (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 pomyślnym zatwierdzeniu T2 można by oczekiwać, że otrzymamy te same dane wyjściowe „T2 aktualizuje wiersz” zarówno dla tabeli 1, jak i tabeli 2, ale wyniki pokazują, że tylko tabela 2 została zaktualizowana. Można by pomyśleć, że jeśli jakikolwiek błąd napotka w transakcji, wszystkie oświadczenia w transakcji zostaną automatycznie wycofane lub jeśli transakcja zostanie pomyślnie zatwierdzona, wszystkie instrukcje zostaną wykonane niepodzielnie. Dotyczy to zakleszczenia, ale nie limitu czasu oczekiwania na blokadę InnoDB.
O ile nie ustawisz innodb_rollback_on_timeout=1 (domyślnie 0 - wyłączone), automatyczne wycofanie nie nastąpi w przypadku błędu upływu czasu oczekiwania na blokadę InnoDB. Oznacza to, że postępując zgodnie z ustawieniem domyślnym, MySQL nie zawiedzie i nie wycofa całej transakcji, ani nie będzie ponawiał ponownych prób z przekroczeniem limitu czasu i po prostu przetworzy następne instrukcje, aż do osiągnięcia COMMIT lub ROLLBACK. To wyjaśnia, dlaczego transakcja T2 została częściowo popełniona!
Dokumentacja InnoDB wyraźnie mówi „InnoDB wycofuje tylko ostatnią instrukcję po przekroczeniu limitu czasu transakcji domyślnie”. W tym przypadku nie uzyskujemy atomowości transakcji oferowanej przez InnoDB. Atomowość w zgodności z ACID polega na tym, że otrzymujemy całość lub nic z transakcji, co oznacza, że częściowa transakcja jest po prostu niedopuszczalna.
Radzenie sobie z przekroczeniem limitu czasu oczekiwania na blokadę InnoDB
Tak więc, jeśli spodziewasz się automatycznego wycofania transakcji po napotkaniu błędu oczekiwania na blokadę InnoDB, podobnie jak w przypadku zakleszczenia, ustaw następującą opcję w pliku konfiguracyjnym MySQL:
innodb_rollback_on_timeout=1Wymagane jest ponowne uruchomienie MySQL. Podczas wdrażania klastra opartego na MySQL, ClusterControl zawsze ustawia innodb_rollback_on_timeout=1 na każdym węźle. Bez tej opcji aplikacja musi ponowić próbę wykonania instrukcji, która zakończyła się niepowodzeniem lub wykonać jawne ROLLBACK, aby zachować niepodzielność transakcji.
Aby sprawdzić, czy konfiguracja została załadowana poprawnie:
mysql> SHOW GLOBAL VARIABLES LIKE 'innodb_rollback_on_timeout';
+----------------------------+-------+
| Variable_name | Value |
+----------------------------+-------+
| innodb_rollback_on_timeout | ON |
+----------------------------+-------+Aby sprawdzić, czy nowa konfiguracja działa, możemy śledzić licznik com_rollback, gdy wystąpi ten błąd:
mysql> SHOW GLOBAL STATUS LIKE 'com_rollback';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| Com_rollback | 1 |
+---------------+-------+Śledzenie transakcji blokującej
Istnieje kilka miejsc, w których możemy prześledzić blokującą transakcję lub wyciągi. Zacznijmy od sprawdzenia stanu silnika InnoDB w sekcji TRANSAKCJE:
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 powyższych informacji możemy uzyskać przegląd transakcji, które są aktualnie aktywne na serwerze. Transakcja 3097 obecnie blokuje wiersz, do którego musi uzyskać dostęp transakcja 3100. Jednak powyższe dane wyjściowe nie mówią nam o rzeczywistym tekście zapytania, który mógłby pomóc nam w ustaleniu, którą część zapytania/oświadczenia/transakcji musimy dokładniej zbadać . Używając blokera wątku MySQL o identyfikatorze 48, zobaczmy, co możemy zebrać z listy procesów 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> |
+----+-----------------+-----------------+--------------------+---------+------+------------------------+-----------------------+Identyfikator wątku 48 przedstawia polecenie jako „Sleep”. Jednak nie pomaga nam to zbytnio wiedzieć, które wyciągi blokują drugą transakcję. Dzieje się tak dlatego, że wyciąg w tej transakcji został wykonany, a ta otwarta transakcja w zasadzie nic w tej chwili nie robi. Musimy zanurkować dalej, aby zobaczyć, co dzieje się z tym wątkiem.
W przypadku MySQL 8.0 instrumentacja oczekiwania na blokadę InnoDB jest dostępna w tabeli data_lock_waits w bazie danych performance_schema (lub w tabeli innodb_lock_waits w bazie danych sys). Jeśli ma miejsce zdarzenie oczekiwania na blokadę, powinniśmy zobaczyć coś takiego:
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 | 139887487548648Zauważ, że w MySQL 5.6 i 5.7 podobne informacje są przechowywane w tabeli innodb_lock_waits w bazie danych information_schema. Zwróć uwagę na wartość BLOCKING_THREAD_ID. Możemy użyć tych informacji do wyszukania wszystkich instrukcji wykonywanych przez ten wątek w tabeli events_statements_history:
mysql> SELECT * FROM performance_schema.events_statements_history WHERE `THREAD_ID` = 87;
0 rows in setWygląda na to, że nie ma już informacji o wątku. Możemy to zweryfikować, sprawdzając minimalną i maksymalną wartość kolumny thread_id w tabeli events_statements_history za pomocą następującego zapytania:
mysql> SELECT min(`THREAD_ID`), max(`THREAD_ID`) FROM performance_schema.events_statements_history;
+------------------+------------------+
| min(`THREAD_ID`) | max(`THREAD_ID`) |
+------------------+------------------+
| 98 | 129 |
+------------------+------------------+Wątek, którego szukaliśmy (87) został obcięty z tabeli. Możemy to potwierdzić, patrząc na rozmiar tabeli event_statements_history:
mysql> SELECT @@performance_schema_events_statements_history_size;
+-----------------------------------------------------+
| @@performance_schema_events_statements_history_size |
+-----------------------------------------------------+
| 10 |
+-----------------------------------------------------+Powyższe oznacza, że event_statements_history może przechowywać tylko 10 ostatnich wątków. Na szczęście performance_schema ma inną tabelę do przechowywania większej liczby wierszy o nazwie events_statements_history_long, która przechowuje podobne informacje, ale dla wszystkich wątków i może zawierać znacznie więcej wierszy:
mysql> SELECT @@performance_schema_events_statements_history_long_size;
+----------------------------------------------------------+
| @@performance_schema_events_statements_history_long_size |
+----------------------------------------------------------+
| 10000 |
+----------------------------------------------------------+Jeśli jednak po raz pierwszy spróbujesz wykonać zapytanie do tabeli events_statements_history_long, otrzymasz pusty wynik. Jest to oczekiwane, ponieważ domyślnie ta instrumentacja jest wyłączona w MySQL, jak widać w poniższej tabeli 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 |
+----------------------------------+---------+Aby aktywować tabelę events_statements_history_long, musimy zaktualizować tabelę setup_consumers, jak poniżej:
mysql> UPDATE performance_schema.setup_consumers SET enabled = 'YES' WHERE name = 'events_statements_history_long';Sprawdź, czy w tabeli events_statements_history_long są teraz wiersze:
mysql> SELECT count(`THREAD_ID`) FROM performance_schema.events_statements_history_long;
+--------------------+
| count(`THREAD_ID`) |
+--------------------+
| 4 |
+--------------------+Fajny. Teraz możemy poczekać, aż zdarzenie oczekiwania na blokadę InnoDB ponownie się pojawi, a kiedy to nastąpi, powinieneś zobaczyć następujący wiersz w tabeli 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 | 139887487548648Ponownie używamy wartości BLOCKING_THREAD_ID do filtrowania wszystkich instrukcji, które zostały wykonane przez ten wątek, względem tabeli 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 |
+-----------+----------+-----------------------+----------------+----------------------------------------------------------------+W końcu znaleźliśmy winowajcę. Możemy stwierdzić, patrząc na sekwencję zdarzeń w wątku 57, gdzie powyższa transakcja (T1) jeszcze się nie zakończyła (brak COMMIT lub ROLLBACK), i widzimy, że ostatnia instrukcja uzyskała wyłączną blokadę wiersza w celu aktualizacji operacja, która jest wymagana przez inną transakcję (T2) i po prostu się tam zawiesza. To wyjaśnia, dlaczego w danych wyjściowych listy procesów MySQL widzimy „Sleep”.
Jak widać, powyższa instrukcja SELECT wymaga wcześniejszego pobrania wartości thread_id. Aby uprościć to zapytanie, możemy użyć klauzuli IN i podzapytania, aby połączyć obie tabele. Następujące zapytanie daje identyczny wynik jak powyżej:
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 |
+-----------+----------+-----------------------+----------------+----------------------------------------------------------------+Jednak nie jest praktyczne, abyśmy wykonywali powyższe zapytanie za każdym razem, gdy wystąpi zdarzenie oczekiwania na blokadę InnoDB. Pomijając błąd aplikacji, skąd możesz wiedzieć, że dzieje się zdarzenie oczekiwania na blokadę? Możemy zautomatyzować wykonanie tego zapytania za pomocą następującego prostego skryptu Bash o nazwie 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
doneZastosuj uprawnienia do wykonywania i demonizuj skrypt w tle:
$ chmod 755 track_lockwait.sh
$ nohup ./track_lockwait.sh &Teraz wystarczy poczekać na wygenerowanie raportów w katalogu /root/lockwait. W zależności od obciążenia bazy danych i wzorców dostępu do wierszy prawdopodobnie w tym katalogu może być widocznych wiele plików. Uważnie monitoruj katalog, w przeciwnym razie zostałby zalany zbyt wieloma plikami raportów.
Jeśli korzystasz z ClusterControl, możesz włączyć funkcję Dziennik transakcji w sekcji Wydajność -> Dziennik transakcji, gdzie ClusterControl dostarczy raport o zakleszczeniach i długotrwałych transakcjach, co ułatwi Ci znalezienie winowajcy.
Wnioski
Podsumowując, jeśli napotkamy błąd „Przekroczono limit czasu oczekiwania na blokadę” w MySQL, musimy najpierw zrozumieć skutki, jakie taki błąd może mieć dla naszej infrastruktury, a następnie śledzić obraźliwą transakcję i działać dalej albo za pomocą skryptów powłoki, takich jak track_lockwait.sh, albo oprogramowania do zarządzania bazami danych, takiego jak ClusterControl.
Jeśli zdecydujesz się na korzystanie ze skryptów powłoki, pamiętaj, że mogą one zaoszczędzić pieniądze, ale będą kosztować czas, ponieważ musisz wiedzieć kilka rzeczy na temat ich działania, złóż wniosek uprawnień i prawdopodobnie sprawić, by działały w tle, a jeśli zgubisz się w dżungli z powłokami, możemy pomóc.
Cokolwiek zdecydujesz się wdrożyć, śledź nas na Twitterze lub zasubskrybuj nasz kanał RSS, aby uzyskać więcej wskazówek na temat poprawy wydajności zarówno oprogramowania, jak i baz danych, które je wspierają, takich jak ten post obejmujący 6 typowych scenariuszy awarii w MySQL.
