背景

近期，我遇到了一个技术挑战：通过传输表空间的方式导入一个体积达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的基本用法出发，深入源码层面，分析其实现原理，并探讨案例中的表空间导入操作为何大部分耗时集中在System lock阶段。

SHOW PROFILE 的基本用法

让我们通过一个示例来了解SHOW PROFILE的用法。

# 开启 Profiling
mysql> set profiling=1; Query OK, 0 rows affected, 1 warning (0.00 sec)
# 执行需要分析的 SQL
mysql> select count(*) from slowtech.t1; +----------+ | count(*) | +----------+ | 1048576 | +----------+ 1 row in set (1.09 sec)
# 通过 show profiles 查看 SQL 对应的 Query_ID
mysql> 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_ID
mysql> 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（进程间通信）发送/接受的消息数量、