源码版本：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
}
