如何debugging在MySQL上超出locking等待超时？
在我的生产错误日志中偶尔会看到：
SQLSTATE [HY000]：一般错误：1205锁超时超时; 尝试重新启动事务
我知道当时哪个查询试图访问数据库，但是有什么方法可以找出哪个查询在那个时刻locking了？
什么使这个消失是交易的话。 通过声明显而易见，查询试图在一个或多个InnoDB表中至less更改一行。
既然你知道这个查询，那么所有被访问的表都可以作为罪魁祸首。
从那里，你应该可以运行SHOW ENGINE INNODB STATUS\G
您应该能够看到受影响的表（S）
你得到各种额外的locking和互斥信息。
以下是我的一个客户的样本：
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的locking等待超时值，默认值是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线程之一中提到的那样：有时locking表的进程显示为在进程列表中睡眠！ 我把我的头发撕掉，直到我杀死了所有在数据库中打开的睡眠线程（当时没有活动的线程）。 最终解锁表并让更新查询运行。
评论者说了类似于“有时MySQL线程locking表，然后睡觉，而它等待与非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读取视图”消息是否与冻结锁相关，但与其他活动事务不同，这个不会显示发出的查询，而是声明事务是“清理”，但具有多个行锁）
故事的寓意是，即使线程正在睡眠， 事务也可以是活动的。
由于MySQL受欢迎程度，难怪锁超时超时; 尝试重新启动事务exception在SO上得到如此多的关注。
您拥有的争夺越多，死锁的机会就越大，数据库引擎将通过暂停其中一个死锁事务来解决这个问题。 另外，修改（例如UPDATE或DELETE ）大量条目（如高性能Java持久性簿中所述的那样locking以避免脏写exception）的长时间运行的事务更可能与其他事务产生冲突。
尽pipeInnoDB MVCC，您仍然可以使用FOR UPDATE子句来请求显式locking 。 但是，与其他stream行的DB（Oracle，MSSQL，PostgreSQL，DB2）不同，MySQL 使用REPEATABLE_READ作为默认的隔离级别 。
现在，您获取的锁（通过修改行或使用显式locking）在当前正在运行的事务的持续时间内保持不变。 如果您想要解释一下REPEATABLE_READ和READ COMMITTED之间在locking方面的区别，请阅读Percona文章 。
在REPEATABLE READ中，交易期间获得的每个锁持续交易期间。
在READ COMMITTED中，不匹配扫描的锁在STATEMENT完成后被释放。
…
这意味着在READ COMMITTED中，一旦UPDATE语句完成，其他事务就可以自由更新它们将不能更新的行（在REPEATABLE READ中）。
这种更严格的隔离级别（ REPEATABLE_READ ， SERIALIZABLE ）越有可能发生死锁。 这不是一个“本身”的问题，这是一个权衡。
使用READ_COMMITED可以获得非常好的结果，因为在使用跨多个HTTP请求的逻辑事务时，需要应用程序级丢失更新预防 。 乐观locking方法的目标是即使在使用SERIALIZABLE隔离级别时可能发生的丢失更新 ，同时允许使用READ_COMMITED来减less锁争用。
为了logging，当发生死锁时，锁等待超时exception也会发生，而且MySQL无法检测到，所以它只是超时。 另一个原因可能是一个非常长的运行查询，这是更容易解决/修复，但是，我不会在这里描述这种情况。
如果在两个事务中“正确地”构造MySQL，通常能够处理死锁。 MySQL然后杀死/回滚拥有较less锁的一个事务（不太重要，因为它会影响较less的行），并让另一个完成。
现在假设有两个进程A和B以及三个事务：
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等。
艺术是找出（哪个查询）导致第一个锁（lockingX）。 您将可以轻松地看到（ show engine innodb status ）事务3等待事务2，但是您将看不到事务2正在等待的事务（事务1）。 MySQL不会打印与事务1相关的任何锁或查询。唯一的提示是在事务列表的底部（ show engine innodb status打印输出）的底部，你会看到事务1显然什么都不做（事实上，交易3完成）。
在这里描述了如何查找哪个SQL查询导致为正在等待的给定事务授予locking（lockingX）的技术。在此处描述Tracking MySQL query history in long running transactions
如果你想知道在这个例子中的过程和交易是什么。 这个过程是一个PHP过程。 事务是由innodb-trx-table定义的事务。 就我而言，我有两个PHP进程，每个都手动启动一个事务。 有趣的部分是，即使我在一个进程中开始了一个事务，MySQL实际上在内部使用了两个单独的事务（我不知道为什么，也许一些MySQL开发人员可以解释）。
MySQL在内部pipe理自己的事务，并决定（在我的情况下）使用两个事务来处理来自PHP进程（进程A）的所有SQL请求。 事务1正在等待事务3完成的声明是一个内部的MySQL事物。 MySQL“知道”事务1和事务3实际上是作为一个“事务”请求（来自进程A）的一部分实例化的。 现在整个“交易”被封锁了，因为交易3（“交易”的一个子部分）被封锁了。 由于“交易”不能完成交易1（也是“交易”的一个子部分）被标记为还没有完成。 这就是我所说的“交易1等待交易3完成”。
这个例外的一个大问题是，它通常在testing环境中不可重现，而且在产品发生的时候，我们并不会运行innodb引擎状态。 所以在其中的一个项目中，我把下面的代码放到catch块中，这个例外。 当发生exception时，这帮助我抓住引擎状态。 这帮助了很多。
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中提取信息，也可以用来创build一个每30秒运行一次的daemon 。
从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将它们closures：
kill 5341773
（从MySQL内部，而不是shell，显然）
您必须从以下位置find线程ID：
show engine innodb status\G
命令，并找出哪一个是阻止数据库。
您可以使用：
show full processlist
这将列出MySQL中的所有连接以及当前的连接状态以及正在执行的查询。 还有一个更短的变体show processlist; 其中显示截断的查询以及连接统计信息。
激活MySQL general.log（磁盘密集型）并使用mysql_analyse_general_log.pl提取长时间运行的事务，例如：
–min-duration =你的innodb_lock_wait_timeout值
之后禁用general.log。
