本周在公司专项排查一个问题,最终问题被解决了,自己也感觉收获颇丰,特此总结一下。
一、问题背景
公司产品有一个数据导出功能,该功能一直以来饱受诟病,客户经常反馈说导出不了数据,于是就让客户支持人员帮忙手动导数据。客户体验差不说,客户支持人员也是苦不堪言。
内部实现上,该数据导出功能是通过 Celery 异步任务的方式来处理的。如果是因为导出数据量太大,导致任务超时被中途停掉,倒还可以理解。但大部分情况是,即使是很少量的数据,也无法导出。
二、排查分析
1. 查看 Celery 错误日志
当数据导出不了的时候,查看 Celery 错误日志,一般都是这样的:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28
| [2016-11-15 14:17:09,478: ERROR/MainProcess] Exception during reset or similar Traceback (most recent call last): File "/data/app/eggs/SQLAlchemy-1.0.15-py2.7-linux-x86_64.egg/sqlalchemy/pool.py", line 636, in _finalize_fairy fairy._reset(pool) File "/data/app/eggs/SQLAlchemy-1.0.15-py2.7-linux-x86_64.egg/sqlalchemy/pool.py", line 774, in _reset self._reset_agent.rollback() File "/data/app/eggs/SQLAlchemy-1.0.15-py2.7-linux-x86_64.egg/sqlalchemy/engine/base.py", line 1563, in rollback self._do_rollback() File "/data/app/eggs/SQLAlchemy-1.0.15-py2.7-linux-x86_64.egg/sqlalchemy/engine/base.py", line 1601, in _do_rollback self.connection._rollback_impl() File "/data/app/eggs/SQLAlchemy-1.0.15-py2.7-linux-x86_64.egg/sqlalchemy/engine/base.py", line 670, in _rollback_impl self._handle_dbapi_exception(e, None, None, None, None) File "/data/app/eggs/SQLAlchemy-1.0.15-py2.7-linux-x86_64.egg/sqlalchemy/engine/base.py", line 1341, in _handle_dbapi_exception exc_info File "/data/app/eggs/SQLAlchemy-1.0.15-py2.7-linux-x86_64.egg/sqlalchemy/util/compat.py", line 202, in raise_from_cause reraise(type(exception), exception, tb=exc_tb, cause=cause) File "/data/app/eggs/SQLAlchemy-1.0.15-py2.7-linux-x86_64.egg/sqlalchemy/engine/base.py", line 668, in _rollback_impl self.engine.dialect.do_rollback(self.connection) File "/data/app/eggs/SQLAlchemy-1.0.15-py2.7-linux-x86_64.egg/sqlalchemy/dialects/mysql/base.py", line 2542, in do_rollback dbapi_connection.rollback() File "/data/app/eggs/PyMySQL-0.7.6-py2.7.egg/pymysql/connections.py", line 772, in rollback self._execute_command(COMMAND.COM_QUERY, "ROLLBACK") File "/data/app/eggs/PyMySQL-0.7.6-py2.7.egg/pymysql/connections.py", line 1055, in _execute_command self._write_bytes(packet) File "/data/app/eggs/PyMySQL-0.7.6-py2.7.egg/pymysql/connections.py", line 1007, in _write_bytes raise err.OperationalError(2006, "MySQL server has gone away (%r)" % (e,)) OperationalError: (pymysql.err.OperationalError) (2006, "MySQL server has gone away (error(32, 'Broken pipe'))") [2016-11-15 14:17:09,478: ERROR/MainProcess] Hard time limit (1800s) exceeded for app.jobs.download.download_data[63c0d55e-76a5-42ef-8d65-7bd432bc0877]
|
分析上述日志:
似乎是 MySQL 报错了,但是 “MySQL server has gone away” 通常表明:client 端连接超时了,然后 server 端受不了了,所以强制 kill 掉了数据库连接(参考 Error 2006: MySQL server has gone away)
导出任务执行超过了 1800 秒(30 分钟)!!然后被强制停掉了。。。
所有矛头都指向了一点:导出任务执行过慢。
2. 加日志作性能分析
导出任务执行过慢,最直接的判断就是:执行过程中有些步骤耗时过长。没啥好说的,加日志分别计算下每个步骤的执行时间呗。
这里特别提一点:对于使用了 SQLAlchemy 的代码,在对数据库查询作性能分析时,不必为每个查询语句都加日志,相关技巧请参考这篇官方文档 How can I profile a SQLAlchemy powered application?
加上日志后,(为了让修改后的代码生效)重启 celery-download,然后观察日志。然而。。。并没有发现异常,每个步骤的执行时间看起来都很合理。。。
3. 由 CPU 占用率引发的思考
事实证明,上面的排查手段并不奏效。重新整理思路后,决定不再过早地作判断,而是先搜集更多的有用信息。
很自然地,这一次注意到了 celery-download 的 CPU 占用率。一个 top 命令,发现 celery-download 的 CPU 占用率竟然接近 100%:
1 2
| PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 28912 tester 20 0 477576 116500 14600 S 99.3 8.5 71:07.62 [celeryd: celery_download...]
|
惊讶地同时,似乎也能解释得通了:这么高的 CPU 占用率,一定是哪里出现了死循环,导致整个 celery-download 进程几乎瘫痪,进而无法正常工作。
除此以外,经过一些尝试和观察,还注意到一个现象:如果重启 celery-download,CPU 占用率会瞬间降下来,并且维持一段时间的正常值,然后过一会儿 CPU 占用率又会飙到很高。这也解释了在上一步 加日志作性能分析
的时候,为什么没有发现问题了:刚刚重启后的一段时间内,一切都是正常的。
但是为何会出现上述这些现象,对此我毫无头绪。请教 Google 大神后,意外地搜到了这个 celery:issue#1845。仔细看完以后,简直可以用 “醍醐灌顶” 来形容。
4. 顺藤摸瓜找元凶
按照 celery:issue#1845 中给出的思路,进行一一排查:
1)strace 跟踪 celery-download 进程
1 2 3 4 5 6 7 8 9 10 11
| $ strace -p 28912 ... epoll_wait(11, {{EPOLLIN|EPOLLOUT, {u32=30, u64=21474836725}}}, 130, 1) = 1 clock_gettime(CLOCK_MONOTONIC, {29956630, 774274775}) = 0 clock_gettime(CLOCK_MONOTONIC, {29956630, 774404883}) = 0 clock_gettime(CLOCK_MONOTONIC, {29956630, 774497018}) = 0 epoll_wait(11, {{EPOLLIN|EPOLLOUT, {u32=30, u64=21474836725}}}, 130, 1) = 1 clock_gettime(CLOCK_MONOTONIC, {29956630, 774643990}) = 0 clock_gettime(CLOCK_MONOTONIC, {29956630, 774770274}) = 0 clock_gettime(CLOCK_MONOTONIC, {29956630, 774861865}) = 0 ...
|
可以看出,celery-download 进程一直在重复调用 epoll_wait 和 clock_gettime。参考 Linux 手册,我们知道 epoll_wait 返回 1 表示:有 1 个 fd(文件描述符)可用于读写。在这里,这个导致 epoll_wait 返回的 fd 就是 30。
再来看看这个 fd 有什么特别之处:
1 2
| $ lsof -d 30|grep 28912 [celeryd: 28912 tester 30u IPv4 1026883657 0t0 TCP xx-celery-app0:3759->ip-10-10-10-10.xx:6379 (CLOSE_WAIT)
|
很明显地,”xx-celery-app0:3759->ip-10-10-10-10.xx:6379” 是一个指向 Redis 的 socket 连接,而且这个连接处于 CLOSE_WAIT 状态!正是这个 CLOSE_WAIT 状态的 Redis 连接,导致 epoll_wait 总是会立即返回,从而让 celery-download 进程陷入了不断调用 epoll_wait 的死循环中!!
而对于 “celery-download 重启后,CPU 占用率会恢复正常” 的现象,可以这样解释:因为进程结束时,会关闭它用到的所有文件描述符(包括 CLOSE_WAIT 连接);而对于新启动的进程,运行一段时间后,才会莫名其妙地产生 CLOSE_WAIT 连接 :-(
2)分析 CLOSE_WAIT 连接
那么上述 Redis 连接为什么会处于 CLOSE_WAIT 状态呢?
我们知道,Redis 有个 timeout 参数,参考 Redis 配置文件:
1 2
| # Close the connection after a client is idle for N seconds (0 to disable) timeout 0
|
如果 timeout 不为 0,当 client 端连接的空闲时间超过了 timeout 秒,server 端会主动关闭该连接(更多说明参考 Client timeouts)。这种 “server 端主动关闭超时的 client 端连接” 的机制,与之前提到的 MySQL 的机制,其实是类似的。
当然这里的 timeout 0
是官方的参考值,”ip-10-10-10-10.xx” 对应的 Redis 实例(注意:与 celery:issue#1845 中描述的情况不同,这个 Redis 实例不是用作 Celery 的 broker 或 result backend,而是用作普通的缓存),实际的 timeout 配置为 1200(秒)。
于是,我们可以大胆猜测:fd 为 30 的那个 Redis 连接,因为空闲时间超过了 1200 秒,进而被 Redis 的 server 端主动关闭了(发送 FIN 报文),但是因为 client 端没有正确关闭(即被动关闭的一方,也许响应了 ACK 报文,但是没有发送 FIN 报文),导致该连接一直处于 CLOSE_WAIT 状态。
到这里,尚存两点疑惑:
- 为什么 Redis 连接超过了 1200 秒,client 端还不主动关闭,非要等到 server 端关闭呢?
- 为什么 server 端关闭后,client 端不正确响应呢?
3)redis-py 的连接池机制
考虑到使用的 Redis 客户端库是 redis-py ,参考文档发现 redis-py 内部使用了 连接池机制,因此:一个连接用完后,不会被立即关闭,而会被释放到连接池中,等待下次取用。
查看 redis-py 的源码:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22
|
class StrictRedis(object):
...
def execute_command(self, *args, **options): "Execute a command and return a parsed response" pool = self.connection_pool command_name = args[0] connection = pool.get_connection(command_name, **options) try: connection.send_command(*args) return self.parse_response(connection, command_name, **options) except (ConnectionError, TimeoutError) as e: connection.disconnect() if not connection.retry_on_timeout and isinstance(e, TimeoutError): raise connection.send_command(*args) return self.parse_response(connection, command_name, **options) finally: pool.release(connection)
|
结合 redis-py:issue#306 的说法,可以进一步得知:redis-py 对于关闭连接的处理是被动的,只会在下一次使用该连接的时候,检测该连接的可用性;如果使用连接时,遇到报错 ConnectionError 或 TimeoutError,才会调用 disconnect() 关闭该连接。
综上所述,前面提到的两点疑惑,具体来讲,可以归结为一点:
- 为什么 fd 为 30 的 Redis 连接,在 redis-py 中没有被再次使用过,进而导致 server 端关闭该连接后,redis-py 不能正确关闭该连接?
遗憾地是,目前为止,这个问题还没能得到解答。(因为 Celery 的并发使用了 gevent,所以怀疑过是 gevent 魔幻的 patch 处理
跟 redis-py 的连接池机制
产生了化学反应,然而这种猜测暂时无法得到验证。)
三、归纳总结
前面长篇大论地说了很多,关于这个问题,总结起来其实只有三点:
1. 根本原因
celery-download 进程,运行一段时间后,产生了处于 CLOSE_WAIT 状态的连接,这种连接会让系统调用 epoll_wait 立即返回,从而让进程陷入不断调用 epoll_wait 的死循环中,进而导致该进程无法正常工作。
2. 解决办法
将 Redis 的 timeout 配置修改为 0(即禁止 server 端主动关闭超时的 client 端连接),从源头上避免 CLOSE_WAIT 连接的产生。
3. 遗留问题
celery 3.1.24 + gevent 1.2a1 + redis-py 2.10.5 的组合,会出现这种问题:redis-py 的连接池机制无法复用某些连接,进而导致这些连接处于失控状态。
四、一些技巧
1. 问题复现
对于上述 epoll 与 CLOSE_WAIT 连接
的问题,用这个 简化示例 可以完美复现。
server 端的代码如下:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24
|
import SocketServer import time
HOST = '127.0.0.1' PORT = 9999
class ReusableTCPServer(SocketServer.TCPServer): allow_reuse_address = True
class ServeAndCloseHandler(SocketServer.BaseRequestHandler): """ Sends some data and then closes, to test epoll behavior against. """
def handle(self): for i in range(3): self.request.sendall('data %d\n' % i) time.sleep(.5)
if __name__ == '__main__': server = ReusableTCPServer((HOST, PORT), ServeAndCloseHandler) server.serve_forever()
|
client 端的代码如下:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19
|
import select import socket
HOST = '127.0.0.1' PORT = 9999
def main(): s = socket.socket() s.connect((HOST, PORT)) epoll = select.epoll() epoll.register(s, select.POLLIN) while True: epoll.poll() data = s.recv(256)
if __name__ == '__main__': exit(main())
|
复现步骤提示:
- 启动 server 端(python server.py)
- 启动 client 端(python client.py)
- 观察 client 端进程的 CPU 占用率(top)
- 跟踪 client 端进程的执行情况(strace)
- 观察 client 端进程的 CLOSE_WAIT 连接(lsof)
2. 关闭 CLOSE_WAIT 连接
我们知道,重启进程可以去掉 CLOSE_WAIT 连接。但是重启进程毕竟动作太大,有没有办法在进程运行的同时,去掉该进程中产生的 CLOSE_WAIT 连接呢?
答案是肯定的,借助 gdb 就可以做到。继续上面的例子,假设进程号为 28912、CLOSE_WAIT 连接的 fd 为 30,可以使用以下命令:
1
| $ gdb -p 28912 -ex 'p close(30)' -ex 'set confirm off' -ex 'quit'
|