最近碰到一个 case，通过可传输表空间的方式导入一个 4GB 大小的表，耗时 13 分钟。
通过PROFILE定位，发现大部分耗时竟然是在System lock阶段。
mysql> set profiling=1;Query OK, 0 rows affected, 1 warning (0.00 sec)
mysql> alter table sbtest2 import tablespace;Query OK, 0 rows affected (13 min 8.99 sec)
mysql> show profile for query 1;+| Status | Duration |+| starting | 0.000119 || Executing hook on
transaction | 0.000004 || starting | 0.000055 || checking permissions | 0.000010 || discard_or_import_tablespace | 0.000007 || Opening tables | 0.000156 || System lock | 788.966338 || end | 0.007391 || waiting for handler commit | 0.000041 || waiting for handler commit | 0.011179 || query end | 0.000022 || closing tables | 0.000019 || waiting for handler commit | 0.000031 || freeing items | 0.000035 || cleaning up | 0.000043 |+15 rows in set, 1 warning (0.03 sec)
不仅如此，SQL 在执行的过程中，show processlist中的状态显示的也是System lock。
mysql> show processlist;+| Id | User | Host | db | Command | Time | State | Info |+| 5 | event_scheduler | localhost | NULL | Daemon | 818 | Waiting on empty queue | NULL || 10 | root | localhost | sbtest | Query | 648 | System lock | alter table sbtest2 import tablespace || 14 | root | localhost | NULL | Query | 0 | init | show processlist |+3 rows in set, 1 warning (0.00 sec)
这个状态其实有很大的误导性。
接下来我们从SHOW PROFILE的基本用法出发，从源码角度分析它的实现原理。
最后在分析的基础上，看看 case 中的表空间导入操作为什么大部分耗时是在System lock阶段。
下面通过一个示例来看看SHOW PROFILE的用法。
# 开启 Profilingmysql> set profiling=1;Query OK, 0 rows affected, 1 warning (0.00 sec)# 执行需要分析的 SQLmysql> select count(*) from slowtech.t1;+| count(*) |+| 1048576 |+1 row in set (1.09 sec)# 通过 show profiles 查看 SQL 对应的 Query_IDmysql> show profiles;+| Query_ID | Duration | Query |+| 1 | 1.09378600 | select count(*) from slowtech.t1 |+1 row in set, 1 warning (0.00 sec)# 查看该 SQL 各个阶段的执行耗时情况，其中，1 是该 SQL 对应的 Query_IDmysql> show profile for query 1;+| Status | Duration |+| starting | 0.000157 || Executing hook on transaction | 0.000009 || starting | 0.000020 || checking permissions | 0.000012 || Opening tables | 0.000076 || init | 0.000011 || System lock | 0.000026 || optimizing | 0.000013 || statistics | 0.000033 || preparing | 0.000032 || executing | 1.093124 || end | 0.000025 |
| query end | 0.000013 || waiting for handler commit | 0.000078 || closing tables | 0.000048 || freeing items | 0.000076 || cleaning up | 0.000037 |+17 rows in set, 1 warning (0.01 sec)
如果指定 all 还会输出更详细的统计信息，包括 CPU、上下文切换、磁盘IO、IPC（进程间通信）发送/接受的消息数量、页面故障次数、交换次数等。
需要注意的是，这里的统计信息是针对整个进程的，不是单个 SQL 的。如果在执行上述 SQL 的同时还有其它 SQL 在执行，那么这些数据就不能用来评估该 SQL 的资源使用情况。
mysql> show profile all for query 1\G...*************************** 11. row *************************** Status: executing Duration: 0.825417 CPU_user: 1.486951 CPU_system: 0.007982 Context_voluntary: 0Context_involuntary: 553 Block_ops_in: 0 Block_ops_out: 0 Messages_sent: 0 Messages_received: 0 Page_faults_major: 0 Page_faults_minor: 24 Swaps: 0 Source_function: ExecuteIteratorQuery Source_file: sql_union.cc Source_line: 1678...17 rows in set, 1 warning (0.00 sec)
SHOW PROFILE 主要是在sql_profile.cc中实现的。它的实现主要分为两部分：
下面我们分别从这两个维度来看看 SHOW PROFILE 的实现原理。
数据的采集实际上是通过“埋点”实现的。不同阶段对应的“埋点”地址可通过show profile source查看。
mysql> show profile source for query 1;+| Status | Duration | Source_function | Source_file | Source_line |+| starting | 0.000157
| NULL | NULL | NULL || Executing hook on transaction | 0.000009 | launch_hook_trans_begin | rpl_handler.cc | 1484 || starting | 0.000020 | launch_hook_trans_begin | rpl_handler.cc | 1486 || checking permissions | 0.000012 | check_access | sql_authorization.cc | 2173 || Opening tables | 0.000076 | open_tables | sql_base.cc | 5911 || init | 0.000011 | execute | sql_select.cc | 760 || System lock | 0.000026 | mysql_lock_tables | lock.cc | 332 || optimizing | 0.000013 | optimize | sql_optimizer.cc | 379 || statistics | 0.000033 | optimize | sql_optimizer.cc | 721 || preparing | 0.000032 | optimize | sql_optimizer.cc | 806 || executing | 1.093124 | ExecuteIteratorQuery | sql_union.cc | 1677 || end | 0.000025 | execute | sql_select.cc | 796 || query end | 0.000013 | mysql_execute_command | sql_parse.cc | 4896 || waiting for handler commit | 0.000078 | ha_commit_trans | handler.cc | 1636 || closing tables | 0.000048 | mysql_execute_command | sql_parse.cc | 4960 || freeing items | 0.000076 | dispatch_sql_command | sql_parse.cc | 5434 || cleaning up | 0.000037 | dispatch_command | sql_parse.cc | 2478 |+17 rows in set, 1 warning (0.00 sec)
以executing为例，它对应的“埋点”地址是sql_union.cc文件的第 1677 行，该行对应的代码是：
THD_STAGE_INFO(thd, stage_executing);
其它的“埋点”地址也类似，调用的都是THD_STAGE_INFO，唯一不一样的是 stage 的名称。
THD_STAGE_INFO 主要会做两件事情：
下面我们结合代码看看具体的实现细节。
void QUERY_PROFILE::new_status(const char *status_arg, const char *function_arg, const char *file_arg, unsigned int line_arg) { PROF_MEASUREMENT *prof; ... if ((function_arg != nullptr) && (file_arg != nullptr)) prof = new PROF_MEASUREMENT(this, status_arg, function_arg, base_name(file_arg), line_arg); else prof = new PROF_MEASUREMENT(this, status_arg); prof->m_seq = m_seq_counter++; m_end_time_usecs = prof->time_usecs; entries.push_back(prof); ...}
继续分析PROF_MEASUREMENT的初始化逻辑。
PROF_MEASUREMENT::PROF_MEASUREMENT(QUERY_PROFILE *profile_arg, const char *status_arg, const char *function_arg, const char *file_arg, unsigned int line_arg) : profile(profile_arg) { collect(); set_label(status_arg, function_arg, file_arg, line_arg);}void PROF_MEASUREMENT::collect() { time_usecs = (double)my_getsystime() / 10.0; #ifdef HAVE_GETRUSAGE getrusage(RUSAGE_SELF, &rusage);#elif defined(_WIN32) ...#endif}
PROF_MEASUREMENT 在初始化时会调用collect函数，collect()函数非常关键，它会做两件事情：
getrusage是一个用于获取进程或线程资源使用情况的系统调用。它返回进程在执行期间所消耗的资源信息，包括 CPU 时间、内存使用、页面故障、上下文切换等信息。
PROF_MEASUREMENT 初始化完毕后，会将其添加到 entries 中。entries 是一个队列（Queue entries）。这个队列，会在执行show profile for query N或者information_schema.profiling时用到。
说完数据的采集，接下来我们看看数据的计算，毕竟“埋点”收集的只是系统当前时间，而我们在show profile for query N中看到的Duration 是一个时长。
当我们在执行show profile for query N时，实际上查询的是information_schema.profiling，此时，会调用PROFILING::fill_statistics_info来填充数据。
下面我们看看该函数的实现逻辑。
int PROFILING::fill_statistics_info(THD *thd_arg, Table_ref *tables) { DBUG_TRACE; TABLE *table = tables->table; ulonglong row_number = 0; QUERY_PROFILE *query; void *history_iterator; for (history_iterator = history.new_iterator(); history_iterator != nullptr; history_iterator = history.iterator_next(history_iterator)) { query = history.iterator_value(history_iterator); ulong seq; void *entry_iterator; PROF_MEASUREMENT *entry, *previous = nullptr; for (entry_iterator = query->entries.new_iterator(); entry_iterator != nullptr; entry_iterator = query->entries.iterator_next(entry_iterator), previous = entry, row_number++) { entry = query->entries.iterator_value(entry_iterator); seq = entry->m_seq; if (previous == nullptr) continue; if (thd_arg->lex->sql_command == SQLCOM_SHOW_PROFILE) { if (thd_arg->lex->show_profile_query_id == 0) { if (query != last) continue; } else { if (thd_arg->lex->show_profile_query_id != query->profiling_query_id) continue; } } restore_record(table, s->default_values); table->field[0]->store((ulonglong)query->profiling_query_id, true); table->field[1]->store((ulonglong)seq, true); table->field[2]->store(previous->status, strlen(previous->status), system_charset_info); my_decimal duration_decimal; double2my_decimal( E_DEC_FATAL_ERROR, (entry->time_usecs - previous->time_usecs) / (1000.0 * 1000), &duration_decimal); table->field[3]->store_decimal(&duration_decimal);#ifdef HAVE_GETRUSAGE my_decimal cpu_utime_decimal, cpu_stime_decimal;
double2my_decimal( E_DEC_FATAL_ERROR, RUSAGE_DIFF_USEC(entry->rusage.ru_utime, previous->rusage.ru_utime) / (1000.0 * 1000), &cpu_utime_decimal); ... table->field[4]->store_decimal(&cpu_utime_decimal);... return 0;}
可以看到，information_schema.profiling中的第三列（STATE，对应 show profile for query N 中的 Status）存储的是上一条记录的 status（阶段名），而第四列（DURATION）的值等于当前记录的采集时间（entry->time_usecs）减去上一条记录的采集时间（previous->time_usecs）。
所以，我们在show profile for query N中看到的 Duration 实际上通过下一个阶段的采集时间减去当前阶段的采集时间得到的，并不是show profile source中函数（Source_function）的执行时长。
这种实现方式在判断操作当前状态和分析各个阶段耗时时存在一定的误导性。
回到开头的 case。
表空间导入操作是在mysql_discard_or_import_tablespace函数中实现的。
下面是该函数简化后的代码。
bool Sql_cmd_discard_import_tablespace::mysql_discard_or_import_tablespace( THD *thd, Table_ref *table_list) { ... THD_STAGE_INFO(thd, stage_discard_or_import_tablespace); ... if (open_and_lock_tables(thd, table_list, 0, &alter_prelocking_strategy)) { return true; } ... const bool discard = (m_alter_info->flags & Alter_info::ALTER_DISCARD_TABLESPACE); error = table_list->table->file->ha_discard_or_import_tablespace(discard, table_def); THD_STAGE_INFO(thd, stage_end); ... return true;}
可以看到，该函数实际调用的是 THD_STAGE_INFO(thd, stage_discard_or_import_tablespace)。
只不过，在调用 THD_STAGE_INFO(thd, stage_discard_or_import_tablespace) 后，调用了 open_and_lock_tables。
而 open_and_lock_tables 最后会调用 THD_STAGE_INFO(thd, stage_system_lock)。
这也就是为什么上述函数中虽然调用了 THD_STAGE_INFO(thd, stage_discard_or_import_tablespace)，但show profile和show processlist的输出中却显示System lock。
但基于对耗时的分析，我们发现这么显示其实并不合理。
在开头的 case 中，虽然System lock阶段显示的耗时是 788.966338 秒，但实际上open_and_lock_tables这个函数只消耗了 0.000179 秒，真正的耗时是来自 table_list->table->file->ha_discard_or_import_tablespace，其执行时间长达 788.965481 秒。
为什么这个函数需要执行这么久呢？主要是表空间在导入的过程中会检查并更新表空间中的每个页，包括验证页是否损坏、更新表空间 ID 和 LSN、处理 Btree 页（如设置索引 ID、清除 delete marked 记录等）、将页标记为脏页等。表越大，检查校验的时候会越久。
如此来看，针对表空间导入操作，将其状态显示为discard_or_import_tablespace更能反映操作的真实情况。
在SHOW PROFILE中显示的每个阶段的耗时，实际上是由下一个阶段的采集时间减去当前阶段的采集时间得出的。
每个阶段的采集时间是通过在代码的不同路径中植入 THD_STAGE_INFO(thd, stage_xxx) 实现的，采集的是系统当前时间。
这种实现方式在判断操作当前状态（通过 SHOW PROCESSLIST）和分析各个阶段耗时（通过 SHOW PROFILE ）时存在一定的误导性，主要是因为预定义的阶段数量是有限的。
在 MySQL 8.4 中，共定义了 98 个阶段，具体的阶段名可在mysqld.cc中的all_server_stages数组找到。
在表空间导入操作中，虽然大部分耗时显示为System lock阶段，但实际上，使用discard_or_import_tablespace来描述这一过程会更为准确。
