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

本文涉及的产品
云数据库 RDS MySQL,集群系列 2核4GB
推荐场景:
搭建个人博客
RDS MySQL Serverless 基础系列,0.5-2RCU 50GB
日志服务 SLS,月写入数据量 50GB 1个月
简介: 尝试分析MySQL慢日志slow_log为何会出现Prepare与Binlog Dump

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

问题现象

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

Prepare:
1.jpg

Binlog dump:
2.jpg

问题分析

慢日志中出现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程序进行验证。

相关实践学习
阿里云图数据库GDB入门与应用
图数据库(Graph Database,简称GDB)是一种支持Property Graph图模型、用于处理高度连接数据查询与存储的实时、可靠的在线数据库服务。它支持Apache TinkerPop Gremlin查询语言,可以帮您快速构建基于高度连接的数据集的应用程序。GDB非常适合社交网络、欺诈检测、推荐引擎、实时图谱、网络/IT运营这类高度互连数据集的场景。 GDB由阿里云自主研发,具备如下优势: 标准图查询语言:支持属性图,高度兼容Gremlin图查询语言。 高度优化的自研引擎:高度优化的自研图计算层和存储层,云盘多副本保障数据超高可靠,支持ACID事务。 服务高可用:支持高可用实例,节点故障迅速转移,保障业务连续性。 易运维:提供备份恢复、自动升级、监控告警、故障切换等丰富的运维功能,大幅降低运维成本。 产品主页:https://www.aliyun.com/product/gdb
目录
相关文章
|
存储 关系型数据库 MySQL
mysql 语句传参数 -- prepare语句的用法
mysql 语句传参数 -- prepare语句的用法
154 0
|
存储 关系型数据库 MySQL
mysql 语句传参数 -- prepare语句的用法
mysql 语句传参数 -- prepare语句的用法
81 0
|
SQL 关系型数据库 Java
mysql prepare原理
mysql prepare 原理
5973 0
|
存储 关系型数据库 MySQL
|
24天前
|
NoSQL 关系型数据库 MySQL
微服务架构下的数据库选择:MySQL、PostgreSQL 还是 NoSQL?
在微服务架构中,数据库的选择至关重要。不同类型的数据库适用于不同的需求和场景。在本文章中,我们将深入探讨传统的关系型数据库(如 MySQL 和 PostgreSQL)与现代 NoSQL 数据库的优劣势,并分析在微服务架构下的最佳实践。
|
26天前
|
存储 SQL 关系型数据库
使用MySQL Workbench进行数据库备份
【9月更文挑战第13天】以下是使用MySQL Workbench进行数据库备份的步骤:启动软件后,通过“Database”菜单中的“管理连接”选项配置并选择要备份的数据库。随后,选择“数据导出”,确认导出的数据库及格式(推荐SQL格式),设置存储路径,点击“开始导出”。完成后,可在指定路径找到备份文件,建议定期备份并存储于安全位置。
192 11
|
1天前
|
SQL 关系型数据库 MySQL
|
21天前
|
存储 SQL 关系型数据库
MySQL的安装&数据库的简单操作
本文介绍了数据库的基本概念及MySQL的安装配置。首先解释了数据库、数据库管理系统和SQL的概念,接着详细描述了MySQL的安装步骤及其全局配置文件my.ini的调整方法。文章还介绍了如何启动MySQL服务,包括配置环境变量和使用命令行的方法。最后,详细说明了数据库的各种操作,如创建、选择和删除数据库的SQL语句,并提供了实际操作示例。
60 13
MySQL的安装&数据库的简单操作
|
27天前
|
存储 SQL 关系型数据库
一篇文章搞懂MySQL的分库分表,从拆分场景、目标评估、拆分方案、不停机迁移、一致性补偿等方面详细阐述MySQL数据库的分库分表方案
MySQL如何进行分库分表、数据迁移?从相关概念、使用场景、拆分方式、分表字段选择、数据一致性校验等角度阐述MySQL数据库的分库分表方案。
126 14
一篇文章搞懂MySQL的分库分表,从拆分场景、目标评估、拆分方案、不停机迁移、一致性补偿等方面详细阐述MySQL数据库的分库分表方案
|
1天前
|
关系型数据库 MySQL 数据库
DZ社区 mysql日志清理 Discuz! X3.5数据库可以做定期常规清理的表
很多站长在网站日常维护中忽略了比较重要的一个环节,就是对于数据库的清理工作,造成数据库使用量增加必须多的原因一般有2个:后台站点功能开启了家园,此功能现在很少有论坛会用到,但是灌水机会灌入大量垃圾信息致使站长长时间未能发觉;再有就是程序默认的一些通知类表单会存放大量的、对于网站日常运行并无意义的通知信息。
13 2