MySQL · 源码分析 · store procedure记录了过多的slow_log的问题详解

Author: 张旭明(玄旭)

背景

最近遇到一个问题，深入把mysql的slow_log又研究了一遍，给大家分享一下。 问题的现象如下：

  1. slow log中记录了store procedure中执行的全部SQL
  2. store procedure执行时间小于long_query_time，内部执行的SQL也全部被记录到了slow log中
  3. store procedure中create temporary命令记录在slow log中的信息显示，随着多次执行，执行时间和扫描行数都在增长

深入研究代码后，找到了复现方法， 复现用例详见附录，感兴趣的可以自己试一下。

下面是call sp1和call sp2后，slow log的内容：

slow_log

从图中可以看到，对于sp1来说，slow log只记录了call sp1这一条记录，对于sp2来说，则记录了存储过程执行的全部内容，同时rows_examined和执行时间与当条SQL的实际情况不一致。

slow_log机制

mysql.slow_log表结构

mysql.slow_log建表语句


1. CREATE TABLE `slow_log` (
2. `start_time` timestamp(6) NOT NULL DEFAULT CURRENT_TIMESTAMP(6) ON UPDATE CURRENT_TIMESTAMP(6),
3. `user_host` mediumtext NOT NULL,
4. `query_time` time(6) NOT NULL,
5. `lock_time` time(6) NOT NULL,
6. `rows_sent` int(11) NOT NULL,
7. `rows_examined` int(11) NOT NULL,
8. `db` varchar(512) NOT NULL,
9. `last_insert_id` int(11) NOT NULL,
10. `insert_id` int(11) NOT NULL,
11. `server_id` int(10) unsigned NOT NULL,
12. `sql_text` mediumblob NOT NULL,
13. `thread_id` bigint(21) unsigned NOT NULL
14. ) ENGINE=CSV DEFAULT CHARSET=utf8 COMMENT='Slow log'
Field Comments
start_time SQL语句执行完写slow log的时间
user_host 执行SQL语句的用户和主机名
query_time SQL语句的执行时间，不包括锁等待时间
lock_time 执行SQL语句前，等待锁的时间
rows_sent SQL语句返回的结果集行数, thd->get_sent_row_count()
rows_examined SQL聚集执行时扫描的行数, thd->get_examined_row_count()
db 执行SQL语句的库名
last_insert_id thd->stmt_depends_on_first_successful_insert_id_in_prev_stmt
insert_id thd->auto_inc_intervals_in_cur_stmt_for_binlog
server_id 服务器ID
sql_text 执行的SQL语句
thread_id 执行SQL的线程ID

主要列内容的产生方法

1. start_time

start_time实际上写入的是函数bool Log_to_csv_event_handler::log_slow的参数current_time


1. // In function
2. bool Log_to_csv_event_handler::log_slow(……) {
3. ……
4. /* store the time and user values */
5. assert(table->field[SQLT_FIELD_START_TIME]->type() == MYSQL_TYPE_TIMESTAMP);
6. ull2timeval(current_utime, &tv);
7. table->field[SQLT_FIELD_START_TIME]->store_timestamp(&tv);
8. ……
9. }

current_time是在下面的函数中获取并传给log_slow方法


1. bool Query_logger::slow_log_write() {
2. ……
3. ulonglong current_utime = my_micro_time();
4. ……
5. for (Log_event_handler **current_handler = slow_log_handler_list;
6. *current_handler;) {
7. error |= (*current_handler++)
8. ->log_slow(thd, current_utime,
9. (thd->start_time.tv_sec * 1000000ULL) +
10. thd->start_time.tv_usec,
11. user_host_buff, user_host_len, query_utime,
12. lock_utime, is_command, query, query_length);
13. }
14. ……
15. }

2. query_time和lock_time

query_time和lock_time的产生方法


1. bool Query_logger::slow_log_write() {
2. ……
3. query_utime = (current_utime - thd->start_utime);
4. lock_utime = thd->get_lock_usec();
5. ……
6. }

3. SQL执行过程中slow_log相关变量的变化过程和写入slow_log的时机


1. dispatch_command(thd)                     // 开始执行SQL
2. -> ……
3. -> thd->enable_slow_log = true;           // 初始化enable_slow_log为true
4. -> thd->set_time()
5. -> ……
6. -> start_utime = my_micro_time();      // 设置sql开始执行的时间
7. -> ……
8. -> dispatch_sql_command(thd)
9. -> mysql_reset_thd_for_next_command(thd)
10. -> thd->reset_for_next_command()
11. -> ……
12. -> thd->m_sent_row_count = thd->m_examined_row_count = 0;
13. -> ……
14. -> parse_sql(thd)                      // 语法解析
15. -> mysql_execute_command(thd)          // 执行SQL
16. -> ……
17. -> thd->update_slow_query_status()        // 更新状态，为写slow_log作准备
18. -> 如果SQL执行时间超过了long_query_time， server_status |= SERVER_QUERY_WAS_SLOW
19. -> 这里用了当前时间和start_utime的差值进行比较，判断超过long_query_time的时间包括query_time和lock_time
20. -> log_slow_statement(thd)                // 写slow_log入口
21. -> if (log_slow_applicable(thd))       // 判断当前查询是否需要记录到slow_log中
22. log_slow_do(thd)                  // 当前查询记录到slow_log中
23. -> ……

4. 存储过程和slow_log相关的逻辑

下面的流程只表示了存储过程执行SQL的主要调用链，不包含其他类型的语句


1. mysql_execute_command
2. ->  Sql_cmd_dml::execute()
3. -> Sql_cmd_call::execute_inner()
4. -> sp_head::execute_procedure
5. -> 如果thd->enable_slow_log == true并且不是在event中调用
6. save_enable_slow_log = true
7. thd->enable_slow_log = false               // 在存储过程中临时关闭slow log
8. -> sp_head::execute
9. 循环对存储过程中的每一条SQL执行
10. -> sp_instr_stmt::execute
11. -> sp_instr_stmt::validate_lex_and_execute_core
12. -> sp_lex_instr::reset_lex_and_exec_core
13. -> sp_instr_stmt::exec_core
14. -> mysql_execute_command
15. -> thd->update_slow_query_status()
16. -> if (log_slow_applicable(thd))
17. log_slow_do(thd)
18. -> 如果save_enable_slow_log == true， thd->enable_slow_log = ture   // 恢复enable_slow_log状态

可以看到在存储过程执行开始的时候，会将线程的enable_slow_log开关关闭，执行完成后，会再打开

5. log_slow_applicable逻辑

  1. 子查询/被kill/执行出错/解析出错，返回false

  2. set warn_no_index = 下面3个条件的与值

  3. thd->server_statu & (SERVER_QUERY_NO_INDEX_USED | SERVER_QUERY_NO_GOOD_INDEX_USED )

查询包含JT_ALL的表或包含动态range scan的表

  1. log_queries_not_using_indexe = true
  2. !(sql_command_flags[thd->lex->sql_command] & CF_STATUS_COMMAND)

根据sql_command_flags的设置的值，这个条件表明SQL不是SHOW相关的命令 3. set log_this_query = 下面2个条件的与值

  1. (thd->server_status & SERVER_QUERY_WAS_SLOW) || warn_no_index

    查询是慢查询或warn_no_index为true 2. thd->get_examined_row_count() >= thd->variables.min_examined_row_limit SQL的扫描数据行数不小于变量min_examined_row_limit的值 4. 如果slow log没有开启，返回false thd->enable_slow_log == false || opt_slow_log 5. set suppress_logging = log_throttle_qni.log(thd, warn_no_index)

log_throttle_qni.log(thd, warn_no_index) 用来计算该条未使用索引的SQL是否需要写入到slow_log，计算需要使用到参数log_throttle_queries_not_using_indexes , 该参数表明允许每分钟写入到slow_log中的未使用索引的SQL的数量，0表示不限制 6. 如果 suppress_logging == false 并且 log_this_query == true 返回true， 表示需要记录slow_log

6. log_slow_admin_statements 干了什么

根据官方文档说明，这个开关表示需要记录执行慢的admin语句，从代码上可以看到，admin语句包含了下面的SQL


1. check table xxx;
2. analyze table xxx;
3. optimize table xxx;
4. repair table xxx;
5. create index ....;
6. drop index ...;

相关功能代码execute方法中，会在执行命令之前，执行： thd->enable_slow_log = opt_log_slow_admin_statements

执行完成后，并没有恢复 thd->enable_slow_log 的值

问题发生的实际原因

根据以上的信息，我们可以总结出问题发生的根本原因

  1. 存储过程中包含的analyze table命令，导致执行存储过程时，被关闭的thd->enable_slow_log，又被打开了
  2. 存储过程执行中，并不会reset start_utime和examined_rows，只有在存储过程开始执行的时候会reset, 存储过程中每条查询SQL都会导致examined_rows的值进行增长，SQL记录slow_log时计算查询时间的方法是跟start_utime进行比较，会导致存储过程中每条SQL记录到slow_log的查询时间一直在增加
  3. log_queries_not_using_indexe = on，导致记录存储过程中执行SQL的慢日志检查时，不检查实际执行时间，忽略了long_query_time的限制

总结

mysql slow_log不是简单的打开开关slow_query_log，设置long_query_time就可以了，通过这个问题分析，我们可以更了解mysql slow_log的工作原理，以便我们在分析数据库慢查询问题的过程中更好的使用mysql slow_log。

下表是对slow log相关变量的总结说明

变量 说明
slow_query_log slow log总开关，全局变量
log_output 记录日志的方式，取值范围TABLE或FILE，如果是TABLE，slow log记录在系统表 mysql.slow_log中，如果是FILE记录在文件中，文件路径由参数slow_query_log_file指定
slow_query_log_file FILE方式记录slow log时保存文件的路径
long_query_time 记录slow log的时间阈值，单位是秒，最小0， 最大 31536000 (365天)
log_slow_admin_statements admin sql 是否记录慢日志，默认是OFF
min_examined_row_limit 记录慢日志的SQL的最小扫描行数，小于该值的SQL不会记录到慢日志
log_queries_not_using_indexe 查询包含未使用索引的表(JT_ALL)，或使用动态range scan的表时，是否记录SQL到慢日志，开启这个开关后，检查是否记录慢SQL时会忽略执行时间的检查结果
log_throttle_queries_not_using_indexes 每分钟记录到慢日志中未使用索引的查询语句的数量，0 表示不限制，超过改数量的SQL不会写入到慢日志

参考

[1] MySQL Source Code

附录

1. 复现用例


1. set global log_queries_not_using_indexes =on;
2. set global log_slow_admin_statements = on;
3. set global slow_query_log = on;
4. set long_query_time = 10000;

6. create table t1(a1 int);
7. insert into t1 values(1);
8. insert into t1 values(2);
9. insert into t1 values(3);
10. insert into t1 values(4);
11. insert into t1 values(5);

14. delimiter //
15. create procedure sp1()
16. begin
17. set @i = 0;
18. while @i < 5 DO
19. drop temporary table if exists t1_tmp0;
20. create temporary table t1_tmp0 (a1 int);
21. insert into t1_tmp0 select * from t1;
22. select * from t1_tmp0;
23. set @i=@i+1;
24. END while;
25. end //

27. create procedure sp2()
28. begin
29. analyze table t1;
30. set @i = 0;
31. while @i < 5 DO
32. drop temporary table if exists t1_tmp0;
33. create temporary table t1_tmp0 (a1 int);
34. insert into t1_tmp0 select * from t1;
35. select * from t1_tmp0;
36. set @i=@i+1;
37. END while;
38. end //

40. delimiter ;

42. truncate mysql.slow_log;
43. select * from mysql.slow_log;
44. call sp1;
45. select * from mysql.slow_log;
46. call sp2;
47. select * from mysql.slow_log;

原文：http://mysql.taobao.org/monthly/2023/09/01/