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

一个同事反馈库存表编辑的时候超时，我去看 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 之后正常解决

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