故障分析 | 一条本该记录到慢日志的 SQL 是如何被漏掉的

news2024/11/28 16:47:57

背景

生产环境中 select count(*) from table 语句执行很慢，已经远超 long_query_time 参数定义的慢查询时间值，但是却没有记录到慢日志中。在测试环境也很容易复现出该问题，慢查询日志确实没有记录 select count(*) 语句。

慢查询相关参数设置如下：

slow_query_log = 1                                            #开启慢查询日志
slow_query_log_file = /mydata/3306/log/mysql.slow.log     #慢查询日志文件目录
log_queries_not_using_indexes = 1                           #开启记录未使用索引的SQL
log_slow_admin_statements = 1                               #开启记录管理语句
log_slow_slave_statements = 1                               #开启主从复制中从库的慢查询
log_throttle_queries_not_using_indexes = 10  #限制每分钟写入慢日志的未用索引的SQL的数量
long_query_time = 2                                         #定义慢查询的SQL执行时长
min_examined_row_limit = 100                  #该SQL检索的行数小于100则不会记录到慢日志

select count(*) 执行原理可以总结如下：InnoDB 存储引擎在执行 select count(*) 时，Server 层遍历读取 InnoDB 层的二级索引或主键，然后按行计数。

因此，慢查询日志不应该没有记录到执行时间超过long_query_time 的 select count(*) 语句。

慢查询日志源码剖析

为了一探到底，在 MySQL 源码中找到了以下记录慢查询日志的相关函数，本文所涉及的 MySQL 数据库版本为 8.0.32。

sql_class.cc 文件中的 update_slow_query_status 函数：

void THD::update_slow_query_status() {
  if (my_micro_time() > start_utime + variables.long_query_time)
    server_status |= SERVER_QUERY_WAS_SLOW;
}

my_micro_time 函数返回的是当前时间，如果当前时间大于这条 SQL 执行的开始时间加 long_query_time 参数定义的时长，则更新这条 SQL 的 server_status 为 SERVER_QUERY_WAS_SLOW。

log.cc 文件中的 log_slow_applicable 和 log_slow_statement 函数：

bool log_slow_applicable(THD *thd) {
......

  bool warn_no_index =
      ((thd->server_status &
        (SERVER_QUERY_NO_INDEX_USED | SERVER_QUERY_NO_GOOD_INDEX_USED)) &&
       opt_log_queries_not_using_indexes &&
       !(sql_command_flags[thd->lex->sql_command] & CF_STATUS_COMMAND));
  bool log_this_query =
      ((thd->server_status & SERVER_QUERY_WAS_SLOW) || warn_no_index) &&
      (thd->get_examined_row_count() >= thd->variables.min_examined_row_limit);

  // The docs say slow queries must be counted even when the log is off.
  if (log_this_query) thd->status_var.long_query_count++;

  /*
    Do not log administrative statements unless the appropriate option is
    set.
  */
  if (thd->enable_slow_log && opt_slow_log) {
    bool suppress_logging = log_throttle_qni.log(thd, warn_no_index);

    if (!suppress_logging && log_this_query) return true;
  }
  return false;
}

判断该 SQL 是否满足记录慢查询日志的三个条件：

  1. server_status 标记为 SERVER_QUERY_WAS_SLOW;
  2. warn_no_index 没有使用索引;
  3. 该 SQL 检索的行数 >= min_examined_row_limit 参数定义的行数。

如果该 SQL 满足记录慢查询日志的条件，那么则调用 log_slow_do 函数写慢查询日志。

void log_slow_statement(THD *thd) {
  if (log_slow_applicable(thd)) log_slow_do(thd);
}

MySQL 源码调试

在 MySQL 源码的 debug 环境中，开启 gdb 调试，对相关函数打下断点，这样便可以通过跟踪源码弄清楚一条 SQL 记录慢查询日志过程中函数和变量的情况。

(gdb) b THD::update_slow_query_status
(gdb) b log_slow_applicable
在客户端执行一条SQL：select count(*) from user_test，跟踪源码执行到update_slow_query_status函数时，可以发现这时候这条SQL的执行时长已经超过了long_query_time参数值，并且把这条SQL的server_status更新为SERVER_QUERY_WAS_SLOW。
查看堆栈信息如下：
(gdb) bt
#0  THD::update_slow_query_status (this=0x7f7d6000dcb0) at /root/gdb_mysql/mysql-8.0.32/sql/sql_class.cc:3217
#1  0x000000000329ddaa in dispatch_command (thd=0x7f7d6000dcb0, com_data=0x7f7dc43f1a00, command=COM_QUERY) at /root/gdb_mysql/mysql-8.0.32/sql/sql_parse.cc:2422
#2  0x000000000329a7d3 in do_command (thd=0x7f7d6000dcb0) at /root/gdb_mysql/mysql-8.0.32/sql/sql_parse.cc:1439
#3  0x00000000034b925f in handle_connection (arg=0xc966100) at /root/gdb_mysql/mysql-8.0.32/sql/conn_handler/connection_handler_per_thread.cc:302
#4  0x00000000051e835c in pfs_spawn_thread (arg=0xc9c0940) at /root/gdb_mysql/mysql-8.0.32/storage/perfschema/pfs.cc:2986
#5  0x00007f7ddff35ea5 in start_thread () from /lib64/libpthread.so.0
#6  0x00007f7dde95db0d in clone () from /lib64/libc.so.6
(gdb) n
3218        server_status |= SERVER_QUERY_WAS_SLOW;
(gdb) n
3219    }

跟踪源码执行到 log_slow_applicable 函数时，可以发现函数 thd->get_examined_row_count() 的返回值为 0。也就是说这条 SQL 检索的行数为 0 行，小于当前设置的 min_examined_row_limit 参数值 100，所以这条 SQL 没有记录到慢查询日志中。堆栈信息及打印变量输出如下：

(gdb) bt
#0  log_slow_applicable (thd=0x7f7d6000dcb0) at /root/gdb_mysql/mysql-8.0.32/sql/log.cc:1592
#1  0x00000000038ce8c5 in log_slow_statement (thd=0x7f7d6000dcb0) at /root/gdb_mysql/mysql-8.0.32/sql/log.cc:1661
#2  0x000000000329dff7 in dispatch_command (thd=0x7f7d6000dcb0, com_data=0x7f7dc43f1a00, command=COM_QUERY) at /root/gdb_mysql/mysql-8.0.32/sql/sql_parse.cc:2456
#3  0x000000000329a7d3 in do_command (thd=0x7f7d6000dcb0) at /root/gdb_mysql/mysql-8.0.32/sql/sql_parse.cc:1439
#4  0x00000000034b925f in handle_connection (arg=0xc966100) at /root/gdb_mysql/mysql-8.0.32/sql/conn_handler/connection_handler_per_thread.cc:302
#5  0x00000000051e835c in pfs_spawn_thread (arg=0xc9c0940) at /root/gdb_mysql/mysql-8.0.32/storage/perfschema/pfs.cc:2986
#6  0x00007f7ddff35ea5 in start_thread () from /lib64/libpthread.so.0
#7  0x00007f7dde95db0d in clone () from /lib64/libc.so.6

(gdb) p thd->get_examined_row_count()   //打印thd->get_examined_row_count()当前返回值
$4 = 0
(gdb) p thd->variables.min_examined_row_limit //打印min_examined_row_limit变量值
$5 = 100

原因

通过跟踪源码，可以查明 select count(*) from table 语句没有写入到慢日志中是因为 MySQL 把此类 SQL 的检索行数计算为 0 行，小于 min_examined_row_limit 参数值。因此，把 min_examined_row_limit 参数设置为 0 后，再次执行 select count(*)，可以看到在慢查询日志中，这条 SQL 执行完成后就被记录了。且慢查询日志中的信息显示这条 SQL 检索的行数为 0 行，返回的函数为 1 行。

所以要想把慢的 select count(*) 记录到慢查询日志中，min_examined_row_limit 这个参数必须保持为默认值 0。但是生产环境中一般会开启 log_queries_not_using_indexes 参数，为了避免慢查询日志记录检索行数较少的全表扫描的 SQL，需要设置 min_examined_row_limit 为某个大于 0 的值。

# User@Host: root[root] @ localhost []  Id:     8
# Query_time: 2.833550  Lock_time: 0.000013 Rows_sent: 1  Rows_examined: 0
use testdb;
SET timestamp=1681844004;
select count(*) from user_test;

提交 BUG

在 InnoDB 存储引擎中，每次执行 select count(*) from table 都会遍历全表或二级索引然后统计行数，不应该把 Rows_examined 计算成 0。因此我在官网上提交了此 bug，官方也证实了这个 bug：https://bugs.mysql.com/bug.php?id=110804

结语

虽然现在的 MySQL 数据库大多数部署在云上或者使用了数据库管理平台收集慢查询，慢查询日志可能不是首选的排查问题 SQL 的方法。但是对于没有额外配置慢查询监控的 MySQL，慢查询日志仍然是一个非常好的定位慢 SQL 的方法，配合 pt-query-digest 工具使用分析某段时间的 TOP SQL 也十分方便。并且数据库管理平台收集的慢查询数据需要额外的数据库存放，一般都会设置保留一段时间，如果要回溯更早的慢 SQL 就只能通过慢查询日志了。

本文来自互联网用户投稿，该文观点仅代表作者本人，不代表本站立场。本站仅提供信息存储空间服务，不拥有所有权，不承担相关法律责任。如若转载，请注明出处：http://www.coloradmin.cn/o/533059.html

如若内容造成侵权/违法违规/事实不符，请联系多彩编程网进行投诉反馈，一经查实，立即删除！

相关文章

数据结构入门-排序

数据结构入门-排序

排序的概念及其英语 排序的概念 排序：所谓排序，就是使一串记录，按照其中的某个或某些关键字的大小，递增或递减的顺序排列起来的操作。稳定性：假定在待排序的记录序列中，存在多个具有相同的关键字的记录&a…
阅读更多...
【网络】计算机中的网络

【网络】计算机中的网络

目录 🍁计算机网络 🍁计算机网络模型 🍁布线工程 🍁布线系统 🦐博客主页：大虾好吃吗的博客 🦐专栏地址：网络专栏 计算机网络 计算机网络的功能 数据通信、资源共享、增加可靠性、提…
阅读更多...
Dubbo——SpringBoot集成Dubbo（@Autowired和@Reference的区别、Dubbo的服务治理）

Dubbo——SpringBoot集成Dubbo（@Autowired和@Reference的区别、Dubbo的服务治理）

Dubbo——原生API实现远程调用_Strine的博客-CSDN博客 在上一篇文章中我们讲了如何使用原生API发起远程调用，显然这种方式肯定是非常麻烦的，因此我们这里就讲如何使用SpringBoot去集成Dubbo将这些配置简化。 生产者服务 添加配置文件 dubbo:applicat…
阅读更多...
如何安装Maven并在IDEA配置

如何安装Maven并在IDEA配置

下载 1.进入官网完成下载，下载好后解压到你喜欢的目录中去即可！ Maven – Download Apache Maven 2.解压出来就能看到以下目录结构，我们关注conf目录即可 3.配置Maven的本地仓库，进入conf目录并打开settings.xml，往下…
阅读更多...
8.3 综合案例2.0-扫码支付二维码生成

8.3 综合案例2.0-扫码支付二维码生成

综合案例2.0-扫码支付二维码生成 扫码支付完整流程案例说明1.硬件2.连线图 搭建云平台环境1.添加设备2.创建设备类型3.功能定义（创建物模型） 代码1.更改MQTT信息2.测试 扫码支付完整流程 参考链接微信支付开发者文档 （1）商户后台…
阅读更多...
数据分析09——Pandas中的索引设置/排序/数据统计（异常值处理）

数据分析09——Pandas中的索引设置/排序/数据统计（异常值处理）

1、Pandas中的索引设置： Series重置索引 重置索引：s2 s1.reindex([1, 2, 3, 4, 5]) # 这种情况即使列表中索引给多了也没事，会自动填充空值。重置索引：s3 s1.reindex([1, 2, 3, 4, 5], fill_value0) # 这种情况列表中索引给多了…
阅读更多...
从0开始 莫比乌斯函数和反演 学习笔记

从0开始 莫比乌斯函数和反演 学习笔记

莫比乌斯 0 前言 建议先看这篇比较简略的文章（有大概了解） 莫比乌斯函数_为最后的荣光的博客-CSDN博客 再根据个人情况食用本篇博客 1 莫比乌斯函数 1 1 定义 首先对 n n n 唯一分解： 唯一分解： 唯一分解定理一篇就够了_求…
阅读更多...
Springboot——根据需求创建后端接口

Springboot——根据需求创建后端接口

需求分析: 具体返回如下JSON格式数据 含有四个属性列:id 和 username 和photo 和followerCount 第一步: 首先按照下面文章创建一个模板项目 SpingBoot——SB整合MB的web项目模板_北岭山脚鼠鼠的博客-CSDN博客 第二步: 使用如下的建表语句在一个数据库中新建一个用户表 CREA…
阅读更多...
【C++进阶之路】类和对象(下)

【C++进阶之路】类和对象(下)

文章目录 一.再谈构造函数初始化对象的两种方式1.函数体内赋值2.初始化列表深入理解初始化列表 3.explicit隐式类型转换 二.static成员引言static成员static成员函数练习 三.友元引入友元函数友元类 四.内部类基本概念练习 五 .匿名对象引入匿名对象补充：编译器的优…
阅读更多...
一百一十三、DBeaver——从hive同步数据到clickhouse

一百一十三、DBeaver——从hive同步数据到clickhouse

目标：把hive的DM层结果数据导出到clickhouse数据库，试了kettle、sqoop等多种方法都报错，尤其是kettle，搞了大半天发现还是不行。结果目前就只能用DBeaver同步数据。 准备工作：hive和clickhouse中都建好表 第一步&…
阅读更多...
$nextTick与原生js先渲染dom再执行函数的方式

$nextTick与原生js先渲染dom再执行函数的方式

$nextTick与原生js先渲染dom再执行函数的方式 vue的$nextTick 简述 Vue.js 的 $nextTick 方法是用于在 DOM 更新后执行延迟回调的方法。 当 Vue.js 更新 DOM 后，有时候需要执行一些操作（如获取更新后的 DOM 元素的位置等），但是…
阅读更多...
2023年美国大学生数学建模竞赛C题预测Wordle的结果解题全过程文档及程序

2023年美国大学生数学建模竞赛C题预测Wordle的结果解题全过程文档及程序

2023年美国大学生数学建模竞赛 C题 预测Wordle的结果 原题再现： 背景介绍   Wordle是纽约时报目前每天提供的一个流行谜题。玩家通过在六次或更短时间内猜出一个至五个字母的单词来解决这个谜题，每次猜测都会得到反馈。在这个版本中， 每个…
阅读更多...
30Wqps+闲鱼优惠中台，如何架构的？

30Wqps+闲鱼优惠中台，如何架构的？

说在前面 在尼恩的（50）读者社群中，经常遇到一个 非常、非常高频的一个面试题，但是很不好回答，类似如下： 千万级数据，如何做系统架构？亿级数据，如何做做系统架构&#xf…
阅读更多...
2022年美国大学生数学建模竞赛E题森林的碳封存解题全过程文档及程序

2022年美国大学生数学建模竞赛E题森林的碳封存解题全过程文档及程序

2022年美国大学生数学建模竞赛 E题 森林的碳封存 原题再现： 背景   正如我们所知，气候变化对生命构成了巨大威胁。为了减轻气候变化的影响，我们需要采取有效的行动来减少大气中温室气体的含量。仅仅减少温室气体排放是不够的。我们需要努…
阅读更多...
Redis可持久化详解2

Redis可持久化详解2

目录 ​编辑 Redis的持久化配置参数： 2.Redis的性能问题： 3保持久化数据的完整性和正确性： 4.Redis的集群技术： 总结： Redis持久化不得不注意的一些地方。 Redis的持久化配置参数： save：指…
阅读更多...
MySQL之InnoDB表空间

MySQL之InnoDB表空间

前言 本文章收录在MySQL性能优化原理实战专栏，点击此处查看更多优质内容。 本文摘录自 ▪ 小孩子4919《MySQL是怎样运行的：从根儿上理解MySQL》 通过前边的内容，相信大家都知道了表空间是一个抽象的概念，对于系统表空间来说&am…
阅读更多...
Unity 全新的输入系统

Unity 全新的输入系统

选new的那个 会重启ide 然后去package manager里把这个装上 创建配置文件 文档地址 https://docs.unity3d.com/Packages/com.unity.inputsystem1.5/manual/index.html 创建完了是这样的 设置成这样 记住 value 和 vector2 然后就可以 选择 上下左右了 之前不设置 value…
阅读更多...
【macOS】：macbook 安装了两个macOS后，设置默认启动的顺序

【macOS】：macbook 安装了两个macOS后，设置默认启动的顺序

【macOS】：macbook 安装了两个macOS后，设置默认启动的顺序 如果你的 MacBook 安装了两个 macOS 操作系统， 你可以通过以下步骤设置默认启动的顺序： 1. 点击苹果菜单，选择“系统偏好设置”。 2. 点击“启动磁盘”选…
阅读更多...
基于OpenMP的并行计算实验

基于OpenMP的并行计算实验

一、实验目的 在Linux系统中，基于C编写OpenMP用例对并行计算进行实验： 1.掌握OpenMP的配置方式； 2.通过编写测试用例，观察引入OpenMP的加速效果 二、实验内容 2.1配置并测试OpenMP 1.配置并测试OpenMP 配置环境变量&#x…
阅读更多...
MySQL基础（三十五）多版本并发控制

MySQL基础（三十五）多版本并发控制

1. 什么是MVCC MVCC （Multiversion Concurrency Control），多版本并发控制。顾名思义，MVCC 是通过数据行的多个版本管理来实现数据库的 并发控制 。这项技术使得在InnoDB的事务隔离级别下执行 一致性读 操作有了保证。换言之&…
阅读更多...
推荐文章
最新文章

Copyright @ 2022~2023