背景：SQL 工单应用基于 tornado 框架实现，其中实现多个接口，包括语法校验接口，其中语法校验基于开源项目 goInception 实现。对于超长 SQL 或多实例的场景，经常出现语法校验超时的问题，原因是接口阻塞，IO 操作导致服务 block。
需求：改造接口实现，从同步阻塞修改为异步非阻塞，缓解语法校验超时的问题。
当前实现
语法校验接口
class StartSyncCheckHandler(tornado.web.RequestHandler):
def post(self):
...
return_data = mysql_check(job_option)
self.finish(return_data)
接口中调用 goinception 实现语法校验，goinception 使用的主要流程如下所示。
conn = self._get_inception_server_connection()
cursor = conn.cursor()
cursor.execute(self._get_inception_check_statement())
query_result = cursor.fetchall()
cursor.close()
由于 goinception 支持使用 MySQL 客户端连接，因此和 MySQL 的使用方式相同，主要包括：
- 创建连接
- 创建 cursor
- 提交校验
- 获取校验结果
使用 pymysql 创建连接，其中指定的 goinception 服务的 IP 和端口。
def _get_inception_server_connection():
return pymysql.connect(
host=GoInceptionServerConfig.mysql_ip,
user=GoInceptionServerConfig.MySQL_User,
passwd=GoInceptionServerConfig.MySQL_Password,
port=GoInceptionServerConfig.MySQL_Port,
charset=GoInceptionServerConfig.MySQL_Charset,
db=GoInceptionServerConfig.Database_Name
)
执行校验前生成提交给 goinception 的审核语句。
def _get_inception_check_statement(self):
"""
获取MySQL Inception使用的检查语句
:return:
"""
backup_option = "--execute=0;--backup=0"
run_option = "--check=1"
inception_statement = """/*--user={inception_user};--password={inception_password};\
--host={inception_host};--port={inception_port};{run_option};{backup_option};*/
inception_magic_start;
{sql_script}
inception_magic_commit;
""".format(
inception_user=self.mysql_user,
inception_password=self.mysql_password,
inception_host=self.mysql_ip,
inception_port=self.mysql_port,
run_option=run_option,
backup_option=backup_option,
sql_script=self.full_sql_script
)
return inception_statement
其中：
- 要求使用/* */将提交的信息括起来，其中每个参数通过分号分隔，包括要审核或执行的语句，包括use database语句也要加分号，这一点与 MySQL 客户端不同；
- 参数中的 IP 和端口是要校验的 SQL 对应的数据库；
- 指定--check=1;--execute=0，表示使用审核，不使用执行；
- goinception 支持语句块的审核，要求通过执行接口将要审核的 SQL 一次性提交，内部拆分后一条条审核。其中inception_magic_start;作为语句块的开始，inception_magic_start;作为语句块的结束。
多进程启动
tornado 默认使用单进程启动，因此首先改用多进程启动，具体实现是在启动时指定进程数。
tornado.options.parse_command_line()
app = Application()
http_server = tornado.httpserver.HTTPServer(app)
port = options.get("port", 8001)
http_server.listen(port, "0.0.0.0")
logging.warning("Server is running at http://0.0.0.0:%s" % port)
tornado.ioloop.IOLoop.instance().start()
# 多进程启动
# fork not available on windows。在windows上启本动服务需注释掉下面这行
http_server.start(8) # Forks multiple sub-processes
但是很快就发现了这种实现的缺点。主要包括：
- 并发数有上限，超过进程数后依然会发生阻塞等待，比如分库分表语法校验；
- 多个接口之间相互影响，当其他比较慢的接口用完了进程数，单实例的语法校验也会发生阻塞等待。
下面是两个案例的具体介绍。
案例1：并发数超过上限后语法校验慢
时间：2023-09-05 10:28:37
现象：分库分表语法校验超时，16 个实例，每个实例 4 个 database，每个 database 256 个表，一共 16,384 个表。
日志
其中：
- 一批接收并处理 8 个请求，每个请求的执行用时在 4s 左右；
- 每当一个请求返回后接收并处理下一个请求。
监控显示接口的 TP99 达到 9s，是接口实际执行用时的两倍左右。
监控显示 SQL 工单应用服务器 CPU 打满，持续时间 30s 左右。
案例 2：其他接口慢导致执行接口调用慢，如果调用语法校验，同样也会慢
时间：20230802 20:02
现象：执行接口调用慢，判断原因是空间检测进程占用进程所致。
监控显示同一时间空间检测接口的 TP99 超过 10s。
执行接口正常情况下接口调用很快，主要是执行一条 update SQL。查看执行接口的日志，其中关键字 'xbp_id': 6044322 表示单号。
root@sql-inception-c3acb574:~# head 6044322.log
2023-08-02 20:01:12,807 [MainThread:140461759665984] [sql] [start_execute_job:post:44] [INFO]- request_body_dict: {'job_uuid': '28182d96-905e-4807-aa4d-134f840cfe86', 'execute_method': 1, 'xbp_id': 6044322}
2023-08-02 20:01:12,807 [MainThread:140461759665984] [sql] [start_execute_job:post:50] [WARNING]- job_uuid=28182d96-905e-4807-aa4d-134f840cfe86, xbp_id=6044322
2023-08-02 20:01:12,888 [MainThread:140461759665984] [sql] [start_execute_job:post:66] [INFO]- return_data={'code': 0, 'message': 'start execute job success'}
工单 6044322 中有 37 个实例，调用执行接口 37 次，全部日志显示执行接口调用的时间相差 20s，原因是接口阻塞。
root@sql-inception-c3acb574:~# cat /export/Logs/sql.log | grep "start_execute_job:post:44" | grep 6044322 | awk '{print $2}'
20:01:12,807
20:01:12,890
...
20:01:37,194
20:01:37,275
...
20:01:39,363
20:01:39,402
可以对比另一个工单 6051798 中有 64 个实例，调用执行接口 64 次，全部日志显示执行接口调用的时间相差 0.2s。
root@sql-inception-c3acb574:~# cat /export/Logs/sql.log | grep "start_execute_job:post:44" | grep 6051798 | awk '{print $2}'
13:36:31,203
13:36:31,203
...
13:36:31,398
13:36:31,398
显然，对于接口阻塞的问题，简单实用多进程无法解决该问题，因此下面测试将接口改为异步非阻塞模式。
测试
准备
接口实现，其中调用 time.sleep(2) 模拟阻塞。
import datetime
import json
import time
import tornado.web
class AsyncHandler(tornado.web.RequestHandler):
def post(self):
data = json.loads(self.request.body)
number = data.get("number")
receive_time = datetime.datetime.now()
print("=== receive number={} in {}".format(number, receive_time))
print("==== {} enter ====".format(number))
time.sleep(2)
data = {
"code": 0
}
print("==== {} exit ====".format(number))
self.finish(data)
接口调用，其中使用线程池并发调用接口测试是否阻塞。
#!/usr/bin/env python
# -*- coding: utf-8 -*-
import datetime
import json
import requests
from common_helper.thread_pool import ThreadPool
def call_api(args):
db_number = args[0] + 1
print("send number={} in {}".format(db_number, datetime.datetime.now()))
api = "async/"
body = {
"number": db_number
}
result = send_request(api, body=body)
return result
def send_request(api, body):
domain = "http://127.0.0.1:8000/"# 调用多接口时便于区分环境
url = domain + api
headers = {
'content-type': "application/json",
}
result = requests.post(url=url, data=json.dumps(body), headers=headers)
return result.content
def main():
start_time = datetime.datetime.now()
print(start_time)
param_list = range(3)
pool = ThreadPool(call_api, param_list)
res_list = pool.run()
print(res_list)
end_time = datetime.datetime.now()
print(end_time)
use_time = end_time - start_time
print("Use time={:.2f} seconds".format(use_time.total_seconds()))
if __name__ == '__main__':
main()
阻塞
服务端日志
=== receive number=2 in2025-02-0920:03:15.001429
==== 2 enter ====
==== 2 exit ====
=== receive number=1in2025-02-0920:03:17.002924
==== 1 enter ====
==== 1 exit ====
=== receive number=3in2025-02-0920:03:19.008361
==== 3 enter ====
==== 3 exit ====
其中：
- 每次调用返回后执行下一次调用，表明接口阻塞；
- 显示 15、17、19 秒分别接收到请求，每个相差 2 秒。
客户端日志
2025-02-0920:03:14.989916
send number=1in2025-02-0920:03:14.990300
send number=2in2025-02-0920:03:14.990630
send number=3in2025-02-0920:03:14.990811
[b'{"code": 0}', b'{"code": 0}', b'{"code": 0}']
2025-02-0920:03:21.012274
Use time=6.02 seconds
其中：
- 并发请求同时发送，时间都是 14 秒，这里可以留一个问题，客户端发送请求但是服务端阻塞未处理时请求保存在哪里？
- 接口的 3 次调用总用时 6s，每次请求分别用时 2、4、6 秒。
接下来分别测试通过多种方法将阻塞接口修改为非阻塞。
async + await
将代码中的阻塞方法 time.sleep 修改为非阻塞方法 tornado.gen.sleep。
在 Tornado 中，tornado.gen.sleep(2) 是一个协程，它会暂停当前协程的执行，等待指定的时间（在本例中是 2 秒）后再恢复执行。为了使用这个协程，我们需要在调用它的函数前面加上 async def 关键字，并在调用 tornado.gen.sleep(2) 时使用 await 关键字。
async def post(self):
...
# time.sleep(2)
await tornado.gen.sleep(2)
...
# self.finish(data) # Coroutine 'finish' is not awaited
await self.finish(data)
1.2.3.4.5.6.7.
服务端日志显示接口处理过程中可以正常接收请求。
=== receive number=2 in2025-02-0920:28:59.343644
==== 2 enter ====
=== receive number=1in2025-02-0920:28:59.343680
==== 1 enter ====
=== receive number=3in2025-02-0920:28:59.343702
==== 3 enter ====
==== 2 exit ====
==== 1 exit ====
==== 3 exit ====
客户端日志
2025-02-0920:28:59.332715
send number=1in2025-02-0920:28:59.333061
send number=2in2025-02-0920:28:59.333485
send number=3in2025-02-0920:28:59.333753
[b'{"code": 0}', b'{"code": 0}', b'{"code": 0}']
2025-02-0920:29:01.346989
Use time=2.01 seconds
测试显示通过将阻塞方法 time.sleep 修改为非阻塞方法 tornado.gen.sleep 可以实现非阻塞。
tornado 中可以使用 gen.coroutine 装饰器实现异步，用于将生成器函数转换成协程，其中使用 yield 关键字来暂停和恢复执行。
import tornado.web
import tornado.gen
class AsyncHandler(tornado.web.RequestHandler):
@tornado.gen.coroutine # 异步、协程处理；增加并发量
def post(self):
...
# time.sleep(2)
yield tornado.gen.sleep(2)
...
self.finish(data)
其中：
- 用 tornado.gen.sleep 替换 time.sleep，fininsh 方法前不需要加 await，这种异步的实现可以像同步函数一样编写，便于理解与维护。
服务端日志
=== receive number=1 in 2025-02-09 20:42:11.404081
==== 1 enter ====
=== receive number=3 in 2025-02-09 20:42:11.404847
==== 3 enter ====
=== receive number=2 in 2025-02-09 20:42:11.404895
==== 2 enter ====
==== 1 exit ====
==== 3 exit ====
==== 2 exit ====
1.2.3.4.5.6.7.8.9.
其中：
- 每次调用返回前开始执行下一次调用，因此是非阻塞；
客户端日志显示同样可以实现异步非阻塞。
2025-02-09 20:42:11.388831
send number=1 in 2025-02-09 20:42:11.389133
send number=2 in 2025-02-09 20:42:11.389564
send number=3 in 2025-02-09 20:42:11.389789
[b'{"code": 0}', b'{"code": 0}', b'{"code": 0}']
2025-02-09 20:42:13.407953
Use time=2.02 seconds
需要注意的是单纯的 yield 并不能实现异步非阻塞，要求 yield 挂起的函数必须是非阻塞函数，比如这里如果还是使用 time.sleep 时依然阻塞。
tornado 中的另一种实现是使用线程池后台执行，其中线程池使用单例模式。
from concurrent.futures import ThreadPoolExecutor
import tornado.web
import tornado.gen
import tornado.concurrent
class Executor(ThreadPoolExecutor):
"""
单例模式实现线程池。大小为10
"""
_instance = None
def __new__(cls, *args, **kwargs):
ifnot getattr(cls, "_instance", None):
cls._instance = ThreadPoolExecutor(max_workers=10)
return cls._instance
class AsyncHandler(tornado.web.RequestHandler):
executor = Executor()
@tornado.gen.coroutine # 异步、协程处理；增加并发量
def post(self):
...
# time.sleep(2)
yield self._process()
...
self.finish(data)
@tornado.concurrent.run_on_executor
def _process(self):
# RuntimeError: There is no current event loop in thread 'ThreadPoolExecutor-0_0'.
# tornado.gen.sleep(2)
time.sleep(2)
其中：
- 将 time.sleep 封装在 _process 函数中， _process 函数调用前要加 yield，否则后台执行直接返回，不会等待结束；
- 不能使用 tornado.gen.sleep，否则报错 RuntimeError: There is no current event loop in thread。
服务端日志
=== receive number=1 in2025-02-0920:49:27.726765
==== 1 enter ====
=== receive number=2in2025-02-0920:49:27.727211
==== 2 enter ====
=== receive number=3in2025-02-0920:49:27.727406
==== 3 enter ====
==== 2 exit ====
==== 3 exit ====
==== 1 exit ====
客户端日志
2025-02-0920:49:27.716155
send number=1in2025-02-0920:49:27.716381
send number=2in2025-02-0920:49:27.716467
send number=3in2025-02-0920:49:27.716828
[b'{"code": 0}', b'{"code": 0}', b'{"code": 0}']
2025-02-0920:49:29.734317
Use time=2.02 seconds
测试显示这种方式虽然可以实现异步非阻塞，但是本质上还是线程池，因此无法满足需求。
到这里可以再次明确需求，接口实现中有 IO 操作，需求是接口异步非阻塞，且需要等待 IO 返回结果，因此适合使用协程，原因是协程允许在执行过程中暂停和恢复，从而实现异步编程。
而 tornado 中支持两种异步的实现方式，包括 yield 挂起函数与类线程池，这里使用前者。
优化
测试
class AsyncInceptionHandler(tornado.web.RequestHandler):
def post(self):
data = json.loads(self.request.body)
number = data.get("number")
receive_time = datetime.datetime.now()
print("=== receive number={} in {}".format(number, receive_time))
print("==== {} enter ====".format(number))
inception_main()
data = {
"code": 0
}
print("==== {} exit ====".format(number))
self.finish(data)
def inception_main():
start_time = datetime.datetime.now()
database_name = "cctest"
sql_script = "select 1;"
inception_test(database_name, sql_script)
end_time = datetime.datetime.now()
print(end_time.second - start_time.second)
def inception_test(database_name, sql_script):
# 调用 goinception
my_inception = GoInception(
mysql_ip="x.x.x.x",
mysql_port=3358,
database_name=database_name,
sql_script=sql_script,
)
check_data = my_inception.check_sql()
return check_data
class GoInception(object):
def check_sql(self):
check_result = self._get_inception_check_result()
returun check_result
def _get_inception_check_result(self):
"""
获取MySQL Inception对脚本进行check操作后的结果
:return:
"""
cursor = self._get_inception_server_connection().cursor()
cursor.execute(self._get_inception_check_statement())
query_result = cursor.fetchall()
return query_result
@staticmethod
def _get_inception_server_connection():
"""
获取MySQL Inception的连接
:return:
"""
return pymysql.connect(
host=GoInceptionServerConfig.mysql_ip,
user=GoInceptionServerConfig.mysql_user,
passwd=GoInceptionServerConfig.mysql_password,
port=GoInceptionServerConfig.mysql_port,
charset=GoInceptionServerConfig.mysql_charset,
db=GoInceptionServerConfig.database_name
)
测试显示接口单次调用执行用时 5.4s
2025-02-16 21:46:56.962885
send number=1 in 2025-02-16 21:46:56.963171
[b'{"code": 0}']
2025-02-16 21:47:02.366053
Use time=5.40 seconds
服务端日志
Request received: /block_inception/
=== receive number=1 in 2025-02-16 21:46:56.972630
==== 1 enter ====
cursor = <pymysql.cursors.Cursor object at 0x7fad806061f0>
execute done
get result
error:
-54
==== 1 exit ====
Request processed: /block_inception/, Elapsed time: 5.39 seconds
线程池并发 3 次调用用时 6.25s，基本上等于单次调用用时的三倍。
2025-02-16 21:48:34.918864
send number=1 in 2025-02-16 21:48:34.919095
send number=2 in 2025-02-16 21:48:34.919488
send number=3 in 2025-02-16 21:48:34.919667
[b'{"code": 0}', b'{"code": 0}', b'{"code": 0}']
2025-02-16 21:48:52.591335
Use time=17.67 seconds
服务端日志显示串行执行，阻塞，单次执行用时稳定在 5s 左右。
Request received: /block_inception/
=== receive number=3in2025-02-1621:48:34.928843
==== 3 enter ====
cursor = <pymysql.cursors.Cursor object at 0x7f7de8836370>
execute done
get result
error:
8
==== 3 exit ====
Request processed: /block_inception/, Elapsed time: 7.51 seconds
Request received: /block_inception/
=== receive number=1in2025-02-1621:48:42.440652
==== 1 enter ====
cursor = <pymysql.cursors.Cursor object at 0x7f7de8816e20>
execute done
get result
error:
6
==== 1 exit ====
Request processed: /block_inception/, Elapsed time: 5.79 seconds
Request received: /block_inception/
=== receive number=2in2025-02-1621:48:48.230043
==== 2 enter ====
cursor = <pymysql.cursors.Cursor object at 0x7f7de8816d90>
execute done
get result
error:
4
==== 2 exit ====
Request processed: /block_inception/, Elapsed time: 4.36 seconds
下面将同步阻塞代码修改为异步非阻塞模式。
aiomysql
使用 aiomyqsl + async + await
class AsyncInceptionHandler(tornado.web.RequestHandler):
@tornado.gen.coroutine
def post(self):
data = json.loads(self.request.body)
number = data.get("number")
receive_time = datetime.datetime.now()
print("=== receive number={} in {}".format(number, receive_time))
print("==== {} enter ====".format(number))
yield inception_main()
data = {
"code": 0
}
print("==== {} exit ====".format(number))
self.finish(data)
asyncdef inception_main():
start_time = datetime.datetime.now()
database_name = "cctest"
sql_script = "select 1;"
await inception_test(database_name, sql_script)
end_time = datetime.datetime.now()
print(end_time.second - start_time.second)
asyncdef inception_test(database_name, sql_script):
# 调用 goinception
my_inception = GoInception(
mysql_ip="x.x.x.x",
mysql_port=3358,
database_name=database_name,
sql_script=sql_script,
)
check_data = await my_inception.check_sql()
return check_data
class GoInception(object):
asyncdef check_sql(self):
check_result = await self._get_inception_check_result()
return check_result
asyncdef _get_inception_check_result(self):
"""
获取MySQL Inception对脚本进行check操作后的结果
:return:
"""
cursor = await self._get_inception_server_cursor()
await cursor.execute(self._get_inception_check_statement())
query_result = await cursor.fetchall()
await cursor.close()
return query_result
@staticmethod
asyncdef _get_inception_server_cursor():
"""
获取MySQL Inception的连接
:return:
"""
conn = await aiomysql.connect(
host=GoInceptionServerConfig.mysql_ip,
user=GoInceptionServerConfig.mysql_user,
password=GoInceptionServerConfig.mysql_password,
port=GoInceptionServerConfig.mysql_port,
charset=GoInceptionServerConfig.mysql_charset,
db=GoInceptionServerConfig.database_name
)
cursor = await conn.cursor()
return cursor
测试结果
服务端日志显示请求非阻塞，但是单次执行用时稳定在 9s 左右，显示比阻塞请求的用时更长。
Request received: /inception/
=== receive number=1in2025-02-1621:50:16.826816
==== 1 enter ====
Request received: /inception/
=== receive number=3in2025-02-1621:50:16.828231
==== 3 enter ====
Request received: /inception/
=== receive number=2in2025-02-1621:50:16.828826
==== 2 enter ====
cursor = <aiomysql.cursors.Cursor object at 0x7f7de8836880>
cursor = <aiomysql.cursors.Cursor object at 0x7f7de8836640>
cursor = <aiomysql.cursors.Cursor object at 0x7f7de8836490>
execute done
get result
error:
8
==== 3 exit ====
Request processed: /inception/, Elapsed time: 7.76 seconds
execute done
get result
error:
10
==== 1 exit ====
Request processed: /inception/, Elapsed time: 9.38 seconds
execute done
get result
error:
11
==== 2 exit ====
Request processed: /inception/, Elapsed time: 10.68 seconds
客户端日志
2025-02-1621:50:16.815495
send number=1in2025-02-1621:50:16.815727
send number=2in2025-02-1621:50:16.815810
send number=3in2025-02-1621:50:16.815895
[b'{"code": 0}', b'{"code": 0}', b'{"code": 0}']
2025-02-1621:50:27.509801
Use time=10.69 seconds
测试显示优化后不阻塞了，但是第一个请求需要等待最后一个请求结束才返回，整体执行反倒变慢。
因此问题就是前面的请求为什么发生等待？
goinception
查看 goinception 的日志，其中显示请求同时进入，但是也几乎同时返回，因此怀疑慢不是应用的原因。
time="2025/02/16 21:50:17.334" level=info msg="con:79 new connection 100.124.212.72:48060" file=server.go func=onConn line=319
time="2025/02/16 21:50:17.340" level=info msg="con:80 new connection 100.124.212.72:48062" file=server.go func=onConn line=319
time="2025/02/16 21:50:17.341" level=info msg="con:81 new connection 100.124.212.72:48064" file=server.go func=onConn line=319
time="2025/02/16 21:50:24.848" level=info msg="con:80 close connection" file=server.go func=func1 line=321
time="2025/02/16 21:50:26.504" level=info msg="con:81 close connection" file=server.go func=func1 line=321
time="2025/02/16 21:50:27.753" level=info msg="con:79 close connection" file=server.go func=func1 line=321
使用 top 命令查看机器负载
其中：
- MySQL 进程 CPU 使用率 92%；
- goIncetpion 进程 CPU 使用率 54%。
上线后测试显示机器负载不高的前提下可以实现异步非阻塞，但是 CPU 使用率高的问题还有待分析与解决。
下面使用 perf 分析 CPU。
首先使用 perf rerord 命令记录程序运行期间的性能时间，默认将性能事件保存到 perf.data 文件中。
[root@test ~]# perf record -g -a sleep 15
[ perf record: Woken up 33 times to write data ]
[ perf record: Captured and wrote 8.452 MB perf.data (51875 samples) ]
[root@test ~]#
[root@test ~]# ll -rth
-rw------- 1 root root 8.5M Feb 16 21:50 perf.data
然后使用 perf report 命令分析 perf record 保存到性能事件。
perf report -g
其中：
- Symbol 表示函数名，其中 [.] 表示用户空间函数，[k] 表示内核空间；
- Shared Object 表示函数所在的共享库或所在的程序；
- Command 表示进程名；
- Children 表示该函数的 CPU 使用率；
- Self 表示该函数的子函数的 CPU 使用率。
perf report --sort cpu -g --stdio
结合 top 与 perf 的结果，判断接口返回慢的原因是机器负载高，机器负载高的原因主要包括 MySQL 连接处理与 goInception SQL 解析，具体有待进一步分析。
下面是用到的命令与参数。
其中：
- perf record -g -a sleep 15
- -g 表示保存函数调用的堆栈关系；
- -a 表示记录所有 CPU 上的数据；
- sleep 15 表示 perf record 命令之后要运行的命令，sleep 15 命令会让进程休眠 10 秒钟，perf record 记录执行期间的所有事件。
- perf report -g
- -g 表示显示调用堆栈，其中快捷键 E 展开，C 收起。
- perf report --sort cpu -g --stdio
- --sort cpu 表示按照 CPU 使用率排序，默认倒序；
- --stdio 表示以文本模式显示报告。
结论
SQL 工单应用中遇到语法校验超时的问题，原因是接口同步阻塞，语法校验最耗时的是 IO 操作，期间服务 block。
最开始的优化方案是将应用启动方式从单进程修改为多进程，但事实证明这种方式并不合理，原因是超过上限后依然阻塞，甚至多个接口之间相互影响。
因此将代码从同步阻塞修改为异步非阻塞，tornado 中支持两种异步的实现方式，包括 yield 挂起函数与类线程池，这里使用前者。当然要求 yield 挂起的函数支持非阻塞，这里使用 aiomysql 替换 pymysql、async def 替换 def。
