如何定位和处理预编译语句(prepared statements)数量超限的问题

2,090 阅读12分钟

最近线上服务突然爆出大量 Can't create more than max_prepared_stmt_count statements (current value: 16382) 的错误,也就是说 MySQL 服务器上创建的预编译语句超过了设置的最大上限,导致新建 prepared statements 失败。其主要原因是服务内采用预编译的方式来优化执行效率,但是由于使用了动态 SQL,导致预编译资源被迅速耗光。本文尝试对该错误的定位和排查方法进行一次归纳总结。

什么是预编译

execute_flow.png

通常 MySQL 在执行一条 SQL 的时候需要依次通过分析器、优化器和执行器,分别对 SQL 进行词法语义解析,执行计划制定以及执行和结果返回。大多数情况下,一条 SQL 可能会被多次执行,或者每次执行的 SQL 仅存在个别参数值不同(例如查询的条件值等),如果每次执行都要进行以上所述的三个阶段,显然将会做大量的重复性工作,从而对执行的效率产生一定的影响。为此,MySQL提供了预编译语句(prepared statements)方案来优化执行效率。

所谓预编译语句可以理解为带占位符的模板化(或参数化)SQL,即将 SQL中的可变参数值用占位符代替,并在执行时用实际的参数进行填充。预编译即对 SQL 语句进行编译和生成对应的执行计划,并缓存处理结果,以供将来重复使用。我们可以通过 MySQL 提供的 PREPARE,EXECUTE,DEALLOCATE PREPARE 来完成预编译语句的编译、执行和释放,例如:

mysql> PREPARE user_info from 'select * from user where `name`=?'; -- 编译
mysql> SET @name='tom'; -- 绑定参数
mysql> EXECUTE user_info USING @name; -- 执行语句
mysql> SET @name='jim'; 
mysql> EXECUTE user_info USING @name;
mysql> DEALLOCATE PREPARE user_info; -- 释放

使用预编译主要有以下优势:

  • 优化 SQL 的执行效率:一次编译、多次执行,省去了重复的解析优化等过程。 编译后的结果会被放到命令缓冲区,缓存的 key 即为编译的 SQL 字符串 。在实际执行 SQL时,MySQL 服务端通过缓存获取执行方案,利用客户端传来的参数,拼接 SQL 语句并执行。
  • 预防 SQL 注入攻击:自动对特殊字符进行转义处理,避免执行逻辑错误。目前通过预编译语句,已被视为预防SQL注入攻击的最有效措施。

预编译虽好,但是其本身会占用 MySQL 服务端的内存资源,用于编译结果缓存。MySQL 对于可缓存的预编译数量也设定了一定的上限。

预编译语句超过上限了怎么办

Can't create more than max_prepared_stmt_count statements (current value: 16382)错误的根本原因是当前已创建的预编译语句的数量超过了系统限制。因此,在排查该问题时, 我们可能需要依次探索一下以下几件事情:

  • 当前预编译语句的上限是多少
  • 都有哪些用户占用了预编译资源
  • 都存在哪些预编译 SQL

预编译数量上限到底是多少

查看最大上限

MySQL 的最大预编译数量上限通过变量 max_prepared_stmt_count 进行指定,错误信息中其实已经给出了当前该变量的值(current value: 16382),当然我们也可以通过以下命令查看当前值:

show variables like '%max_prepared_stmt_count%';
+-------------------------+-------+
| Variable_name           | Value |
+-------------------------+-------+
| max_prepared_stmt_count | 16382 |
+-------------------------+-------+

默认情况下为16382, 并且支持的最大值为1048576。通常,默认设置就已经可以满足我们大部分的业务场景了。

查看当前状态

mysql> show global status like '%com_stmt%';
+-------------------------+-------+
| Variable_name           | Value |
+-------------------------+-------+
| Com_stmt_execute        | 1815  |
| Com_stmt_close          | 1420  |
| Com_stmt_fetch          | 0     |
| Com_stmt_prepare        | 1832  |
| Com_stmt_reset          | 0     |
| Com_stmt_send_long_data | 0     |
| Com_stmt_reprepare      | 360   |
+-------------------------+-------+

参数解释:

Com_stmt_prepare: 执行PREPARE的次数,编译次数

Com_stmt_execute:执行EXECUTE的次数,执行次数

Com_stmt_close:执行DEALLOCATE的次数,关闭释放次数

Com_stmt_reprepare:重新编译的次数,即对于已存在的预编译语句,重新编译一次则加1

这边我们需要重点关注Com_stmt_close的值是否接近于Com_stmt_prepare

当预编译语句超过上限,如果暂时不知道具体原因,最快的处理方式是增大max_prepared_stmt_count`的值或者重启MySQL。但是这通常只能暂时保证服务的正常使用,指标不治本,时间一长始终还是会触及上限。因此,我们需要进一步的探索,造成预编译资源被耗尽的具体原因。

谁占用了预编译资源

有时我们的 MySQL 实例会被多个业务共享,因此在排查过程中,我们可能需要先确定一下具体都有哪些用户占用了大量的预编译资源,以便缩小排查范围,加快问题定位。

以下脚本能够统计出通过当前处于opened状态的预编译语句数量,并按 user+host 进行聚合。其中,open_com_query_ps表示普通prepare语句开启的预编译,open_com_prepare_ps表示通过COM_STMT_PREPARE协议命令开启的预编译。

use performance_schema;
​
SELECT 
  *
FROM (
  SELECT 
    t.processlist_user AS user,
    t.processlist_host AS host,
    SUM(sp.count_star - sd.count_star) AS open_com_query_ps,
    SUM(cp.count_star - cc.count_star) AS open_com_prepare_ps
  FROM
    (
      SELECT 
        COUNT_STAR, THREAD_ID
      FROM
        events_statements_summary_by_thread_by_event_name
      WHERE
        event_name = 'statement/sql/prepare_sql'
    ) sp
    JOIN (
      SELECT 
        COUNT_STAR, THREAD_ID
      FROM
        events_statements_summary_by_thread_by_event_name
      WHERE
        event_name = 'statement/com/Prepare'
    ) cp ON (cp.THREAD_ID = sp.THREAD_ID)
    JOIN(
      SELECT 
        COUNT_STAR, THREAD_ID
      FROM
        events_statements_summary_by_thread_by_event_name
      WHERE
        event_name = 'statement/sql/dealloc_sql'
    ) sd ON (sd.THREAD_ID = sp.THREAD_ID)
    JOIN (
      SELECT 
        COUNT_STAR, THREAD_ID
      FROM
        events_statements_summary_by_thread_by_event_name
      WHERE
        event_name = 'statement/com/Close stmt'
    ) cc ON (cc.THREAD_ID = sp.THREAD_ID)
    JOIN threads t ON (t.THREAD_ID = sp.THREAD_ID)
  GROUP BY user, host
) AS r 
WHERE 
  user IS NOT NULL and host IS NOT NULL
ORDER BY 
  GREATEST(open_com_query_ps, open_com_prepare_ps) DESC;

执行结果如下所示:

+-----------------+------------+-------------------+---------------------+
| user            | host       | open_com_query_ps | open_com_prepare_ps |
+-----------------+------------+-------------------+---------------------+
| root            | 127.0.0.1  |                 1 |               12400 |
| event_scheduler | localhost  |                 0 |                   0 |
| root            | 172.17.0.1 |                 0 |                  20 |
+-----------------+------------+-------------------+---------------------+

通过执行结果,我们大概就能定位到大量消耗预编译资源的用户,进而找到对应的后端服务。我们在前面提到,一般情况下,默认的最大预编译数量(max_prepared_stmt_count = 16384)已足够支撑大部分业务场景,但是如果确实是因为该上限太小了,我们直接通过修改max_prepared_stmt_count即可。而更多情况下,预编译超限则可能是由于以下两种原因导致的:

  • 在服务中引入了动态SQL
  • 没有及时关闭释放预编译资源,造成资源泄漏

动态SQL的使用

动态SQL即一种基于带占位符 SQL ,加上可变参数拼接而得的 SQL,例如:

age := 12
sqlStr := fmt.Sprintf("SELECT * FROM user WHERE id >= ? and age = %v", age)

预编译语句编译后的结果会被放到命令缓冲区,且以 SQL 字符串作为缓存的 key 值,那么当参数的值发生变化时,就可能会导致缓存无法命中而重新创建新的预编译结果。当然,这个只会在我们有使用预编译语句时,才会出现以上问题。针对这种情况,我们就需要知道可能存在哪些动态 SQL,这个可以通过查看 MySQL 执行日历来定位,这个我们将在下一节将进行介绍。

预编译资源泄漏

在代码实现中,我们通常会通过Prepare创建一个预编译,并在适当的时候Close掉,这边以Golang中的实现为例:

var sqlDB *sql.DB
​
stmt, _ := sqlDB.Prepare("SELECT * FROM user WHERE id = ?")
defer stmt.Close()
​
stmt.Exec(12)

如果我们没有及时关闭释放资源,则可能就会造成资源的泄漏。例如,服务因为突发异常而退出并不断地重启,由于客户端是异常退出,MySQL服务端并感知不到,因此不会立马清除相关的缓存,而是等到旧的连接达到设置的最大连接时长( the maximum amount of time a connection may be reused)后才会关闭并释放连接资源。另外或者就是压根漏了关闭逻辑,那么这就明显是一个需要修复的Bug了。

都有哪些SQL被预编译了

如果业务服务本身并不复杂,代码量也不多,我们在知道了是哪个服务大量占用预编译资源后,就可以优先在代码里去排查是否使用了动态 SQL,或者忘记关闭释放预编译。但倘如业务逻辑复杂,或者对服务代码不熟悉,那么就需要另寻他路了。由于预编译的结果是缓存在内存里的,不太好直接查看缓存的内容。幸好 MySQL 提供了general_log ,这里我们可以通过MySQL general_log 来辅助定位。

generate_log 记录了所有执行的 SQL,对排查和分析MySQL的性能问题和线上问题,具有一定的帮助。在不清楚程序具体执行了什么 SQL 语句,找不到出错原因的情况下,可以短暂的开启这个general log日志的来辅助排查。查看和开启日志的方式如下:

mysql> SHOW VARIABLES LIKE "general_log%"; -- 查看日志开启状态
+------------------+---------------------------------+
| Variable_name    | Value                           |
+------------------+---------------------------------+
| general_log      | ON                              |
| general_log_file | /var/lib/mysql/8f69dbbd7131.log |
+------------------+---------------------------------+

如果general_logOFF, 则可以通过以下命令开启:

SET GLOBAL general_log = 'ON';

generate_log_file记录着所有执行过的 SQL 语句,其日志内容如下所示:

root@8f69dbbd7131:/# head -n 10 /var/lib/mysql/8f69dbbd7131.log
Time                           Id Command    Argument
2022-11-21T02:04:08.318164Z    55 Field List  user_variables_by_thread
2022-11-21T02:04:08.320083Z    55 Field List  users
2022-11-21T02:04:08.322360Z    55 Field List  variables_by_thread
2022-11-21T02:04:08.323965Z    55 Field List  variables_info
2022-11-21T02:04:18.849702Z    55 Query select * from setup_instruments where name like '%stmt%'
2022-11-21T02:04:31.064626Z    55 Query PREPARE test FROM ...
2022-11-21T02:04:31.068694Z    55 Prepare select * from setup_instruments where name like ?
2022-11-21T02:04:40.190852Z    55 Query set @name='%stmt%'
2022-11-21T02:04:45.745231Z    55 Query execute test using @name
2022-11-21T02:04:45.747275Z    55 Execute select * from setup_instruments where name like '%stmt%'

可以看到,日志总共有分为四列,其中第三列为Command和第四列Argument是我们比较关注的。根据Prepare关键字即可过滤和监听预编译相关的 SQL 执行日志:

root@8f69dbbd7131:/# tail -f /var/lib/mysql/8f69dbbd7131.log | grep Prepare
2022-11-21T08:15:45.982753Z    61 Prepare SELECT * FROM `user` WHERE id between ? and 20
2022-11-21T08:15:45.991240Z    61 Prepare SELECT * FROM `user` WHERE id IN (1,2,3,4,5,6,7,8,9,10) and id > ?
2022-11-21T08:15:46.002410Z    61 Prepare SELECT * FROM `user` WHERE id between ? and 22
2022-11-21T08:15:46.035252Z    61 Prepare SELECT * FROM `user` WHERE id between ? and 24
2022-11-21T08:15:46.066654Z    61 Prepare SELECT * FROM `user` WHERE id between ? and 26

general_log 可以辅助提供一些破案线索,帮助我们定位可能存在的动态SQL问题。正如上面的示例结果所示,我们就可以很明显地看到,动态 SQL 带来的多次创建预编译的问题。

思考与总结

出现Can't create more than max_prepared_stmt_count statements (current value: 16382) 这个错误的根本原因是系统当前创建的预编译数量大于最大数量限制,而造成这一结果的原因主要是两个:动态SQL的引入以及预编译泄漏。

  • 对于动态SQL:在实际开发中我们要尽可能避免动态 SQL 的使用,不通过字符串拼接的方式进行 SQL 构建,否则可能造成预编译资源耗尽以及引入SQL注入攻击的风险;
  • 对于预编译泄漏:这个主要是因为没有及时回收预编译资源。例如,当客户端异常退出(未正常关闭连接)时,由于MySQL服务端并不能及时感知到客户端已下线,而预编译资源是绑定在连接上的,所以资源并不能在客户端异常下线时被及时回收,从而造成一定时间内的泄漏。如果服务在异常退出后,会自动进行重启(例如我们通过k8s部署服务,并设置为自动重启),那么极有可能在短时间内多次重启后就迅速耗尽预编译资源。在实际开发中,我们应该注意做好预编译资源的释放处理:服务退出主动断开链接,预编译用完后及时关闭。

当然此次遇到的线上事故,也暴露出了另外一些问题,其中我认为值得我们思考以及在后续开发中加强的地方主要有以下几点:

  • 测试数据的多样、随机化:服务测试在压测的时候,通常只基于极为有限的固定数据进行,测试数据过于单一,难以触发类型由于动态 SQL 带来的预编译资源超限的问题。因此在压测过程中,是否应该考虑数据的多样化,例如引入混沌工程?
  • 各业务底层存储独享:在此次事故中,由于多个业务共享同一套存储实例,仅仅因为其中某个业务引入了的动态SQL或者编写了一些BUG,耗尽了 MySQL 预编译资源,就导致了所有业务服务均不可用。多业务之间共享同一套存储示例,容易造成服务之间的资源竞争和雪崩效应。不同业务的具体走向、请求量等存在一定的不可控性,在云原生时代,各服务独享一套物理存储应该会更为合理一些。
  • 服务的优雅退出:保证服务高可用少不了服务的优雅关闭处理,在实际退出之前应该做好资源的回收、未完成任务的执行等,以确保资源不泄漏不丢失。
  • 服务监控完善:我们在搭建服务监控时,除了采集接口QPS,延迟等这些常规指标外,也应该将数据库等中间件的系统资源指标也采集起来(例如线程数、连接数、慢SQL、预编译数量等),并创建相应的监控告警规则,便于问题的快速感知和定位。

参考资料