MySQL源码分析-慢查询

源码版本：MySQL 5.7.22

一条sql语句在MySQL中执行超过一定时间，会被记录为慢查询，慢查询相关的参数有以下几个：

• slow_query_log=1
• long_query_time=0.5
• slow_query_log_file=/mysql/data/mysql_slow.log
• log_queries_not_using_indexes=1
• log_throttle_queries_not_using_indexes=20
• min_examined_row_limit=100
• log_slow_admin_statements=1
• log_slow_slave_statements=1

slow_query_log: 控制是否记录慢查询；
long_query_time: 慢查询阈值，单位秒，执行时间超过这个值的将被记录为慢查询日志中;
slow_query_log_file: 慢查询日志路径；
log_queries_not_using_indexes: 没有使用索引的sql也将被记录到慢查询日志中；
log_throttle_queries_not_using_indexes: 如果log_queries_not_using_indexes打开，没有使用索引的sql将会写入到慢查询日志中，该参数将限制每分钟写入的sql数量；
min_examined_row_limit: 对于查询扫描行数小于此参数的sql，将不会记录到慢查询日志中；
log_slow_admin_statements: 管理语句执行时间大于阈值也将写入到慢查询日志中，管理语句包括alter table, check table等等；
log_slow_slave_statements: 从库应用binlog，如果binlog格式是statement，执行时间超过阈值时，将写入从库的慢查询日志， 对于ROW格式binlog，不管执行时间有没有超过阈值，都不会写入到从库的慢查询日志。

线索一：long_query_time变量

根据慢查询相关参数，在源码中搜索long_query_time，源码中肯定有执行时间大于这个值，就记为慢查询的相关代码逻辑，搜索到一段代码如下：

//sql/sql_class.h 3279行
void update_server_status()
  {
    ulonglong end_utime_of_query= current_utime();
    if (end_utime_of_query > utime_after_lock + variables.long_query_time)
      server_status|= SERVER_QUERY_WAS_SLOW;
  }

这段代码里的if条件是 end_utime_of_query > utime_after_lock + variables.long_query_time， 我们稍微变换一下：
end_utime_of_query - utime_after_lock > variables.long_query_time

end_utime_of_query 为sql执行完取到的当前时间，单位微秒；
utime_after_lock 为sql执行期间锁等待的时间，也就是说MySQL慢查询并不把锁等待的时间算在里面，每次执行sql前，会通过thd->set_time()将该变量重置为当前时间，单位微秒；
variables.long_query_time 为慢查询阈值。

线索二：update_server_status函数

update_server_status函数是THD类的成员函数，utime_after_lock 为THD类的成员变量，下面是THD类的定义简化示意：

//sql/sql_class.h
class THD :public MDL_context_owner,
           public Query_arena,
           public Open_tables_state
{
...
    public:
      ulonglong  start_utime, utime_after_lock;
...
    public:
    void update_server_status()
      {
        ulonglong end_utime_of_query= current_utime();
        if (end_utime_of_query > utime_after_lock +  variables.long_query_time)
          server_status|= SERVER_QUERY_WAS_SLOW;

      }
...
};

下面来看一下update_server_status这个THD的成员函数，什么时候被调用。MySQL 是Server/Engine 架构， 慢查询相关逻辑在Server层进行处理，先看一下MySQL执行一条sql的函数调用栈，如下：

main                //main.cc
mysqld_main         //mysqld.cc
mysqld_socket_acceptor->connection_event_loop    //mysqld.cc
Connection_handler_manager::process_new_connection(Channel_info* channel_info)  //connection_handler_manager.cc
Per_thread_connection_handler::add_connection(Channel_info* channel_info)  //connection_handler_per_thread.cc
handle_connection        //connection_handler_per_thread.cc
do_command               //sql_parse.cc
dispatch_command         //sql_parse.cc
mysql_parse              //sql_parse.cc
mysql_execute_command    //sql_parse.cc
...

在源码中搜索update_server_status， 在dispatch_command函数中，看到如下一段代码逻辑，简化后如下：

// sql/sql_parse.cc
bool dispatch_command(THD *thd, const COM_DATA *com_data,
                      enum enum_server_command command)
{
    thd->set_time();
    mysql_parse(thd, &parser_state);
    thd->update_server_status();
    thd->send_statement_status();
    log_slow_statement(thd);
}

其中
thd->set_time() 对utime_after_lock进行了重置，重置后的值为当前时间，单位是微秒，后面附thd->set_time()函数的具体实现。
mysql_parse(thd, &parser_state) 为sql执行的具体实现，包括调用引擎层的接口，向客户端发送查询结果数据等。
thd->update_server_status() 判断执行时间是否大于设置的慢查询阈值，如果大于慢查询阈值，设置server_status|= SERVER_QUERY_WAS_SLOW
thd->send_statement_status() 发送sql语句执行状态
log_slow_statement(thd) 根据thd->server_status 是否包含 SERVER_QUERY_WAS_SLOW 标志，决定是否写入慢查询日志

线索三：utime_after_lock

另外一个问题，utime_after_lock 这个值应该是不断改变的，因为它记录了锁等待的时间，代码中哪里修改了这个变量值呢？继续搜索代码，发现这么一个函数：

// sql/sql_class.cc
extern "C"
void thd_storage_lock_wait(THD *thd, long long value)
{
  thd->utime_after_lock+= value;
}

这段代码由引擎层调用，引擎层遇到锁等待时，调用这个函数，修改thd->utime_after_lock 变量的值

总结：

至此，MySQL在Server层判断一个sql执行是否属于慢查询的逻辑变得清晰了，总结分以下几步：
（1）sql执行前，通过thd->set_time()函数，记录当前时间（微秒）到 utime_after_lock
（2）sql执行过程中，引擎层遇到锁等待，将等待的时间（微秒）通过thd_storage_lock_wait函数调用，加到utime_after_lock变量上
（3）sql执行完，再次记录当前时间（微秒）到end_utime_of_query， 通过 判断 （end_utime_of_query - utime_after_lock > variables.long_query_time）这个if条件，来决定是否记录到慢查询日志。

附相关函数：

// sql/sql_class.h  THD成员函数
inline void set_time()
  {
    start_utime= utime_after_lock= my_micro_time();
    if (user_time.tv_sec || user_time.tv_usec)
    {
      start_time= user_time;
    }
    else
      my_micro_time_to_timeval(start_utime, &start_time);
#ifdef HAVE_PSI_THREAD_INTERFACE
    PSI_THREAD_CALL(set_thread_start_time)(start_time.tv_sec);
#endif
  }

// sql/sql_class.h   THD成员函数current_utime，实际调用的还是my_micro_time
ulonglong current_utime()  { return my_micro_time(); }

// my_getsystime.c
ulonglong my_micro_time()
{
#ifdef _WIN32
  ulonglong newtime;
  my_get_system_time_as_file_time((FILETIME*)&newtime);
  newtime-= OFFSET_TO_EPOCH;
  return (newtime/10);
#else
  ulonglong newtime;
  struct timeval t;
  /*
    The following loop is here because gettimeofday may fail on some  systems
  */
  while (gettimeofday(&t, NULL) != 0)
  {}
  newtime= (ulonglong)t.tv_sec * 1000000 + t.tv_usec;
  return newtime;
#endif
}