Една от най-популярните грешки на InnoDB е, че времето за изчакване на заключване на InnoDB е превишено, например:
SQLSTATE[HY000]: General error: 1205 Lock wait timeout exceeded; try restarting transactionГорното просто означава, че транзакцията е достигнала innodb_lock_wait_timeout, докато чака да получи ексклузивно заключване, което по подразбиране е 50 секунди. Честите причини са:
- Обиждащата транзакция не е достатъчно бърза, за да извърши или отмени транзакцията в рамките на продължителността на innodb_lock_wait_timeout.
- Обиждащата транзакция изчаква заключването на реда да бъде освободено от друга транзакция.
Ефектите от изчакване на изчакване при заключване на InnoDB
Времето за изчакване на заключване на InnoDB може да доведе до две основни последици:
- Неуспешният оператор не се връща обратно по подразбиране.
- Дори ако innodb_rollback_on_timeout е активиран, когато израз се провали в транзакция, ROLLBACK все още е по-скъпа операция от COMMIT.
Нека поиграем с прост пример, за да разберем по-добре ефекта. Помислете за следните две таблици в базата данни mydb:
mysql> CREATE SCHEMA mydb;
mysql> USE mydb;Първата таблица (таблица1):
mysql> CREATE TABLE table1 ( id INT PRIMARY KEY AUTO_INCREMENT, data VARCHAR(50));
mysql> INSERT INTO table1 SET data = 'data #1';Втората таблица (таблица2):
mysql> CREATE TABLE table2 LIKE table1;
mysql> INSERT INTO table2 SET data = 'data #2';Изпълнихме нашите транзакции в две различни сесии в следния ред:
| Поръчка | Транзакция №1 (T1) | Транзакция №2 (T2) |
| 1 | ИЗБЕРЕТЕ * ОТ таблица1; (OK) | ИЗБЕРЕТЕ * ОТ таблица1; (OK) |
| 2 | АКТУАЛИЗАЦИЯ table1 SET data ='T1 актуализира реда' WHERE id =1; (OK) | |
| 3 | АКТУАЛИЗАЦИЯ table2 SET data ='T2 актуализира реда' WHERE id =1; (OK) | |
| 4 | UPDATE table1 SET data ='T2 актуализира реда' WHERE id =1; (Зависи за известно време и в крайна сметка връща грешка „Времето за изчакване на заключване е превишено; опитайте да рестартирате транзакцията“) | |
| 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 |
+----+-----------------------------------+След като T2 е бил успешно ангажиран, може да се очаква да получи същия изход „T2 актуализира реда“ както за таблица 1, така и за таблица 2, но резултатите показват, че само таблица 2 е актуализирана. Човек може да си помисли, че ако възникне грешка в транзакция, всички оператори в транзакцията автоматично ще бъдат върнати назад или ако транзакцията е успешно ангажирана, целите оператори се изпълняват атомарно. Това е вярно за блокиране, но не и за изчакване на изчакване на заключване на InnoDB.
Освен ако не зададете innodb_rollback_on_timeout=1 (по подразбиране е 0 - деактивирано), автоматичното връщане няма да се случи за грешка при изчакване на изчакване при заключване на InnoDB. Това означава, че следвайки настройката по подразбиране, MySQL няма да се провали и да отмени цялата транзакция, нито да опита отново изсрочения израз и просто да обработи следващите оператори, докато достигне COMMIT или ROLLBACK. Това обяснява защо транзакцията T2 е била частично ангажирана!
Документацията на InnoDB ясно казва „InnoDB връща само последното изявление при изчакване на транзакция по подразбиране". В този случай ние не получаваме атомарността на транзакцията, предлагана от InnoDB. Атомарността в ACID съвместим е или получаваме цялата или нищо от транзакцията, което означава, че частичната транзакция е просто неприемлива.
Справяне с изчакване на изчакване при заключване на InnoDB
Така че, ако очаквате транзакция за автоматично връщане назад, когато срещне грешка при изчакване при заключване на InnoDB, подобно на това, което би се случило в застой, задайте следната опция в конфигурационния файл на MySQL:
innodb_rollback_on_timeout=1Изисква се рестартиране на MySQL. При разполагане на MySQL-базиран клъстер, ClusterControl винаги ще задава innodb_rollback_on_timeout=1 на всеки възел. Без тази опция приложението ви трябва да опита отново с неуспешния оператор или да извърши изрично ROLLBACK, за да поддържа атомарността на транзакцията.
За да проверите дали конфигурацията е заредена правилно:
mysql> SHOW GLOBAL VARIABLES LIKE 'innodb_rollback_on_timeout';
+----------------------------+-------+
| Variable_name | Value |
+----------------------------+-------+
| innodb_rollback_on_timeout | ON |
+----------------------------+-------+За да проверим дали новата конфигурация работи, можем да проследим брояча com_rollback, когато се случи тази грешка:
mysql> SHOW GLOBAL STATUS LIKE 'com_rollback';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| Com_rollback | 1 |
+---------------+-------+Проследяване на блокиращата транзакция
Има няколко места, на които можем да търсим, за да проследим блокиращата транзакция или извлечения. Нека започнем, като разгледаме състоянието на двигателя на InnoDB в секцията ТРАНЗАКЦИИ:
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От горната информация можем да направим преглед на транзакциите, които в момента са активни в сървъра. Транзакция 3097 в момента заключва ред, който трябва да бъде достъпен от транзакция 3100. Горният изход обаче не ни казва действителния текст на заявката, който би могъл да ни помогне да разберем коя част от заявката/изявлението/транзакцията трябва да проучим допълнително . Като използваме блокера на MySQL нишка ID 48, нека видим какво можем да съберем от 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> |
+----+-----------------+-----------------+--------------------+---------+------+------------------------+-----------------------+Идентификатор на нишка 48 показва командата като 'Sleep'. Все пак това не ни помага много да разберем кои изявления блокират другата транзакция. Това е така, защото изявлението в тази транзакция е изпълнено и тази отворена транзакция по същество не прави нищо в момента. Трябва да се потопим по-надолу, за да видим какво се случва с тази тема.
За MySQL 8.0 инструментариумът за изчакване на InnoDB е наличен в таблицата data_lock_waits в базата данни performance_schema (или таблицата innodb_lock_waits в базата данни на sys). Ако се случи събитие за изчакване на заключване, трябва да видим нещо подобно:
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Имайте предвид, че в MySQL 5.6 и 5.7 подобна информация се съхранява в таблицата innodb_lock_waits в базата данни information_schema. Обърнете внимание на стойността BLOCKING_THREAD_ID. Можем да използваме тази информация, за да търсим всички изрази, изпълнявани от тази нишка в таблицата events_statements_history:
mysql> SELECT * FROM performance_schema.events_statements_history WHERE `THREAD_ID` = 87;
0 rows in setИзглежда, че информацията за нишката вече не е там. Можем да проверим, като проверим минималната и максималната стойност на колоната thread_id в таблицата events_statements_history със следната заявка:
mysql> SELECT min(`THREAD_ID`), max(`THREAD_ID`) FROM performance_schema.events_statements_history;
+------------------+------------------+
| min(`THREAD_ID`) | max(`THREAD_ID`) |
+------------------+------------------+
| 98 | 129 |
+------------------+------------------+Нишката, която търсихме (87), беше отрязана от таблицата. Можем да потвърдим това, като разгледаме размера на таблицата event_statements_history:
mysql> SELECT @@performance_schema_events_statements_history_size;
+-----------------------------------------------------+
| @@performance_schema_events_statements_history_size |
+-----------------------------------------------------+
| 10 |
+-----------------------------------------------------+Гореното означава, че events_statements_history може да съхранява само последните 10 нишки. За щастие, performance_schema има друга таблица за съхраняване на повече редове, наречена events_statements_history_long, която съхранява подобна информация, но за всички нишки и може да съдържа много повече редове:
mysql> SELECT @@performance_schema_events_statements_history_long_size;
+----------------------------------------------------------+
| @@performance_schema_events_statements_history_long_size |
+----------------------------------------------------------+
| 10000 |
+----------------------------------------------------------+Въпреки това, ще получите празен резултат, ако се опитате да потърсите за първи път таблицата events_statements_history_long. Това се очаква, тъй като по подразбиране тази инструментация е деактивирана в MySQL, както можем да видим в следната таблица 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 |
+----------------------------------+---------+За да активираме таблицата events_statements_history_long, трябва да актуализираме таблицата setup_consumers, както следва:
mysql> UPDATE performance_schema.setup_consumers SET enabled = 'YES' WHERE name = 'events_statements_history_long';Проверете дали сега в таблицата events_statements_history_long има редове:
mysql> SELECT count(`THREAD_ID`) FROM performance_schema.events_statements_history_long;
+--------------------+
| count(`THREAD_ID`) |
+--------------------+
| 4 |
+--------------------+Готино. Сега можем да изчакаме, докато събитието за заключване на InnoDB се повиши отново и когато се случи, трябва да видите следния ред в таблицата 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 | 139887487548648Отново използваме стойността BLOCKING_THREAD_ID, за да филтрираме всички изрази, които са били изпълнени от тази нишка, спрямо таблицата 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 |
+-----------+----------+-----------------------+----------------+----------------------------------------------------------------+Най-накрая намерихме виновника. Можем да разберем, като погледнем последователността от събития на нишка 57, където горната транзакция (T1) все още не е приключила (без COMMIT или ROLLBACK) и можем да видим, че последният израз е получил изключително заключване на реда за актуализиране операция, която е необходима на другата транзакция (T2) и просто виси там. Това обяснява защо виждаме 'Sleep' в изхода на MySQL процесния списък.
Както виждаме, горният оператор SELECT изисква предварително да получите стойността на thread_id. За да опростим тази заявка, можем да използваме клауза IN и подзаявка, за да обединим двете таблици. Следната заявка дава идентичен резултат като горния:
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 |
+-----------+----------+-----------------------+----------------+----------------------------------------------------------------+За нас обаче не е практично да изпълняваме горната заявка всеки път, когато възникне събитие за изчакване на заключване на InnoDB. Освен грешката от приложението, как ще разберете, че се случва събитието за изчакване на заключване? Можем да автоматизираме изпълнението на тази заявка със следния прост Bash скрипт, наречен 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Приложете разрешение за изпълним файл и демонизирайте скрипта във фонов режим:
$ chmod 755 track_lockwait.sh
$ nohup ./track_lockwait.sh &Сега просто трябва да изчакаме отчетите да бъдат генерирани в директорията /root/lockwait. В зависимост от работното натоварване на базата данни и моделите за достъп до редове, вероятно може да видите много файлове в тази директория. Следете внимателно директорията, в противен случай тя ще бъде наводнена с твърде много файлове с отчети.
Ако използвате ClusterControl, можете да активирате функцията дневник на транзакциите в Ефективност -> Регистър на транзакциите, където ClusterControl ще предостави отчет за блокиране и продължителни транзакции, което ще улесни живота ви при намирането на виновника.
Заключение
В обобщение, ако се сблъскаме с грешка „Lock Wait Timeout Exceeded“ в MySQL, първо трябва да разберем ефектите, които подобна грешка може да има върху нашата инфраструктура, след това да проследим обидната транзакция и да предприемем действия или с шел скриптове като track_lockwait.sh, или софтуер за управление на база данни като ClusterControl.
Ако решите да използвате shell скриптове, просто имайте предвид, че те може да ви спестят пари, но ще ви струват време, тъй като ще трябва да знаете нещо или две за това как работят, кандидатствайте разрешения и евентуално да ги накарате да работят във фонов режим и ако все пак се изгубите в джунглата на черупките, ние можем да помогнем.
Каквото и да решите да приложите, не забравяйте да ни последвате в Twitter или да се абонирате за нашата RSS емисия, за да получите повече съвети за подобряване на производителността както на вашия софтуер, така и на базите данни, които го поддържат, като например тази публикация, обхващаща 6 често срещани сценария на отказ в MySQL.
