mysql prepare 日志_MySQL慢日志slow_log为何会出现Prepare与Binlog Dump-阿里云开发者社区...

最新推荐文章于 2024-08-09 11:16:15 发布

有请笠橙君

最新推荐文章于 2024-08-09 11:16:15 发布

阅读量573

点赞数

文章标签： mysql prepare 日志

本文链接：https://blog.csdn.net/weixin_33733806/article/details/113433517

版权

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]