MySQL慢日志slow_log为何会出现Prepare与Binlog Dump

MySQL慢日志为何会出现Prepare与Binlog Dump

问题现象

某客户的RDS数据库的某个时间段（时间点），慢日志记录出现大量的Prepare操作以及零星的Binlog Dump操作，如下图：

Prepare:

Binlog dump:

问题分析

慢日志中出现Prepare分析

MySQL预处理语句

Prepare是MySQL的预处理命令，其在MySQL server实现了请求的预处理，当我们使用MySQL shell client的时候，可以通过如下方式进行请求：

mysql> PREPARE stmt1 FROM 'SELECT SQRT(POW(?,2) + POW(?,2)) AS hypotenuse';
mysql> SET @a = 3;
mysql> SET @b = 4;
mysql> EXECUTE stmt1 USING @a, @b;
+------------+
| hypotenuse |
+------------+
|          5 |
+------------+           

当我们在开发应用程序时，在代码中使用时，可以通过如下方式请求（下图为JAVA代码）：

String selectSql = "select * from alitest where a = ? or b = ?";
PreparedStatement pretest =  conn.prepareStatement(selectSql);
pretest.setInt(1, 1);
pretest.setInt(2, 2);
ResultSet res = pretest.executeQuery();           

注意：在使用JAVA时，由于预处理既可以在客户端实现也可以在SERVER侧实现，要使程序使用SERVER侧的预处理，需要在建连时打开：useServerPrepStmts=true，即：jdbc:mysql://XXX.XXX.XXX.XXX:3306/alitest?useServerPrepStmts=true

MySQL对预处理请求进行Prepare的函数

从/mysql-5.6.24/sql/sql_prepare.cc源码文件中，可以找到进行Prepare的函数：Prepared_statement::prepare()。它的主要作用是 Parse statement text, validate the statement, and prepare it for execution。

MySQL记录慢日志的函数

从/mysql-5.6.24sql/sql_parse.cc源码文件中，可以找到进行慢日志记录的函数：log_slow_statement(THD *thd)，它的主要作用是Check whether we need to write the current statement to the slow query log。

复现问题

慢日志中出现Prepare，是否是因为Prepared_statement::prepare()函数处理请求过慢超过long_query_time导致?为了验证这个猜测，模拟Prepared_statement::prepare()函数处理慢的情况，人工的通过GDB对Prepared_statement::prepare()设置断点，增加其执行时间，然后通过MySQL shell client 与JAVA代码分别请求，查看慢日志的记录情况。

设置断点

(gdb) b Prepared_statement::prepare

Breakpoint 1 at 0x7d821e: file /opt/mysql-5.6.24/sql/sql_prepare.cc, line 3358.

MySQL shell client 执行如下命令

mysql> PREPARE stmt1 FROM 'SELECT SQRT(POW(?,2) + POW(?,2)) AS hypotenuse';

(命令阻塞......)

命令阻塞后，等待超过long_query_time的时间，然后在GDB中执行continue继续运行命令，PREPARE命令执行完成后，查看慢日志如下：

*************************** 15. row ***************************
    start_time: 2020-08-22 18:34:45
     user_host: root[root] @ localhost []
    query_time: 00:04:56
     lock_time: 00:00:00
     rows_sent: 0
 rows_examined: 0
            db:
last_insert_id: 0
     insert_id: 0
     server_id: 2003306
      sql_text: PREPARE stmt1 FROM 'SELECT SQRT(POW(?,2) + POW(?,2)) AS hypotenuse'
     thread_id: 171           

从慢日志的记录来看，这不是我们想要的结果。

JAVA执行Prepare请求：

调用JAVA代码（请记住连接时启用useServerPrepStmts），执行Prepare操作，请求阻塞后，等待超过long_query_time的时间，然后在GDB中执行continue继续运行命令，JAVA代码执行完成后，查看慢日志如下：

************************* 7. row ***************************
    start_time: 2020-08-22 18:57:45
     user_host: dtstest[dtstest] @  [115.216.4.201]
    query_time: 00:00:09
     lock_time: 00:00:00
     rows_sent: 0
 rows_examined: 0
            db: alitest
last_insert_id: 0
     insert_id: 0
     server_id: 2003306
      sql_text: Prepare
     thread_id: 163           

可以看到，Prepare命令被记录到了慢日志中。

慢日志中出现Binlog dump分析

MySQL的Binlog dump命令

当我们搭建MySQL的从库时，需要从主库获取binlog文件，而Binlog dump（或者Binlog dump gtid）命令就是用来该功能的。MySQL中有2个关于Binlog dump的函数，分别是com_binlog_dump()与com_binlog_dump_gtid()，后者主要应用于开启了GTID的复制。可以在/mysql-5.6.24/sql/rpl_master.cc中找到它们。根据之前的猜测，慢日志中出现Binlog dump（或者Binlog dump GTID）是否是因为对应的函数处理慢导致？

(gdb) b com_binlog_dump

Breakpoint 3 at 0xa12318: file /opt/mysql-5.6.24/sql/rpl_master.cc, line 739.

启动binlog dump

为了测试方便，直接使用mysqlbinlog程序远程获取binlog：

/bin/mysqlbinlog -hxxx.xxx.xxx.xxx -udtstest -p --read-from-remote-server mysqlbin.000004

命令阻塞后，等待超过long_query_time的时间，然后在GDB中执行continue继续运行命令，mysqlbinlog命令执行完成后，查看慢日志如下：

************************* 34. row ***************************
    start_time: 2020-08-22 20:57:38
     user_host: dtstest[dtstest] @  [121.196.185.131]
    query_time: 00:00:00
     lock_time: 00:00:00
     rows_sent: 0
 rows_examined: 0
            db:
last_insert_id: 0
     insert_id: 0
     server_id: 2003306
      sql_text: Binlog Dump
     thread_id: 466           

可以看到，Binlog Dump命令被记录到了慢日志中。

注意：由于Binlog dump属于admin statement，复现问题时，需要把log_slow_admin_statements设置为ON。慢日志才会记录admin statements。

问题结论

慢日志中出现Binlog dump、Binlog dump GTID、Prepare命令，是由于对应的请求执行超过long_query_time导致。出现这种情况，一般意味着系统负载可能较高，尤其是Prepare等命令的出现，需要引起关注。

后记

如果想要更加方便的复现该问题，可以把long_query_time参数设置为0（这样可以避免通过GDB来手动干预命令的耗时），然后调用JAVA代码以及mysqlbinlog程序进行验证。