如何在MySQL上调试锁等待超时问题？

Question

如何在MySQL上调试锁等待超时问题？

mysqldebuggingtransactionsinnodbacid

308

在我的生产错误日志中，我偶尔会看到以下信息：

SQLSTATE[HY000]：一般性错误：1205 锁等待超时；请尝试重新启动事务

我知道哪个查询正在尝试访问数据库，但是否有办法找出那个特定时刻拥有锁的查询呢？

- Matt McCormick

1

我强烈建议每个人尝试一下Eirik的答案。 - kommradHomer

可能是重复的问题：如何克服从表中获取记录锁定失败的问题。 - Max Alexander Hanna

@kommradHomer 他的回答在哪里？ - Volatil3

@Volatil3更改了他的名字。这是答案https://dev59.com/1m025IYBdhLWcg3wclm-#20521293。 - kommradHomer

12个回答

112

正如一位在众多SO线程中提到的人所说：有时锁定表的进程在进程列表中显示为睡眠状态！我一直非常苦恼，直到我杀死了与问题数据库中打开的所有睡眠线程（当时没有任何活动线程），这最终解锁了表并让更新查询运行。

评论者说过类似于“有时MySQL线程会锁定一个表，然后进入睡眠状态，等待非MySQL相关事件发生。”

在重新检查show engine innodb status日志（一旦我追踪到负责该锁的客户端）后，我注意到受困的线程在交易列表的底部列出，位于即将因冻结锁而出错的活动查询之下：

------------------
---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 read view”消息是否与锁定有关，但与其他活动事务不同，该事务未显示出发出的查询，而是声称该事务正在“清理”，但具有多个行锁）

故事的寓意是，即使线程处于睡眠状态，事务仍然可以处于活动状态。

- Eric L.

8

我不能说你救了我的命，但你确实让我心境平静了。读完你的回答，我发现有一个可怕的进程一直在运行3260秒，但却没有显示在任何地方。杀掉它之后，我的所有问题都得到了解决！ - kommradHomer

这是我的问题。一个休眠事务，持续时间为20,000秒，阻止了Rails应用程序中的Delayed Job正常运行。感谢@Eirik。 - bigtex777

2

有没有想法为什么休眠的事务不会被终止？比如，是否可以设置一个事务必须在规定时间内完成的超时时间？ - patrickdavey

3

在搜索锁定事务时可能有用的其他命令是：show processlist;，它可以显示当前正在执行的所有进程的详尽列表，这很好因为它是show engine innodb status\g的简化版本。此外，如果您的数据库位于Amazon RDS实例上，则可以使用CALL mysql.rds_kill(<thread_id>); 来杀死线程。我认为它具有更高的权限，因为它允许我杀死比普通的kill <thread_id>;更多的进程-请注意，这些应该在MySQL CLI中运行。 - nickang

1

有人有相關來源嗎？或許是一個文件頁面，說明鎖定是在 COMMIT 階段之前放置的？我找不到任何東西，盡管看到這個問題，並且通過殺死持有鎖的睡眠線程來解決它。 - Erin Schoonover

显示剩余3条评论

47

争用（contention）越多，死锁的机会就越大，数据库引擎将通过超时来解决其中一个被死锁的事务。

此外，长时间运行的事务（已修改了大量条目的事务，例如UPDATE或DELETE）更有可能与其他事务产生冲突。

虽然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），死锁的机会就越大。这本身不是问题，而是一个权衡之间的折衷。

使用READ_COMMITTED可以获得非常好的结果，尤其是当使用跨多个HTTP请求的逻辑事务时需要应用程序级别的“丢失更新”预防措施。乐观锁定方法针对可能发生的“丢失更新”进行了优化处理，即使您使用SERIALIZABLE隔离级别，也能减少锁争用并允许您使用READ_COMMITTED。

- Vlad Mihalcea

8

锁等待超时和死锁不是同一概念吗？比如，如果一个线程由于合法原因持有锁60秒钟，则会出现锁等待超时。但如果真的发生死锁，MySQL会立即检测并终止事务，这与锁等待超时无关，这是不是正确的？ - ColinM

1

你是正确的。数据库在超时后检测到死锁并杀死一个等待进程，因此一个事务获胜而另一个失败。但是，持有锁的时间越长，应用程序的可扩展性就越低。即使您没有遇到死锁，您仍会增加应用程序运行时行为的串行化部分。 - Vlad Mihalcea

23

值得一提的是，在出现死锁时，MySQL也会发生锁等待超时异常，因为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无法看到死锁（跨越3个事务）。所以MySQL所做的就是......什么都不做！它只是等待，因为它不知道该怎么做。它会等待直到第一个获得的锁超时（A事务1：锁定X），然后这将解除锁定X，进而释放事务2等。

技巧就在于找出是哪个查询导致了第一个锁（锁定X）。你可以轻松地看到（show engine innodb status）事务3正在等待事务2，但你看不到事务2在等待哪个事务（事务1）。MySQL不会打印任何与事务1关联的锁或查询。唯一的提示是，在事务列表的最底部（show engine innodb status输出的），您将看到事务1似乎什么也没做（但实际上在等待事务3完成）。

如何找出导致给定事务被授予锁定（锁定X）的SQL查询的技术在此处描述：在长时间运行的事务中跟踪MySQL查询历史记录

如果您想知道示例中的过程和事务是什么。进程是一个PHP进程。事务是由innodb-trx-table定义的事务。在我的情况下，我有两个PHP进程，在每个进程中我手动启动了一个事务。有趣的部分是，即使我在一个进程中启动了一个事务，MySQL内部实际上使用了两个单独的事务（我不知道为什么，也许某个MySQL开发人员可以解释）。

MySQL在内部管理其自己的事务，并决定（在我的情况下）使用两个事务来处理来自PHP进程（进程A）的所有SQL请求。事务1正在等待事务3完成是MySQL的内部事情。MySQL“知道”事务1和事务3实际上是作为一个“事务”请求的一部分实例化的（来自进程A）。现在整个“事务”被阻塞了，因为事务3（“事务”的子部分）被阻塞了。因为“事务”无法完成，所以事务1（“事务”的另一个子部分）也被标记为未完成。这就是我所说的“事务1正在等待事务3完成”的含义。

- Tomas Bilka

20

这个异常的一个大问题是它通常在测试环境下无法重现，而当它在生产环境下发生时我们不在场来运行innodb engine status。因此，在其中一个项目中，我把下面的代码放到了针对这个异常的catch块中。这帮助我捕获了异常发生时的engine状态。这真的很有帮助。

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));
}

- Maruthi

15

这是我最终为了找出导致锁定超时问题的“其他查询”而必须执行的操作。在应用程序代码中，我们在专门的线程上跟踪所有挂起的数据库调用。如果任何DB调用时间超过N秒（对我们来说是30秒），我们会记录日志：

-- Pending InnoDB transactions
SELECT * FROM information_schema.innodb_trx ORDER BY trx_started; 

-- Optionally, log what transaction holds what locks
SELECT * FROM information_schema.innodb_locks;

通过以上方法，我们能够准确定位导致死锁的并发查询。在我的案例中，它们是像 INSERT ... SELECT 这样的语句，与普通的 SELECT 不同，它会锁定底层行。您可以重新组织代码或使用不同的事务隔离级别，例如读未提交。

祝好运！

- Slawomir

12

请查看pt-deadlock-logger工具的手册页面：

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

它从上面提到的engine innodb status中提取信息，还可以用于创建一个每30秒运行一次的daemon。

- Andrei Sura

3

这个工具现在已成为Percona工具包的一部分。 - Brad Mace

锁等待超时与死锁不同，特别是InnoDB不会显示任何关于它们的信息，因为它们不是检测到的死锁，所以我认为pt-deadlock-logger没有任何帮助。 - Jay Paroline

锁定超时和死锁是相关的 - 请参见https://dev.mysql.com/doc/refman/5.7/en/innodb-deadlock-detection.html。 - Andrei Sura

慢查询日志可能会有所帮助，Percona还维护了他们工具包中的pt-query-digest程序，可以为您总结日志。 - Steen Schütt

12

您可以使用：

show full processlist

使用show full processlist;命令可以列出MySQL中所有的连接及其当前状态，还会显示正在执行的查询语句。也可以使用较短的show processlist;命令，它会显示缩略的查询语句以及连接统计信息。

- Gerrit Brink

12

根据Rolando上面的回答推断，正是这些东西阻止了您的查询：

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

如果您需要执行查询，并且不能等待其他查询运行完成，请使用MySQL线程ID终止它们：

kill 5341773 <replace with your thread id>

^{（显然是在 mysql 中，而不是在 shell 中）。}

您需要从中找到线程 ID：

show engine innodb status\G

执行指令，并找出哪个正在阻塞数据库。

- Ellert van Koperen

1

你怎么知道它是 5341773？我看不出来它与其他的有什么区别。 - Wodin

不，那个threadID可能不是那个问题的原因，它只是一个例子。你需要从“show engine innodb status\G”命令中找到线程ID，并确定哪一个正在阻塞数据库。 - Ellert van Koperen

1

谢谢。换句话说，没有办法在不逐个杀死它们的情况下确定它是哪一个？ - Wodin

在交易列表中，您可以看到哪些正在运行以及持续时间。因此，没有必要一个个地终止它们，该列表通常会让您对正在发生的情况有很好的了解。 - Ellert van Koperen

3

如果您正在使用JDBC，则有以下选项：includeInnodbStatusInDeadlockExceptions=true。

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

- th3sly

网页内容由stack overflow 提供, 点击上面的

可以查看英文原文，
原文链接

- RolandoMySQLDBA · Accepted Answer

可以看到的是事务这个词。根据该语句，查询试图更改一个或多个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_lock_wait_timeout 的值来增加 InnoDB 的锁等待超时时间，默认为 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;

接着您的查询