一次 MySQL 异常的排查： 1205 Lock wait timeout exceeded; try restarting transaction

[qce7]

一个同事反馈库存表编辑的时候超时，我去看 runtime 日志：

PDOException
SQLSTATE[HY000]: General error: 1205 Lock wait timeout exceeded; try restarting transaction

应该是数据被锁了，为了确认，去 MySQL 中查看 processlist 和 innodb 的状态

select * from INFORMATION_SCHEMA.PROCESSLIST where host like '{IP}%'

发现一条可疑记录

         ID: 1551472
         USER: root
         HOST: {IP}:54255
           DB: {DB_NAME}
      COMMAND: Sleep
         TIME: 255
        STATE:
         INFO: NULL
      TIME_MS: 255198.053
        STAGE: 0
    MAX_STAGE: 0
     PROGRESS: 0.000
  MEMORY_USED: 50208
EXAMINED_ROWS: 0
     QUERY_ID: 185761896

show engine innodb status;

发现后边

MySQL thread id 1, OS thread handle 0x7f356ac6b700, query id 0 Waiting for background binlog tasks
---TRANSACTION 12111541021, ACTIVE 564 sec
4 lock struct(s), heap size 1184, 1 row lock(s), undo log entries 3
MySQL thread id 1551472, OS thread handle 0x7f34e57ff700, query id 185761896 10.2.4.152 root cleaning up
Trx read view will not see trx with id >= 12111541022, sees < 12111541022
TABLE LOCK table `{DB_NAME}`.`{TABELE_A}` trx id 12111541021 lock mode IX
RECORD LOCKS space id 20359 page no 20 n bits 104 index `PRIMARY` of table `{DB_NAME}`.`{TABELE_A}` trx id 12111541021 lock_mode X locks rec but not gap
TABLE LOCK table `{DB_NAME}`.`{TABLE_B}` trx id 12111541021 lock mode IX
TABLE LOCK table `{DB_NAME}`.`{TABLE_C}` trx id 12111541021 lock mode IX

看执行时间和锁的语句就可以确定是这个 thread 了。

由于我们是用的 LNMP 架构，那问题几乎可以确定在 php-fpm 那里。

查看一下 php-fpm 的相关进程:

USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
root      4163  0.0  0.3 125680  6728 ?        Ss   15:13   0:00 php-fpm: master process (/usr/local/php7/etc/php-fpm.conf)
...
http      4164  0.0  0.7 130848 14164 ?        S    15:13   0:01 php-fpm: pool www
http      4173  0.1  0.9 135136 18588 ?        S    15:13   0:04 php-fpm: pool www
http      4174  0.1  0.9 135120 18588 ?        S    15:13   0:05 php-fpm: pool www
http      4175  0.0  0.9 135084 19068 ?        S    15:13   0:01 php-fpm: pool www
http      4176  0.0  0.7 130908 14396 ?        S    15:13   0:00 php-fpm: pool www
http      4177  0.0  0.7 130840 14364 ?        S    15:13   0:00 php-fpm: pool www
http      4178  0.3  0.9 134944 18368 ?        S    15:13   0:10 php-fpm: pool www
...
vagrant   5155  0.0  0.0 105948  1080 pts/0    S+   16:00   0:00 awk /php-fpm/ || NR == 1

这么多子进程，还没法确定是那个进程，还得看下端口占用

sudo lsof -i -P -n | awk '/php-fpm/ || NR==1'

注意 lsof 要加上 sudo，不然没有任何信息输出

COMMAND    PID       USER   FD   TYPE DEVICE SIZE/OFF NODE NAME
php-fpm   4175       http    6u  IPv4  16770      0t0  TCP 10.0.2.15:25155->{IP}:3306 (ESTABLISHED)
php-fpm   4175       http    9u  IPv4  16772      0t0  TCP 10.0.2.15:7730->{IP}:6332 (ESTABLISHED)
php-fpm   4175       http   10u  IPv4  16775      0t0  TCP 10.0.2.15:7731->{IP}:6332 (ESTABLISHED)
php-fpm   4175       http   12u  IPv4  16783      0t0  TCP 10.0.2.15:22581->{IP3}:80 (ESTABLISHED)

由此看出就是 4175 这个进程。

把它 kill 掉，果然行锁就被解除了。

但是，为什么这个进程会被挂起呢？

开启 xdebug 中的 trace。

// in php.ini
zend_extension=xdebug.so
xdebug.trace_output_dir="/tmp/xdebug"
xdebug.auto_trace=1

重新对问题接口请求，查看日志的最后几行：

    1.4633    9857208                               -> is_array() ****/common/extensions/xinge/XingeApp.php:1294
    1.4633    9857208                               -> http_build_query() ****/common/extensions/xinge/XingeApp.php:1294
    1.4633    9861680                               -> curl_init() ****/common/extensions/xinge/XingeApp.php:1329
    1.4633    9862592                               -> curl_setopt_array() ****/common/extensions/xinge/XingeApp.php:1331
    1.4633    9862592                               -> curl_exec() ****/common/extensions/xinge/XingeApp.php:1333

终于破案了，Xinge 推送的里面有个 curl 的请求没有设置超时时间，同时由于是开发环境，这台服务器的 php-fpm 也没有设置超时时间。

其实这个 bug 并不难找，顺藤摸瓜，高手可能就 10 分钟，但是我却用了一下午。 其中的坑：

1.废了好长的时间去想为什么 lsof 中 php-fpm 的网络端口和 mysql processlist 里边的不一样，找了半天的原因才明白，由于用了 vagrant，应该是 vagrant 里边的服务器连接 mysql 服务器的时候是用的宿主机的网卡，所以 mysql 显示的 ip 和端口都是宿主机的。

2.该服务器是一位前端童鞋的开发机，没有 xdebug，编译安装的时候遇到的坑，不知道什么时候 xdebug 要扔到 php 目录里边去编译了，README 里边没有说，后来在官网才看到此说明。

3.开启 xdebug auto_trace 搞了好久都没输出，最后发现该目录是 755 权限，+x 之后正常解决

给大家分享折腾一下午的收获，欢迎吐槽

[fzleee]

在需要锁记录的事务里面，尽量避免耗时的网络操作不是更好一点么。

[qce7]

@fzleee 还真是。。这个建议太犀利了，回头我吧这个推送请求放到异步队列里

[bwangel]

现在 Information Schema 中存在一个表 INNODB_TRX，可以查询到某个事务执行的 SQL 语句。感觉比看 InnoDB status 要舒服一些。

<script src="https://gist.github.com/bwangel23/f6bcdc508c4cc2b7e5b521210fbcfd39.js"></script>

上面的 SQL 是我从 《 MySQL 技术内幕》中学到的查询阻塞事务的方法，不过我本地测试的时候发现有时候 INNODB_LOCK_WAITS .blocking_query 这个字段可能为空，所以可以再 join 上 INNODB_TRX 表查询阻塞事务的执行 SQL。

[carlclone]

学到了