Как отлаживать время ожидания ожидания ожидания ожидания на сервере MySQL?

То, что дает это, – это слово транзакция . По утверждению, очевидно, что запрос пытался изменить хотя бы одну строку в одной или нескольких таблицах InnoDB.

Поскольку вы знаете запрос, все доступные таблицы являются кандидатами на то, чтобы быть виновником.

Оттуда вы сможете запустить SHOW ENGINE INNODB STATUS\G

Вы должны иметь возможность видеть затронутые таблицы (таблицы)

Вы получаете все виды дополнительной информации о блокировке и мьютексе.

Вот пример от одного из моих клиентов:

 mysql> show engine innodb status\G *************************** 1. row *************************** Type: InnoDB Name: Status: ===================================== 110514 19:44:14 INNODB MONITOR OUTPUT ===================================== Per second averages calculated from the last 4 seconds ---------- SEMAPHORES ---------- OS WAIT ARRAY INFO: reservation count 9014315, signal count 7805377 Mutex spin waits 0, rounds 11487096053, OS waits 7756855 RW-shared spins 722142, OS waits 211221; RW-excl spins 787046, OS waits 39353 ------------------------ LATEST FOREIGN KEY ERROR ------------------------ 110507 21:41:35 Transaction: TRANSACTION 0 606162814, ACTIVE 0 sec, process no 29956, OS thread id 1223895360 updating or deleting, thread declared inside InnoDB 499 mysql tables in use 1, locked 1 14 lock struct(s), heap size 3024, 8 row lock(s), undo log entries 1 MySQL thread id 3686635, query id 124164167 10.64.89.145 viget updating DELETE FROM file WHERE file_id in ('6dbafa39-7f00-0001-51f2-412a450be5cc' ) Foreign key constraint fails for table `backoffice`.`attachment`: , CONSTRAINT `attachment_ibfk_2` FOREIGN KEY (`file_id`) REFERENCES `file` (`file_id`) Trying to delete or update in parent table, in index `PRIMARY` tuple: DATA TUPLE: 17 fields; 0: len 36; hex 36646261666133392d376630302d303030312d353166322d343132613435306265356363; asc 6dbafa39-7f00-0001-51f2-412a450be5cc;; 1: len 6; hex 000024214f7e; asc $!O~;; 2: len 7; hex 000000400217bc; asc @ ;; 3: len 2; hex 03e9; asc ;; 4: len 2; hex 03e8; asc ;; 5: len 36; hex 65666635323863622d376630302d303030312d336632662d353239626433653361333032; asc eff528cb-7f00-0001-3f2f-529bd3e3a302;; 6: len 40; hex 36646234376337652d376630302d303030312d353166322d3431326132346664656366352e6d7033; asc 6db47c7e-7f00-0001-51f2-412a24fdecf5.mp3;; 7: len 21; hex 416e67656c73204e6f7720436f6e666572656e6365; asc Angels Now Conference;; 8: len 34; hex 416e67656c73204e6f7720436f6e666572656e6365204a756c7920392c2032303131; asc Angels Now Conference July 9, 2011;; 9: len 1; hex 80; asc ;; 10: len 8; hex 8000124a5262bdf4; asc JRb ;; 11: len 8; hex 8000124a57669dc3; asc JWf ;; 12: SQL NULL; 13: len 5; hex 8000012200; asc " ;; 14: len 1; hex 80; asc ;; 15: len 2; hex 83e8; asc ;; 16: len 4; hex 8000000a; asc ;; But in child table `backoffice`.`attachment`, in index `PRIMARY`, there is a record: PHYSICAL RECORD: n_fields 6; compact format; info bits 0 0: len 30; hex 36646261666133392d376630302d303030312d353166322d343132613435; asc 6dbafa39-7f00-0001-51f2-412a45;...(truncated); 1: len 30; hex 38666164663561652d376630302d303030312d326436612d636164326361; asc 8fadf5ae-7f00-0001-2d6a-cad2ca;...(truncated); 2: len 6; hex 00002297b3ff; asc " ;; 3: len 7; hex 80000040070110; asc @ ;; 4: len 2; hex 0000; asc ;; 5: len 30; hex 416e67656c73204e6f7720436f6e666572656e636520446f63756d656e74; asc Angels Now Conference Document;; ------------ TRANSACTIONS ------------ Trx id counter 0 620783814 Purge done for trx's n:o < 0 620783800 undo n:o < 0 0 History list length 35 LIST OF TRANSACTIONS FOR EACH SESSION: ---TRANSACTION 0 0, not started, process no 29956, OS thread id 1192212800 MySQL thread id 5341758, query id 189708501 127.0.0.1 lwdba show innodb status ---TRANSACTION 0 620783788, not started, process no 29956, OS thread id 1196472640 MySQL thread id 5341773, query id 189708353 10.64.89.143 viget ---TRANSACTION 0 0, not started, process no 29956, OS thread id 1223895360 MySQL thread id 5341667, query id 189706152 10.64.89.145 viget ---TRANSACTION 0 0, not started, process no 29956, OS thread id 1227888960 MySQL thread id 5341556, query id 189699857 172.16.135.63 lwdba ---TRANSACTION 0 620781112, not started, process no 29956, OS thread id 1222297920 MySQL thread id 5341511, query id 189696265 10.64.89.143 viget ---TRANSACTION 0 620783736, not started, process no 29956, OS thread id 1229752640 MySQL thread id 5339005, query id 189707998 10.64.89.144 viget ---TRANSACTION 0 620783785, not started, process no 29956, OS thread id 1198602560 MySQL thread id 5337583, query id 189708349 10.64.89.145 viget ---TRANSACTION 0 620783469, not started, process no 29956, OS thread id 1224161600 MySQL thread id 5333500, query id 189708478 10.64.89.144 viget ---TRANSACTION 0 620781240, not started, process no 29956, OS thread id 1198336320 MySQL thread id 5324256, query id 189708493 10.64.89.145 viget ---TRANSACTION 0 617458223, not started, process no 29956, OS thread id 1195141440 MySQL thread id 736, query id 175038790 Has read all relay log; waiting for the slave I/O thread to update it -------- FILE I/O -------- I/O thread 0 state: waiting for i/o request (insert buffer thread) I/O thread 1 state: waiting for i/o request (log thread) I/O thread 2 state: waiting for i/o request (read thread) I/O thread 3 state: waiting for i/o request (write thread) Pending normal aio reads: 0, aio writes: 0, ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0 Pending flushes (fsync) log: 0; buffer pool: 0 519878 OS file reads, 18962880 OS file writes, 13349046 OS fsyncs 0.00 reads/s, 0 avg bytes/read, 6.25 writes/s, 4.50 fsyncs/s ------------------------------------- INSERT BUFFER AND ADAPTIVE HASH INDEX ------------------------------------- Ibuf: size 1, free list len 1190, seg size 1192, 174800 inserts, 174800 merged recs, 54439 merges Hash table size 35401603, node heap has 35160 buffer(s) 0.50 hash searches/s, 11.75 non-hash searches/s --- LOG --- Log sequence number 28 1235093534 Log flushed up to 28 1235093534 Last checkpoint at 28 1235091275 0 pending log writes, 0 pending chkp writes 12262564 log i/o's done, 3.25 log i/o's/second ---------------------- BUFFER POOL AND MEMORY ---------------------- Total memory allocated 18909316674; in additional pool allocated 1048576 Dictionary memory allocated 2019632 Buffer pool size 1048576 Free buffers 175763 Database pages 837653 Modified db pages 6 Pending reads 0 Pending writes: LRU 0, flush list 0, single page 0 Pages read 770138, created 108485, written 7795318 0.00 reads/s, 0.00 creates/s, 4.25 writes/s Buffer pool hit rate 1000 / 1000 -------------- ROW OPERATIONS -------------- 0 queries inside InnoDB, 0 queries in queue 1 read views open inside InnoDB Main thread process no. 29956, id 1185823040, state: sleeping Number of rows inserted 6453767, updated 4602534, deleted 3638793, read 388349505551 0.25 inserts/s, 1.25 updates/s, 0.00 deletes/s, 2.75 reads/s ---------------------------- END OF INNODB MONITOR OUTPUT ============================ 1 row in set, 1 warning (0.00 sec) 

Вы должны подумать об увеличении значения ожидания ожидания блокировки для InnoDB, установив innodb_lock_wait_timeout , значение по умолчанию - 50 секунд

 mysql> show variables like 'innodb_lock_wait_timeout'; +--------------------------+-------+ | Variable_name | Value | +--------------------------+-------+ | innodb_lock_wait_timeout | 50 | +--------------------------+-------+ 1 row in set (0.01 sec) 

Вы можете установить его на большее значение в /etc/my.cnf навсегда с помощью этой строки

 [mysqld] innodb_lock_wait_timeout=120 

и перезапустите mysql. Если вы не можете перезапустить mysql в это время, запустите это:

 SET GLOBAL innodb_lock_wait_timeout = 120; 

Вы также можете просто установить его на время сеанса

 SET innodb_lock_wait_timeout = 120; 

затем ваш запрос

Как кто-то упомянул в одном из многих SO-streamов, касающихся этой проблемы: иногда процесс, который заблокировал таблицу, отображается как спящий в списке процессов! Я рвал волосы до тех пор, пока не уничтожу все спящие нити, которые были открыты в соответствующей базе данных (в то время ни одна из них не была активной). Это, наконец, разблокирует таблицу и позволяет запустить запрос обновления.

Комментарий сказал что-то похожее на «Иногда stream MySQL блокирует таблицу, а затем спит, пока он ждет чего-то, что не связано с MySQL».

После повторного пересмотра журнала show engine innodb status (как только я выследил клиента, ответственного за блокировку), я заметил, что застрявший stream был указан в самом конце списка транзакций, под активными запросами, которые были готовы к ошибке из-за замороженного замка:

 ------------------ ---TRANSACTION 2744943820, ACTIVE 1154 sec(!!) 2 lock struct(s), heap size 376, 2 row lock(s), undo log entries 1 MySQL thread id 276558, OS thread handle 0x7f93762e7710, query id 59264109 [ip] [database] cleaning up Trx read view will not see trx with id >= 2744943821, sees < 2744943821 

(неуверенный, если сообщение «Просмотр прочитанного сообщения Trx» связано с замороженной блокировкой, но в отличие от других активных транзакций это не отображается с запросом, который был выпущен, и вместо этого утверждает, что транзакция «очищает», но имеет несколько строчные замки)

Мораль этой истории заключается в том, что транзакция может быть активной, даже если stream спал.

Из-за популярности MySQL, не удивительно, что время ожидания ожидания ожидания ожидания превышено; попробуйте перезапустить исключение транзакции, так много внимания уделяет SO.

Чем больше у вас конкурентов, тем больше вероятность блокировок, которые механизм БД будет решать путем тайм-аута одной из тупиковых транзакций. Кроме того, долгосрочные транзакции, которые модифицировали (например, UPDATE или DELETE ) большое количество записей (которые занимают блокировки во избежание аномалий с грязной записью, как описано в книге высокопроизводительных Java Persistence ), скорее всего, создадут конфликты с другими транзакциями ,

Хотя InnoDB MVCC, вы можете запросить явные блокировки с помощью предложения FOR UPDATE . Однако, в отличие от других популярных БД (Oracle, MSSQL, PostgreSQL, DB2), MySQL использует REPEATABLE_READ как уровень изоляции по умолчанию .

Теперь блокировки, которые вы приобрели (либо путем изменения строк, либо с использованием явной блокировки), удерживаются на время текущей транзакции. Если вы хотите получить хорошее объяснение разницы между REPEATABLE_READ и READ COMMITTED в отношении блокировки, прочитайте эту статью в Percona .

В REPEATABLE READ каждый замок, приобретенный во время транзакции, удерживается на время транзакции.

В READ COMMITTED блокировки, которые не совпадают с проверкой, выходят после завершения ЗАЯВЛЕНИЯ.

…

Это означает, что в READ COMMITTED другие транзакции могут обновлять строки, которые они не смогли бы обновить (в REPEATABLE READ) после завершения инструкции UPDATE.

Это более ограничительный уровень изоляции ( REPEATABLE_READ , SERIALIZABLE ), тем больше вероятность блокировки. Это не проблема «per se», это компромисс.

Вы можете получить очень хорошие результаты с помощью READ_COMMITED , так как вам необходимо предотвратить предотrotation обновления на уровне приложения при использовании логических транзакций, которые охватывают несколько HTTP-запросов. Оптимистичный подход к блокировке нацелен на потерянные обновления, которые могут произойти, даже если вы используете SERIALIZABLE изоляции SERIALIZABLE одновременно уменьшая конфликт блокировки, позволяя использовать READ_COMMITED .

Для записи исключение ожидания ожидания блокировки происходит также, когда есть тупик, и MySQL не может его обнаружить, поэтому он просто отключается. Еще одна причина может заключаться в чрезвычайно длительном запросе, который проще решить / отремонтировать, и я не буду описывать этот случай здесь.

Обычно MySQL может иметь дело с взаимоблокировками, если они построены «правильно» в двух транзакциях. Затем MySQL просто убивает / откатывает одну транзакцию, которая владеет меньшим количеством блокировок (менее важно, так как она будет влиять на меньшее количество строк) и позволяет другому завершить.

Предположим теперь, что существует два процесса A и B и 3 транзакции:

 Process A Transaction 1: Locks X Process B Transaction 2: Locks Y Process A Transaction 3: Needs Y => Waits for Y Process B Transaction 2: Needs X => Waits for X Process A Transaction 1: Waits for Transaction 3 to finish (see the last two paragraph below to specify the terms in more detail) => deadlock 

Это очень неудачная настройка, потому что MySQL не видит, что существует тупик (в трех транзакциях). Так что MySQL делает … ничего! Он просто ждет, так как он не знает, что делать. Он ждет, пока первый приобретенный замок не превысит тайм-аут (Process A Transaction 1: Locks X), затем он разблокирует Lock X, который открывает транзакцию 2 и т. Д.

Искусство состоит в том, чтобы выяснить, что (какой запрос) вызывает первый замок (Lock X). Вы сможете легко увидеть ( show engine innodb status ), что Transaction 3 ждет транзакции 2, но вы не увидите, какая транзакция транзакции 2 ждет (транзакция 1). MySQL не будет печатать какие-либо блокировки или запрос, связанные с транзакцией 1. Единственный намек будет заключаться в том, что в самом конце списка транзакций (из распечатки show engine innodb status ) вы увидите, что транзакция 1, по-видимому, ничего не делает (но на самом деле ждет для завершения транзакции 3).

Ниже описывается способ поиска того, какой SQL-запрос вызывает блокировку (блокировку X) для данной ожидающей транзакции. Tracking MySQL query history in long running transactions

Если вам интересно, что процесс и транзакция точно приведены в этом примере. Процесс является процессом PHP. Транзакция – транзакция, определенная innodb-trx-table . В моем случае у меня было два процесса PHP, в каждом из которых я начал транзакцию вручную. Интересная часть заключалась в том, что, хотя я начал одну транзакцию в процессе, MySQL использовал внутренне фактически две отдельные транзакции (я не знаю, почему, может быть, может объяснить какой-то MySQL-разработчик).

MySQL самостоятельно управляет своими собственными транзакциями и решил (в моем случае) использовать две транзакции для обработки всех запросов SQL, поступающих из процесса PHP (процесс A). Утверждение, что Transaction 1 ожидает завершения транзакции 3, является внутренней задачей MySQL. MySQL «знал» транзакцию 1, а транзакция 3 фактически была создана как часть одного запроса транзакции (из процесса A). Теперь вся транзакция была заблокирована, потому что транзакция 3 (подраздел «транзакция») была заблокирована. Поскольку «транзакция» не была способна завершить транзакцию 1 (также подчасти «транзакции»), была отмечена как не завершенная. Это то, что я имел в виду под термином «Транзакция 1 ждет завершения транзакции 3».

Большая проблема с этим исключением заключается в том, что он обычно не воспроизводится в тестовой среде, и мы не собираемся запускать статус двигателя innodb, когда это происходит на prod. Поэтому в одном из проектов я помещал приведенный ниже код в блок catch для этого исключения. Это помогло мне уловить статус двигателя, когда произошло исключение. Это очень помогло.

 Statement st = con.createStatement(); ResultSet rs = st.executeQuery("SHOW ENGINE INNODB STATUS"); while(rs.next()){ log.info(rs.getString(1)); log.info(rs.getString(2)); log.info(rs.getString(3)); } в Statement st = con.createStatement(); ResultSet rs = st.executeQuery("SHOW ENGINE INNODB STATUS"); while(rs.next()){ log.info(rs.getString(1)); log.info(rs.getString(2)); log.info(rs.getString(3)); } 

Взгляните на страницу руководства утилиты pt-deadlock-logger :

 brew install percona-toolkit pt-deadlock-logger --ask-pass server_name 

Он извлекает информацию из состояния engine innodb status упомянутого выше, а также может использоваться для создания daemon который запускается каждые 30 секунд.

Экстраполируя ответ Роландо выше, именно они блокируют ваш запрос:

 ---TRANSACTION 0 620783788, not started, process no 29956, OS thread id 1196472640 MySQL thread id 5341773, query id 189708353 10.64.89.143 viget 

Если вам нужно выполнить свой запрос и не можете дождаться, пока остальные будут запущены, уничтожьте их с помощью идентификатора streamа MySQL:

 kill 5341773 

^{(изнутри mysql, а не оболочки, очевидно)}

Вы должны найти идентификаторы streamов из:

 show engine innodb status\G 

и выяснить, какая из них блокирует базу данных.

Вы можете использовать:

 show full processlist 

в котором будут перечислены все соединения в MySQL и текущее состояние соединения, а также выполняемый запрос. Также есть более короткий вариант show processlist; который отображает усеченный запрос, а также статистику соединения.

Если вы используете JDBC, у вас есть опция
includeInnodbStatusInDeadlockExceptions = верно

https://dev.mysql.com/doc/connector-j/8.0/en/connector-j-reference-configuration-properties.html

Активируйте MySQL general.log (интенсивный диск) и используйте mysql_analyse_general_log.pl для извлечения длинных транзакций, например:

–min-duration = значение innodb_lock_wait_timeout

После этого отключите general.log.