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程序进行验证。
