torndb 导致 tornado 进程卡死问题

更新日期: 2015-12-12 阅读次数: 7589 分类: Tornado

具体表现

某个月黑风高的夜晚,突然服务器出现了久违的 502 维护页面。

  • Nginx 日志正常,能接收到请求,但是全部 502
  • 看了一下后台 tornado 的日志,发现所有进程都停止了响应, 卡在了某处.
23:03:10 request /
23:30:17 torndb:236 Error connecting to MySQL on x.x.x.x(remote ip):3306
	 ...
	 <PATH>/MySQLdb/connections.py
	 OperationalError: (2013, 'Lost connection to MySQL server during query')

tornado 进程被这条查询卡住了近半个小时。

然后,重启所有 tornado 进程,所有进程又卡在了数据库连接上。

而这个问题只有在 mysql 与 tornado 不在一台机器上时才会出现。

定位问题

归纳一下,在使用 python 操作 mysql 的时候,例如执行一个 select 语句, 在远端 mysql 接收到请求之后,并执行查询的过程中,但是没有返回结果的这段时间里,如果突然网络断开,这时候就会出现。

如何验证问题定位是准确的

模拟一个慢查询,然后在查询的过程中,kill 掉 mysql,看进程是否会卡住。

torndb 执行 sql 请求 SELECT sleep(20), 然后关闭 mysql,这时接口直接返回了,连异常都没报。

这里关闭 mysql 的方式不同,会用不同的返回: 使用 sudo killall -9 mysql 会立即报错

Lost connection to MySQL server during query

而使用 sudo service mysql stop 则会直接返回正确结果。

尝试不用 service 启动 mysql 进程,改用 sudo mysqld 启动,然后 kill 掉 mysql 进程,仍然立即报错。

忽略了一个问题,刚才一直在用本地 mysql 测试,如果使用非本机 mysql 测试呢?嘿嘿

使用我的开发机连接 VPS 上的 mysql 服务器,查询的过程中,断开本地网络,果然重现了。

如何更快的定位此类问题呢?

使用 strace 启动 tornado,以确认进程卡在了哪里

write(1, "start at: 2015-01-05 13:48:46.64"..., 37start at: 2015-01-05 13:48:46.644485) = 37
poll([{fd=3, events=POLLIN|POLLPRI}], 1, 0) = 0 (Timeout)

read(3,

可见是卡在了 read 操作上,由于本人对 C 以及 linux 系统接口属于白痴水平,只能

man read

可以看到

ssize_t read(int fd, void *buf, size_t count);

所以是卡在了对 file descriptor fd 3 的读取上。确认 fd 3 对应的文件信息

lsof -d 3 | grep python
python     2975 zhongwei    3u  IPv4   17920      0t0       TCP *:8888 (LISTEN)
ipython    2999 zhongwei    3u   REG   8,1    37888 118360140 /home/zhongwei/.ipython/profile_default/history.sqlite
python     8224 zhongwei    3u  IPv4   894837      0t0       TCP zhongwei-dev:35451->x.x.x.x:mysql (ESTABLISHED)

可见就是卡在了 mysql 的连接上。

疑问,如果不使用 strace,如何在保留现场的情况下知道卡在了哪里?

gdb -p 进程号

然后输入 bt

#0  0x00007f1b612cbdbd in read () at ../sysdeps/unix/syscall-template.S:81
#1  0x00007f1b5d932794 in vio_read_buff () from /usr/lib/x86_64-linux-gnu/libmysqlclient.so.18
#2  0x00007f1b5d9229d0 in ?? () from /usr/lib/x86_64-linux-gnu/libmysqlclient.so.18
#3  0x00007f1b5d92357d in my_net_read () from /usr/lib/x86_64-linux-gnu/libmysqlclient.so.18
#4  0x00007f1b5d91cbdc in cli_safe_read () from /usr/lib/x86_64-linux-gnu/libmysqlclient.so.18

但是这个唯一不方便的地方是,不能知道读取的 fd 具体是啥。

找到一个好方法

sudo strace -p <进程号>

可以看到对应的等待操作

Process <进程号> attached - interrupt to quit
recvfrom(5, 

问题产生的原因

在 torndb 与 mysql 建立 TCP 连接之后,如果出现网络断开问题,python client 是没有感知的。 至于为啥 client 端感知不到,这就要归咎于 TCP 的实现机制了,必须有一方主动发送关闭连接的信息,这个连接才会主动断开。

这个时候就只能依赖于系统的 tcp keepalive 探测机制来被动发现 TCP 连接已断开。

| 配置项 | 默认值 | 含义 | |--|--|--| | /proc/sys/net/ipv4/tcp_keepalive_time | 7200 | tcp开始进行keealive探测的秒数 | | /proc/sys/net/ipv4/tcp_keepalive_intvl | 75| 每次重试的间隔| | /proc/sys/net/ipv4/tcp_keepalive_probes | 9|探测失败时的重试次数 |

默认需要等待的时间是

7200 + 75 * 8 = 7875

约 2 个小时

解决方法

  • mysql read/write timeout
  • Nginx timeout 与 mysql read timeout 的一致性

read/write timeout 与 mysql client api 的版本有关系, 5.0.25, 5.1.12 版本以上才支持。

如何产看 mysql client api 的版本

mysql -V

显示我的 mysql client 版本为 5.1.61

从 torndb 的代码来看,并不支持 connect_timeout 之外的其他超时参数

def __init__(self, host, database, user=None, password=None,
    max_idle_time=7 * 3600, connect_timeout=0,
    time_zone="+0:00", charset = "utf8", sql_mode="TRADITIONAL"):

torndb 依赖于 MySQLdb 模块,目前使用的 MySQLdb 最新版本为 1.2.5, 已经支持读写 timeout。

但是对开发机上的 1.2.3 MySQLdb 升级时报错

sudo pip install MySQL-python --upgrade

EnvironmentError: mysql_config not found

安装依赖

sudo apt-get install libmysqld-dev

卸载重装

sudo apt-get remove --purge python-mysqldb 
sudo pip install MySQLdb-python

如何让 torndb 支持各种 timeout 参数? 先看一下 MySQLdb/_mysql.c 的代码

/* According to https://dev.mysql.com/doc/refman/5.1/en/mysql-options.html
   The MYSQL_OPT_READ_TIMEOUT apear in the version 5.1.12 */
#if MYSQL_VERSION_ID > 50112
#define HAVE_MYSQL_OPT_TIMEOUTS 1
#endif

于是把 torndb 修改了一下,对应的 pull request

MYSQL_OPT_WRITE_TIMEOUT MYSQL_OPT_READ_TIMEOUT 的区别是啥?

  • MYSQL_OPT_READ_TIMEOUT: Specifies the timeout in seconds for reading packets from server.
  • MYSQL_OPT_WRITE_TIMEOUT: Specifies the timeout in seconds for sending packets to server.

但是在生产环境测试时发现,超时时间是设置的超时值的3倍。 按照 MySQL 官网的说法, 这里 read 会重试两次,write 会重试一次,所以 read 会是3倍的超时时间,写会是两倍的超时时间。

反思

  • 看来 linux 上开发,无论使用什么语言,必须对 C 以及 linux 系统接口及工具熟悉
  • mysql 的 C API 手册必须读一遍, mysql_options

参考

爱评论不评论

近期节日

2019年11月20日 国际儿童日
2019年11月21日 世界问候日
2019年11月22日 小雪
2019年11月22日 感恩节
2019年11月29日 黑色星期五
2019年12月01日 世界艾滋病日
2019年12月03日 国际残疾人日
2019年12月07日 大雪
2019年12月09日 "一二九"运动纪念日
2019年12月09日 世界足球日
2019年12月10日 世界人权日
2019年12月12日 西安事变纪念日
查看更多节日