专栏首页吴生的专栏MySQL 慢日志线上问题分析及功能优化

MySQL 慢日志线上问题分析及功能优化

MySQL 慢日志(slow log)是 MySQL DBA 及其他开发、运维人员需经常关注的一类信息。使用慢日志可找出执行时间较长或未走索引等 SQL 语句,为进行系统调优提供依据。 本文将结合一个线上案例,分析如何正确设置 MySQL 慢日志参数和使用慢日志功能,并介绍下网易云 RDS 对 MySQL 慢日志功能的增强。

MySQL 参数组功能

网易云 RDS 实例提供了参数组管理功能,可通过参数管理界面查看绝大部分常用的 MySQL 系统参数,用户可了解当前运行值和建议值:

用户还可通过参数管理页面对所列的参数进行修改,点击 “修改参数” 按钮进行在线设置,点击 “保存修改” 即可一键完成 MySQL 主从节点的参数修改:

查看参数管理界面不难发现,与慢查询相关的参数比较多,那么,这些参数都是如何起作用的呢,相互关系又是如何,满足什么条件的 SQL 语句才会记录到慢日志中?只有了解这些才能更好地利用慢日志进行系统调优和问题定位。 下面,我们以这个线上案例为依托,介绍下该如何正确配置慢日志参数: 有用户报告,他们使用的多个 RDS 5.7 版本实例慢日志异常,明明执行了一分多钟的 SQL 语句,却没有记录到慢日志中。还提供了用于复现的 SQL 语句。

慢日志参数正确配置姿势

首先,我们需要确认该实例是否开启了慢日志功能,默认情况下,MySQL 慢日志功能是关闭的。慢日志开关参数为 slow_query_log,可在 mysqld 启动命令行或配置文件中显式指定,若指定 slow_query_log=1 或不指定值,则表示开启慢日志,赋值为 0 表示关闭。用户可以在运行时动态开启和关闭。 网易云 RDS 实例默认开启慢日志功能,我们确认了该用户未关闭实例的慢日志开关。 接下来,需确认慢日志记录位置,MySQL 使用 log_output 参数指定以文件(FILE)还是以表 (TABLE) 的方式来保存慢日志。需要强调的是,仅指定 log_output 而将 slow_query_log 置为 0 并不会记录慢日志,也就是说 slow_query_log 才是慢日志的开关。若使用文件形式记录慢日志,则可通过 slow_query_log_file 指定文件名,如果用户没有显式指定 slow_query_log_file,则 MySQL 将其初始化为 host_name-slow.log,host_name 即为运行 mysqld 的主机名,慢日志文件默认位于 MySQL 数据目录。 网易云 RDS 实例不允许用户修改日志文件路径,但可以配置 log_output 参数,通过查询,确认该实例以文件方式记录慢日志,查看日志文件确认没有用户所述的 SQL 语句。 由于用户提供了复现语句,我们执行了其 SQL 语句,确实 1 分多钟才返回,通过 explain 命令发现其未走索引,扫描了较多的记录数,再次查看慢日志仍没有记录该 SQL 语句。 MySQL 会记录满足执行时间超过 long_query_time 秒,扫描记录数超过 min_examined_row_limit 行的 SQL 语句。long_query_time 参数最小值和默认值分别为 1 和 10s,该参数可以精确到微秒(ms)。如果选择将慢日志记录到文件中,那么所记录的时间精确到微秒,如果记录到慢日志表(mysql.slow_log)中,那么仅精确到秒,微秒部分被忽略。 网易云 RDS 实例允许用户设置这两个参数值,那么是不是用户调整了上述两个阈值,导致无法满足记录条件呢,进一步查询发现也不是问题原因所在。 我们注意到 MySQL 还有个名为 log_queries_not_using_indexes 的参数用于控制是否记录未走索引的 SQL 查询,代码如下:

重点关注箭头所指内容,如果查询未走索引或者索引无效,且相关参数开启,那么 warn_no_index 设置为 true,若同时满足扫描记录数超过阈值,也会像慢查询一样被记录,那么是不是该参数未开呢?结果仍是否定的。

问题原因之所在

由于数据库实例中可能有较多不走索引的 SQL 语句,若开启 log_queries_not_using_indexes,则存在日志文件或表容量增长过快的风险,此时可通过设置 log_throttle_queries_not_using_indexes 来限制每分钟写入慢日志中的不走索引的 SQL 语句个数,该参数默认为 0,表示不开启,也就是说不对写入 SQL 语句条数进行控制。 启用后,系统会在第一条不走索引的查询执行后开启一个 60s 的窗口,在该窗口内,仅记录最多 log_throttle_queries_not_using_indexes 条 SQL 语句。超出部分将被抑制,在时间窗结束时,会打印该窗口内被抑制的慢查询条数以及这些慢查询一共花费的时间。下一个统计时间窗并不是马上创建,而是在下一条不走索引的查询执行后开启。 对应到该线上问题,log_throttle_queries_not_using_indexes 被设置为 10,在日志文件中看到周期性打印了如下内容:

确实符合上面描述的现象,用户的慢日志应该是被抑制了,汇总到了 359 里面去。我们尝试将 log_throttle_queries_not_using_indexes 设置为 0,再执行对应的 SQL 语句,果然在日志文件中记录了相应的 SQL 语句。 这个线上问题似乎已经定位到了,就是系统产生的不走索引的慢日志太多,而设置的 log_throttle_queries_not_using_indexes 太小,导致无法正常记录用户未走索引的慢日志。但还有一个疑惑点没有解决,那就是 log_throttle_queries_not_using_indexes 为 0 时,每分钟并没有打印超过10条慢日志,更没有 throttle 提示的 359 条这么多,那么设置为 10 的时候用户提供的那条 SQL 语句应该被记录到慢日志中才对啊,为何没有记录,原因何在?其实,仔细看下 MySQL 记录不走索引的日志的代码逻辑可以找到答案:

上图是记录慢日志的主逻辑,是否记录日志由函数 log_slow_applicable 控制,该函数先前已分析了一部分,我们进一步看该函数的其他相关内容,见下图红框:

Suppress_logging 是个决定性的变量,只有它为 false,该 SQL 语句才可能被记录。其结果就跟 log_throttle_queries_not_using_indexes 相关,我们进一步看下 log_throttle_qni.log 相关实现,如下图:

Eligible 即为 warn_no_index,inc_log_count() 函数在 1 分钟内不走索引的语句总数超过 log_throttle_queries_not_using_indexes 时返回值为 true,只有 warn_no_index 和 inc_log_count() 返回值都为 true,suppress_current 才为 true,而 suppress_current 即为 suppress_logging。 通过对上述 2 个截图内容进行分析,可以解答之前的疑惑点: log_throttle_queries_not_using_indexes 统计的是所有不走索引的语句,其中有些语句因为不满足扫描记录数的约束而不会记录到慢日志中,这就是为什么该值为 10 的时候,慢日志文件中并没有 10 条记录。因为这 10 条中有 8 条 SQL 语句由于扫描记录数太少并没有被记录。

InnoSQL 慢日志功能增强

还有部分 RDS 实例用户问我们,为什么我的 SQL 语句执行时间没有超过所设置的 long_query_time,而且走了索引,但还是被记录到慢日志中,是不是出 Bug 了?其实这不是 Bug,而是因为网易云 RDS 使用的 InnoSQL(网易维护的 MySQL 开源分支)版本对慢日志做了优化,除了考察 SQL 语句的执行时间外,还关注该查询所需的磁盘页面(Disk Page)数,因为所需的页面数目过多,也可能会对系统负载造成较大影响。为了能够量化统计,我们收集了 SQL 查询所需读取的总页面数和这些页面中实际进行 IO 的次数,分别记录为 logical_reads和physical_reads,前者包括命中 InnoDB Buffer Pool 和未命中需要进行 IO 的页面请求。 通过引入 slow_query_type 和 long_query_io 两个参数为用户提供该功能。前者可设置为 0/1/2/3。“1” 表示启用基于执行时间来记录慢日志,“2” 表示基于搜索总页面数来记录慢日志,“3” 是 “1” 和 “2” 的合集。所以在 InnoSQL 中,SQL 查询只需满足执行时间够长或所需总页面数够多即可记录到慢日志中。代码实现片段如下:

页面数阈值通过 long_query_io 参数来衡量,用户可动态设置,如果总页面数 m_logical_reads 超过了该值,即使执行时间未超标,也会被记录。相应的,RDS 实例慢日志表结构和慢日志文件输出内容也增加了新的字段。

上图即为 InnoSQL 版的 slow_log 表结构,其中,logical_reads 和 physical_reads 为 InnoSQL 增加字段。同样的,慢日志文件的输出内容也增加了两个字段,如下所示:

除了以上详细描述的内容外,MySQL 慢日志模块还有如下几个特性值得关注: ○ 进行慢日志统计及慢日志中所记录的时间并不包括该 SQL 语句开始执行前获取锁所需等待的时间; ○ MySQL 在 SQL 语句执行完且所持有的锁均已释放后才将其写入慢日志中,所以慢日志中的 SQL 语句记录顺序并不能准确反映这些 SQL 语句的实际执行顺序; ○ 每条慢日志都包含一个时间戳,若写入文件中,log_timestamps 参数用于将慢日志时间戳转化为指定时区的时间。但该参数对于 mysql.slow_log 表中的慢日志不起作用; ○ 可通过设置 log_slow_slave_statements 来开启 MySQL 从库的慢日志功能; ○ ALTER TABLE, ANALYZE TABLE, CHECK TABLE, CREATE INDEX, DROP INDEX, OPTIMIZE TABLE, and REPAIR TABLE 等表管理操作也能够被记录到慢日志中,可通过 log_slow_admin_statements 选项开启。

相关文章推荐:http://www.roncoo.com/article/index?title=mysql

原文链接:http://www.roncoo.com/article/detail/131610

我来说两句

0 条评论
登录 后参与评论

相关文章

  • 性能优化-MySQL慢查日志分析工具(mysqldumpslow)

    1、查询次数多且每次查询占用时间长的sql 通常为pt-query-digest分析的前几个查询;该工具可以很清楚的看出每个SQL执行的次数及百分比等信息,执...

    cwl_java
  • 性能优化-MySQL慢查日志分析工具(mysqldumpslow)

    如何进行查看慢查询日志,如果开启了慢查询日志,就会生成很多的数据,然后我们就可以通过对日志的分析,生成分析报表,然后通过报表进行优化。

    cwl_java
  • 性能优化-MySQL慢查日志分析工具(pt-query-digest)

    性能的管理一直都是摆在第一位的,dba的很多工作管理层都看不到也没有办法衡量价值,但是如果一个系统慢的跟蜗牛一样,dba通过监控调优把系统从崩溃边 缘重新拉回到...

    cwl_java
  • MySQL“被动”性能优化汇总!

    当然,本篇也是关于性能优化的,那性能优化就应该一把梭子吗?还是要符合一些规范和原则呢?

    Java中文社群-磊哥
  • 云数据库MySQL CPU飙升排查流程

    在日常使用MySQL的过程中,会遇到 CPU 使用率过高甚至达到 100% 的情况。CPU飙升会导致数据库无法连接,事务无法提交等一系列问题。本文基于日常问题处...

    苏欣
  • Mysql性能优化——慢查询分析

    MYSQL数据库是常见的两个瓶颈是CPU和I/O的瓶颈,CPU在饱和的时候一般发生在数据装入内存或从磁盘上读取数据时候。磁盘I/O瓶颈发生在装入...

    L宝宝聊IT
  • 高性能MySQL(一):MySQL架构与历史

    第二层架构是MySQL比较有意思的部分,大多数MySQL的核心服务功能都在这一层,包括增删查改以及所有的内置函数。 所有跨存储引擎的功能都在这一层实现,存储过...

    看、未来
  • 58同城 Elasticsearch 应用及平台建设实践

    导读:Elasticsearch是一个分布式的搜索和分析引擎,可以用于全文检索、结构化检索和分析,并能将这三者结合起来。Elasticsearch基于Lucen...

    week
  • Mysql数据库之Binlog日志使用总结

    binlog二进制日志对于mysql数据库的重要性有多大,在此就不多说了。下面根据本人的日常操作经历,并结合网上参考资料,对binlog日志使用做一梳理: 一、...

    洗尽了浮华
  • Mysql数据库全局分析及太极后端优化实战

    | 导语 腾讯机器学习平台太极后端数据库是自己运维的Mysql,历史原因没有用公司CDB、TDSQL等,之后还是要进行数据库迁移把db维护交给专业的人去运维,...

    腾讯大讲堂
  • TiDB 3.0 GA Release Notes

    2019 年 6 月 28 日,TiDB 发布 3.0 GA 版本,对应的 TiDB Ansible 版本为 3.0.0。

    PingCAP
  • 浅谈性能瓶颈定位之MySQL慢查询

    在性能测试过程中,我们会发现各种各样的性能问题,其中数据库相关的问题尤为居多。在鄙人做过的项目中,超过40%以上性能问题是跟开发人员编写的SQL有关。今天从性能...

    老_张
  • 【Java调优】MysqlIO.readFully问题排查分析过程

    支付清结算系统"外部对账"部分任务在早上6:00~7:00时间段内对账速度缓慢,且经常造成对账统计结果不准确问题,导致结转记账不准确。

    用户5927304
  • 有赞MySQL自动化运维系统--ZanDB

    有赞作为"新零售"的软件服务供应商,随着业务的不断发展,从第一批几十家商户到现在300万商家,涉及零售,美业,餐饮,自媒体等众多商家,业务规模以及访问量爆发式...

    用户1278550
  • 数据库自助服务演进初步设计

    今天对接完成了SQL自动化上线的一个功能,其实心里还是有点小激动,终于可以很肯定说,数据库方向开始提供的是数据服务,而不是传统意义的工单了。

    jeanron100
  • What’s New in TiDB 3.0.0 Beta.1

    今年 1 月份,我们发布了 TiDB 3.0.0 Beta 版本,DevCon 上也对这个版本做了介绍,经过两个月的努力,今天推出了下一个 Beta 版本 3....

    PingCAP
  • Mysql性能调优(五)

      上篇文章我们介绍了MySQL体系结构以及存储引擎的相关介绍。接下来,我们给大家介绍SQL语句的优化以及具体的sql优化步骤。接下来我们介绍优化sql的具体步...

    一计之长
  • 技术分享 | Slow Query Log 使用详解

    爱可生交付服务部团队 DBA 擅长日志分析、问题排查等;主要负责处理 MySQL 与我司自研数据库自动化管理平台 DMP 的日常运维问题,对数据库及周边技术有浓...

    爱可生开源社区
  • MySQL 性能优化技巧

    最近公司项目添加新功能,上线后发现有些功能的列表查询时间很久。原因是新功能用到旧功能的接口,而这些旧接口的 SQL 查询语句关联5,6张表且编写不够规范,导致 ...

    lyb-geek

扫码关注云+社区

领取腾讯云代金券