背景

近期，我遇到了一个案例，涉及到通过可传输表空间的方式导入一个体积达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（进程间通信）发送/接收的消息数量、页面故障次数