发帖
翼度科技»论坛 › 编程开发 › mysql › 查看内容

源码解析丨一次慢SQL排查

三寸时光

9

主题

9

帖子

27

积分

新手上路

Rank: 1

积分
27
显示全部楼层
当long_query_time=1时（表info的id为主键），出现下面的慢日志，可能会让你吃惊
  1. # Time: 2024-01-28T22:52:24.500491+08:00
  2. # User@Host: root[root] @  [127.0.0.1]  Id:     8
  3. # Query_time: 7.760787  Lock_time: 7.757456 Rows_sent: 0  Rows_examined: 0
  4. use apple;
  5. SET timestamp=1706453536;
  6. delete from info where id < 10;
复制代码
环境信息

配置参数ip172.17.137.12hostnamedevmemory16Gcpu8CMySQL versionGreatSQL 8.0.26慢查询相关参数
  1. greatsql> select * from performance_schema.global_variables where variable_name in('slow_query_log','log_output','slow_query_log_file','long_query_time','log_queries_not_using_indexes','log_slow_admin_statements','min_examined_row_limit','log_throttle_queries_not_using_indexes') order by variable_name;
  2. +----------------------------------------+-------------------------------------+
  3. | VARIABLE_NAME                          | VARIABLE_VALUE                      |
  4. +----------------------------------------+-------------------------------------+
  5. | log_output                             | FILE                                |
  6. | log_queries_not_using_indexes          | OFF                                 |
  7. | log_slow_admin_statements              | OFF                                 |
  8. | log_throttle_queries_not_using_indexes | 0                                   |
  9. | long_query_time                        | 1.000000                            |
  10. | min_examined_row_limit                 | 0                                   |
  11. | slow_query_log                         | ON                                  |
  12. | slow_query_log_file                    | /root/local/8026/log/slow.log       |
  13. +----------------------------------------+-------------------------------------+
  14. 8 rows in set (10.49 sec)
复制代码

  • slow_query_log：慢日志开关
  • log_output：慢日志存储方式，FILE或TABLE
  • long_query_time：慢日志阈值
  • min_examined_row_limit：设置慢SQL的最小examined扫描行数，建议设置为0，因为有bug：https://bugs.mysql.com/bug.php?id=110804
  • log_queries_not_using_indexes：不使用索引的慢查询日志是否记录到索引
  • log_slow_admin_statements：在写入慢速查询日志的语句中包含慢速管理语句（create index,drop index,alter table,analyze table,check table,optimize table,repair table）默认是不会记录的
  • log_throttle_queries_not_using_indexes：用于限制每分钟输出未使用索引的日志数量。每分钟允许记录到slow log的且未使用索引的sql语句次数，配合long_queries_not_using_indexes开启使用。
  • log_slow_slave_statements：默认OFF，是否开启主从复制中从库的慢查询
根本原因

一、慢日志写入大致流程


  • dispatch_command(thd)

    • thd->enable_slow_log = true // 初始化enable_slow_log为true
    • thd->set_time // 设置开始时间
    • dispatch_sql_command
    • parse_sql // 语法解析
    • mysql_execute_command // 执行SQL

      • lex->m_sql_cmd->execute // 常见的CRUD操作

    • thd->update_slow_query_status // 判断是否达到慢日志阈值。若为慢查询，则更新thd的server_status状态，为写slow_log作准备
    • log_slow_statement
    • log_slow_applicable // 判断是否写入慢日志

      • log_slow_do // 开始写入

        • slow_log_write

          • log_slow
          • write_slow




二、判断是否达到慢日志阈值


  • 8.0.26版本的慢日志判断标准
  1. void THD::update_slow_query_status() {
  2.   if (my_micro_time() > utime_after_lock + variables.long_query_time)
  3.     server_status | = SERVER_QUERY_WAS_SLOW;
  4. }
  5. // my_micro_time() 获取当前系统时间点，单位为微妙
  6. // utime_after_lock 为MDL LOCK和row lock等待时间后的时间点，单位为微妙
  7. // variables.long_query_time 慢日志阈值long_query_time * 1000000 ，单位为微妙
  8. // 等价于：my_micro_time() - utime_after_lock  > variables.long_query_time
  9. // 不包含锁等待时间
复制代码

  • 8.0.32版本的慢日志判断标准（8.0.28开始）
  1. void THD::update_slow_query_status() {
  2.   if (my_micro_time() > start_utime + variables.long_query_time)
  3.     server_status | = SERVER_QUERY_WAS_SLOW;
  4. }
  5. // 判别标准变成了：（语句执行结束的时间 - 语句开始执行时间） > 慢日志阈值
  6. // my_micro_time() 当前系统时间点，单位为微妙
  7. // start_utime：语句开始执行时间点，单位为微妙
  8. // variables.long_query_time 慢日志阈值long_query_time * 1000000 ，单位为微妙
  9. // 包含锁等待时间
复制代码
从上面可以看出慢日志的判断标准发生了根本变化
举例说明
  1. greatsql> select * from info;
  2. +----+------+
  3. | id | name |
  4. +----+------+
  5. |  1 |    1 |
  6. |  2 |    2 |
  7. |  5 |    5 |
  8. | 60 |    8 |
  9. | 40 |   11 |
  10. | 20 |   20 |
  11. | 30 |   30 |
  12. +----+------+
  13. 7 rows in set (0.05 sec)
  15. greatsql> show create table info\G
  16. *************************** 1. row ***************************
  17.        Table: info
  18. Create Table: CREATE TABLE `info` (
  19.   `id` int NOT NULL AUTO_INCREMENT,
  20.   `name` int NOT NULL,
  21.   PRIMARY KEY (`id`),
  22.   UNIQUE KEY `uk_name` (`name`)
  23. ) ENGINE=InnoDB AUTO_INCREMENT=61 DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_0900_ai_ci
  24. 1 row in set (0.02 sec)
复制代码
session1session2begin;delete from info where id < 10;delete from info where id < 10;session1等待一段时间超过慢日志阈值long_query_timerollback；• 在8.0.26版本中，是不会记录session2中的delete from info where id < 10
• 在8.0.32版本中，会记录session2中的delete from info where id < 10
三、判断是否写入慢日志
  1. void log_slow_statement(THD *thd,
  2.                         struct System_status_var *query_start_status) {
  3.   if (log_slow_applicable(thd)) log_slow_do(thd, query_start_status);
  4. }
  7. //----------------------------------------------------------------
  9. bool log_slow_applicable(THD *thd) {
  10.   DBUG_TRACE;
  12.   /*
  13.     The following should never be true with our current code base,
  14.     but better to keep this here so we don't accidently try to log a
  15.     statement in a trigger or stored function
  16.   */
  17.   if (unlikely(thd->in_sub_stmt)) return false;  // Don't set time for sub stmt
  19.   if (unlikely(thd->killed == THD::KILL_CONNECTION)) return false;
  21.   /*
  22.     Do not log administrative statements unless the appropriate option is
  23.     set.
  24.   */
  25.   if (thd->enable_slow_log && opt_slow_log) {
  26.     bool warn_no_index =
  27.         ((thd->server_status &
  28.           (SERVER_QUERY_NO_INDEX_USED | SERVER_QUERY_NO_GOOD_INDEX_USED)) &&
  29.          opt_log_queries_not_using_indexes &&
  30.          !(sql_command_flags[thd->lex->sql_command] & CF_STATUS_COMMAND));
  31.     bool log_this_query =
  32.         ((thd->server_status & SERVER_QUERY_WAS_SLOW) || warn_no_index) &&
  33.         (thd->get_examined_row_count() >=
  34.          thd->variables.min_examined_row_limit);
  35.     bool suppress_logging = log_throttle_qni.log(thd, warn_no_index);
  37.     if (!suppress_logging && log_this_query) return true;
  38.   }
  39.   return false;
  40. }
复制代码

  • 若log_slow_applicable(thd)返回值为true，则执行log_slow_do(thd, query_start_status)，写入慢日志
  • if (unlikely(thd->in_sub_stmt)) return false;if (unlikely(thd->killed == THD::KILL_CONNECTION)) return false;
​        a. 子查询，返回false
​        b. 被kill，返回false
​        c. 解析出错，返回false
​        d. 执行出错，返回false

  • warn_no_index 表示log_queries_not_using_indexes开启且（未使用索引或未使用最优索引）

    • thd->server_status 该线程状态
    • SERVER_QUERY_NO_INDEX_USED 表示未使用索引
    • SERVER_QUERY_NO_GOOD_INDEX_USED 表示未使用最优索引
    • opt_log_queries_not_using_indexes 表示log_queries_not_using_indexes参数的值，默认OFF

  • !(sql_command_flags[thd->lex->sql_command] & CF_STATUS_COMMAND))表示该语句不是SHOW相关的命令。CF_STATUS_COMMAND常量表示执行的命令为show相关的命令。
  • log_this_query = ((thd->server_status & SERVER_QUERY_WAS_SLOW) || warn_no_index) && (thd->get_examined_row_count() >=thd->variables.min_examined_row_limit);

    • (thd->server_status & SERVER_QUERY_WAS_SLOW) 表示该SQL为慢查询
    • (thd->get_examined_row_count() >=thd->variables.min_examined_row_limit) 表示SQL的扫描数据行数不小于参数min_examined_row_limit 的值，默认为0

  • log_throttle_qni.log(thd, warn_no_index) 表示用来计算该条未使用索引的SQL是否需要写入到slow log，计算需要使用到参数log_throttle_queries_not_using_indexes , 该参数表明允许每分钟写入到slow log中的未使用索引的SQL的数量，默认值为0，表示不限制
按照线上配置

  • log_throttle_queries_not_using_indexes = 0
  • log_queries_not_using_indexes = OFF
  • log_slow_admin_statements = OFF
  • min_examined_row_limit = 0
  • slow_query_log = ON
  • long_query_time = 1.000000
那么在GreatSQL-8.0.26中，是否写入到慢日志中，取决于thd->server_status & SERVER_QUERY_WAS_SLOW，即SQL执行总耗时-SQL锁等待耗时>1秒
那么在GreatSQL-8.0.32中，是否写入到慢日志中，取决于thd->server_status & SERVER_QUERY_WAS_SLOW，即SQL执行总耗时>1秒

Enjoy GreatSQL
来源:https://www.cnblogs.com/greatsql/p/18088776
免责声明：由于采集信息均来自互联网，如果侵犯了您的权益，请联系我们【E-Mail:cb@itdo.tech】 我们会及时删除侵权内容，谢谢合作！

上一篇: 源码解析丨一次慢SQL排查

下一篇: 源码解析丨一次慢SQL排查

发表于 2024-3-22 23:50:41

举报 回复 使用道具

返回列表 发新帖

Archiver|手机版|小黑屋|翼度科技

Copyright © 2001-2020, Tencent Cloud.　Powered by Discuz! X3.4