Python 语法校验接口异步非阻塞实现-51CTO.COM

引言

本文主要记录线上案例中将同步阻塞代码修改为异步非阻塞的过程，期间介绍 goInception 的基本使用、多进程实现踩的坑、测试 tornado 中异步的多种实现，最终使用协程，并对使用期间遇到的性能问题进行了简单的分析。

现象

背景：SQL 工单应用基于 tornado 框架实现，其中实现多个接口，包括语法校验接口，其中语法校验基于开源项目 goInception 实现。对于超长 SQL 或多实例的场景，经常出现语法校验超时的问题，原因是接口阻塞，IO 操作导致服务 block。

需求：改造接口实现，从同步阻塞修改为异步非阻塞，缓解语法校验超时的问题。

当前实现

语法校验接口

class StartSyncCheckHandler(tornado.web.RequestHandler):
  
  def post(self):
   ...
      return_data = mysql_check(job_option)
      self.finish(return_data)1.
2.
3.
4.
5.
6.

接口中调用 goinception 实现语法校验，goinception 使用的主要流程如下所示。

conn = self._get_inception_server_connection()
  cursor = conn.cursor()
  cursor.execute(self._get_inception_check_statement())
  query_result = cursor.fetchall()
  cursor.close()1.
2.
3.
4.
5.

由于 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
  )1.
2.
3.
4.
5.
6.
7.
8.
9.

执行校验前生成提交给 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_statement1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
17.
18.
19.
20.
21.
22.

其中：

要求使用/* */将提交的信息括起来，其中每个参数通过分号分隔，包括要审核或执行的语句，包括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-processes1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.

但是很快就发现了这种实现的缺点。主要包括：

并发数有上限，超过进程数后依然会发生阻塞等待，比如分库分表语法校验；
多个接口之间相互影响，当其他比较慢的接口用完了进程数，单实例的语法校验也会发生阻塞等待。

下面是两个案例的具体介绍。

案例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'}1.
2.
3.
4.

工单 6044322 中有 37 个实例，调用执行接口 37 次，全部日志显示执行接口调用的时间相差 20s，原因是接口阻塞。

root@sql-inception-c3acb574:~# cat /export/Logs/sql.log | grep "start_execute_job:post:44" | grep 6044322 | awk '{print $2}'
01:12,807
01:12,890
...
01:37,194
01:37,275
...
01:39,363
01:39,4021.









可以对比另一个工单 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}'
36:31,203
36:31,203
...
36:31,398
36:31,3981.






显然，对于接口阻塞的问题，简单实用多进程无法解决该问题，因此下面测试将接口改为异步非阻塞模式。

测试

准备

接口实现，其中调用 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)1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
17.
18.
19.
20.
21.
22.

接口调用，其中使用线程池并发调用接口测试是否阻塞。

#!/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()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.
29.
30.
31.
32.
33.
34.
35.
36.
37.
38.
39.
40.
41.
42.
43.
44.
45.
46.
47.
48.

阻塞

服务端日志

=== 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 ====1.
2.
3.
4.
5.
6.
7.
8.
9.

其中：

每次调用返回后执行下一次调用，表明接口阻塞；
显示 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 seconds1.
2.
3.
4.
5.
6.
7.

其中：

并发请求同时发送，时间都是 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 ====1.
2.
3.
4.
5.
6.
7.
8.
9.

客户端日志

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 seconds1.
2.
3.
4.
5.
6.
7.

测试显示通过将阻塞方法 time.sleep 修改为非阻塞方法 tornado.gen.sleep 可以实现非阻塞。

@tornado.gen.coroutine

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)1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.

其中：

用 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 seconds1.
2.
3.
4.
5.
6.
7.

需要注意的是单纯的 yield 并不能实现异步非阻塞，要求 yield 挂起的函数必须是非阻塞函数，比如这里如果还是使用 time.sleep 时依然阻塞。

@tornado.concurrent.run_on_executor

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)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.
29.
30.
31.
32.
33.
34.
35.
36.

其中：

将 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 ====1.
2.
3.
4.
5.
6.
7.
8.
9.

客户端日志

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 seconds1.
2.
3.
4.
5.
6.
7.

测试显示这种方式虽然可以实现异步非阻塞，但是本质上还是线程池，因此无法满足需求。

到这里可以再次明确需求，接口实现中有 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
        )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.
29.
30.
31.
32.
33.
34.
35.
36.
37.
38.
39.
40.
41.
42.
43.
44.
45.
46.
47.
48.
49.
50.
51.
52.
53.
54.
55.
56.
57.
58.
59.
60.
61.
62.
63.
64.
65.
66.
67.
68.

测试显示接口单次调用执行用时 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 seconds1.
2.
3.
4.
5.

服务端日志

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 seconds1.
2.
3.
4.
5.
6.
7.
8.
9.
10.

线程池并发 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 seconds1.
2.
3.
4.
5.
6.
7.

服务端日志显示串行执行，阻塞，单次执行用时稳定在 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 seconds1.
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.
29.
30.

下面将同步阻塞代码修改为异步非阻塞模式。

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 cursor1.
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.
29.
30.
31.
32.
33.
34.
35.
36.
37.
38.
39.
40.
41.
42.
43.
44.
45.
46.
47.
48.
49.
50.
51.
52.
53.
54.
55.
56.
57.
58.
59.
60.
61.
62.
63.
64.
65.
66.
67.
68.
69.
70.
71.
72.

测试结果

服务端日志显示请求非阻塞，但是单次执行用时稳定在 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 seconds1.
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.
29.
30.

客户端日志

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 seconds1.
2.
3.
4.
5.
6.
7.

测试显示优化后不阻塞了，但是第一个请求需要等待最后一个请求结束才返回，整体执行反倒变慢。

因此问题就是前面的请求为什么发生等待？

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=3211.
2.
3.
4.
5.
6.

使用 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.data1.
2.
3.
4.
5.
6.

然后使用 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。

修改后测试显示接口不阻塞，但是第一个请求需要等待最后一个请求结束才返回，整体执行反倒变慢。结合 top 与 perf 的结果，判断接口返回慢的原因是机器负载高，机器负载高的原因主要包括 MySQL 连接处理与 goInception SQL 解析，具体有待进一步分析。

关于异步非阻塞与 CPU 使用率高的分析方法还需要深入学习，本文中暂未介绍。