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

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

问题现象

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

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

Binlog dump:
MySQL慢日志slow_log为何会出现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程序进行验证。

上一篇:Go协程并发之百万级并发「让我们一起Golang」


下一篇:Python 库引用提示:name ‘json‘ is not defined. 问题解决办法