MySQL 优化利器 SHOW PROFILE 的实现原理

背景

近来碰到一个 case，通过可传输表空间的方式导入一个 4GB 大小的表，耗时 13 分钟。
通过PROFILE定位，发现大部门耗时竟然是在System lock阶段。

1. mysql> set profiling=1;
   
2. Query OK, 0 rows affected, 1 warning (0.00 sec)
   
3. 
   
4. mysql> alter table sbtest2 import tablespace;
   
5. Query OK, 0 rows affected (13 min 8.99 sec)
   
6. 
   
7. mysql> show profile for query 1;
   
8. +--------------------------------+------------+
   
9. | Status                         | Duration   |
   
10. +--------------------------------+------------+
    
11. | starting                       |   0.000119 |
    
12. | Executing hook on transaction  |   0.000004 |
    
13. | starting                       |   0.000055 |
    
14. | checking permissions           |   0.000010 |
    
15. | discard_or_import_tablespace   |   0.000007 |
    
16. | Opening tables                 |   0.000156 |
    
17. | System lock                    | 788.966338 |
    
18. | end                            |   0.007391 |
    
19. | waiting for handler commit     |   0.000041 |
    
20. | waiting for handler commit     |   0.011179 |
    
21. | query end                      |   0.000022 |
    
22. | closing tables                 |   0.000019 |
    
23. | waiting for handler commit     |   0.000031 |
    
24. | freeing items                  |   0.000035 |
    
25. | cleaning up                    |   0.000043 |
    
26. +--------------------------------+------------+
    
27. 15 rows in set, 1 warning (0.03 sec)

复制代码

不仅云云，SQL 在实行的过程中，show processlist中的状态显示的也是System lock。

1. mysql> show processlist;
   
2. +----+-----------------+-----------+--------+---------+------+------------------------+---------------------------------------+
   
3. | Id | User            | Host      | db     | Command | Time | State                  | Info                                  |
   
4. +----+-----------------+-----------+--------+---------+------+------------------------+---------------------------------------+
   
5. |  5 | event_scheduler | localhost | NULL   | Daemon  |  818 | Waiting on empty queue | NULL                                  |
   
6. | 10 | root            | localhost | sbtest | Query   |  648 | System lock            | alter table sbtest2 import tablespace |
   
7. | 14 | root            | localhost | NULL   | Query   |    0 | init                   | show processlist                      |
   
8. +----+-----------------+-----------+--------+---------+------+------------------------+---------------------------------------+
   
9. 3 rows in set, 1 warning (0.00 sec)

复制代码

这个状态其实有很大的误导性。
接下来我们从SHOW PROFILE的根本用法出发，从源码角度分析它的实现原理。
最后在分析的基础上，看看 case 中的表空间导入操作为什么大部门耗时是在System lock阶段。
SHOW PROFILE 的根本用法

下面通过一个示例来看看SHOW PROFILE的用法。

1. # 开启 Profiling
   
2. mysql> set profiling=1;
   
3. Query OK, 0 rows affected, 1 warning (0.00 sec)
   
4. 
   
5. # 执行需要分析的 SQL
   
6. mysql> select count(*) from slowtech.t1;
   
7. +----------+
   
8. | count(*) |
   
9. +----------+
   
10. |  1048576 |
    
11. +----------+
    
12. 1 row in set (1.09 sec)
    
13. 
    
14. # 通过 show profiles 查看 SQL 对应的 Query_ID
    
15. mysql> show profiles;
    
16. +----------+------------+----------------------------------+
    
17. | Query_ID | Duration   | Query                            |
    
18. +----------+------------+----------------------------------+
    
19. |        1 | 1.09378600 | select count(*) from slowtech.t1 |
    
20. +----------+------------+----------------------------------+
    
21. 1 row in set, 1 warning (0.00 sec)
    
22. 
    
23. # 查看该 SQL 各个阶段的执行耗时情况，其中，1 是该 SQL 对应的 Query_ID
    
24. mysql> show profile for query 1;
    
25. +--------------------------------+----------+
    
26. | Status                         | Duration |
    
27. +--------------------------------+----------+
    
28. | starting                       | 0.000157 |
    
29. | Executing hook on transaction  | 0.000009 |
    
30. | starting                       | 0.000020 |
    
31. | checking permissions           | 0.000012 |
    
32. | Opening tables                 | 0.000076 |
    
33. | init                           | 0.000011 |
    
34. | System lock                    | 0.000026 |
    
35. | optimizing                     | 0.000013 |
    
36. | statistics                     | 0.000033 |
    
37. | preparing                      | 0.000032 |
    
38. | executing                      | 1.093124 |
    
39. | end                            | 0.000025 |
    
40. | query end                      | 0.000013 |
    
41. | waiting for handler commit     | 0.000078 |
    
42. | closing tables                 | 0.000048 |
    
43. | freeing items                  | 0.000076 |
    
44. | cleaning up                    | 0.000037 |
    
45. +--------------------------------+----------+
    
46. 17 rows in set, 1 warning (0.01 sec)

复制代码

如果指定 all 还会输出更详细的统计信息，包罗 CPU、上下文切换、磁盘IO、IPC（进程间通信）发送/担当的消息数量、页面故障次数、交换次数等。
需要注意的是，这里的统计信息是针对整个进程的，不是单个 SQL 的。如果在实行上述 SQL 的同时还有其它 SQL 在实行，那么这些数据就不能用来评估该 SQL 的资源利用情况。

1. mysql> show profile all for query 1\G
   
2. ...
   
3. *************************** 11. row ***************************
   
4.              Status: executing
   
5.            Duration: 0.825417
   
6.            CPU_user: 1.486951
   
7.          CPU_system: 0.007982
   
8.   Context_voluntary: 0
   
9. Context_involuntary: 553
   
10.        Block_ops_in: 0
    
11.       Block_ops_out: 0
    
12.       Messages_sent: 0
    
13.   Messages_received: 0
    
14.   Page_faults_major: 0
    
15.   Page_faults_minor: 24
    
16.               Swaps: 0
    
17.     Source_function: ExecuteIteratorQuery
    
18.         Source_file: sql_union.cc
    
19.         Source_line: 1678
    
20. ...
    
21. 17 rows in set, 1 warning (0.00 sec)

复制代码

SHOW PROFILE 的实现原理

SHOW PROFILE 主要是在sql_profile.cc中实现的。它的实现主要分为两部门：

• 数据的采集。
  
• 数据的计算。
  

下面我们分别从这两个维度来看看 SHOW PROFILE 的实现原理。
数据的采集

数据的采集实际上是通过“埋点”实现的。不同阶段对应的“埋点”地址可通过show profile source检察。

1. mysql> show profile source for query 1;
   
2. +--------------------------------+----------+-------------------------+----------------------+-------------+
   
3. | Status                         | Duration | Source_function         | Source_file          | Source_line |
   
4. +--------------------------------+----------+-------------------------+----------------------+-------------+
   
5. | starting                       | 0.000157 | NULL                    | NULL                 |        NULL |
   
6. | Executing hook on transaction  | 0.000009 | launch_hook_trans_begin | rpl_handler.cc       |        1484 |
   
7. | starting                       | 0.000020 | launch_hook_trans_begin | rpl_handler.cc       |        1486 |
   
8. | checking permissions           | 0.000012 | check_access            | sql_authorization.cc |        2173 |
   
9. | Opening tables                 | 0.000076 | open_tables             | sql_base.cc          |        5911 |
   
10. | init                           | 0.000011 | execute                 | sql_select.cc        |         760 |
    
11. | System lock                    | 0.000026 | mysql_lock_tables       | lock.cc              |         332 |
    
12. | optimizing                     | 0.000013 | optimize                | sql_optimizer.cc     |         379 |
    
13. | statistics                     | 0.000033 | optimize                | sql_optimizer.cc     |         721 |
    
14. | preparing                      | 0.000032 | optimize                | sql_optimizer.cc     |         806 |
    
15. | executing                      | 1.093124 | ExecuteIteratorQuery    | sql_union.cc         |        1677 |
    
16. | end                            | 0.000025 | execute                 | sql_select.cc        |         796 |
    
17. | query end                      | 0.000013 | mysql_execute_command   | sql_parse.cc         |        4896 |
    
18. | waiting for handler commit     | 0.000078 | ha_commit_trans         | handler.cc           |        1636 |
    
19. | closing tables                 | 0.000048 | mysql_execute_command   | sql_parse.cc         |        4960 |
    
20. | freeing items                  | 0.000076 | dispatch_sql_command    | sql_parse.cc         |        5434 |
    
21. | cleaning up                    | 0.000037 | dispatch_command        | sql_parse.cc         |        2478 |
    
22. +--------------------------------+----------+-------------------------+----------------------+-------------+
    
23. 17 rows in set, 1 warning (0.00 sec)

复制代码

以executing为例，它对应的“埋点”地址是sql_union.cc文件的第 1677 行，该行对应的代码是：

1.   THD_STAGE_INFO(thd, stage_executing);

复制代码

其它的“埋点”地址也类似，调用的都是THD_STAGE_INFO，唯一不一样的是 stage 的名称。
THD_STAGE_INFO 主要会做两件事情：

• 采集数据。
  
• 将采集到的数据添加到队列中。
  

下面我们结合代码看看详细的实现细节。

1. void QUERY_PROFILE::new_status(const char *status_arg, const char *function_arg,
   
2.                                const char *file_arg, unsigned int line_arg) {
   
3.   PROF_MEASUREMENT *prof;
   
4.   ...
   
5.   // 初始化 PROF_MEASUREMENT，初始化的过程中会采集数据。
   
6.   if ((function_arg != nullptr) && (file_arg != nullptr))
   
7.     prof = new PROF_MEASUREMENT(this, status_arg, function_arg,
   
8.                                 base_name(file_arg), line_arg);
   
9.   else
   
10.     prof = new PROF_MEASUREMENT(this, status_arg);
    
11.   // m_seq 是阶段的序号，对应 information_schema.profiling 中的 SEQ。
    
12.   prof->m_seq = m_seq_counter++; 
    
13.   // time_usecs 是采集到的系统当前时间。
    
14.   m_end_time_usecs = prof->time_usecs; 
    
15.   // 将采集到的数据添加到队列中，这个队列在查询时会用到。
    
16.   entries.push_back(prof); 
    
17.   ...
    
18. }

复制代码

继续分析PROF_MEASUREMENT的初始化逻辑。

1. PROF_MEASUREMENT::PROF_MEASUREMENT(QUERY_PROFILE *profile_arg,
   
2.                                    const char *status_arg,
   
3.                                    const char *function_arg,
   
4.                                    const char *file_arg, unsigned int line_arg)
   
5.     : profile(profile_arg) {
   
6.   collect();
   
7.   set_label(status_arg, function_arg, file_arg, line_arg);
   
8. }
   
9. 
   
10. void PROF_MEASUREMENT::collect() {
    
11.   time_usecs = (double)my_getsystime() / 10.0; /* 1 sec was 1e7, now is 1e6 */
    
12. #ifdef HAVE_GETRUSAGE
    
13.   getrusage(RUSAGE_SELF, &rusage);
    
14. #elif defined(_WIN32)
    
15.   ...
    
16. #endif
    
17. }

复制代码

PROF_MEASUREMENT 在初始化时会调用collect函数，collect()函数非常关键，它会做两件事情：

• 通过my_getsystime()获取体系的当前时间。
  
• 通过getrusage(RUSAGE_SELF, &rusage)获取当前进程（注意是进程，不是当前 SQL）的资源利用情况。
  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来填凑数据。
下面我们看看该函数的实现逻辑。

1. int PROFILING::fill_statistics_info(THD *thd_arg, Table_ref *tables) {
   
2.   DBUG_TRACE;
   
3.   TABLE *table = tables->table;
   
4.   ulonglong row_number = 0;
   
5. 
   
6.   QUERY_PROFILE *query;
   
7.   // 循环 history 队列，队列中的元素是 QUERY_PROFILE，每一个查询对应一个 QUERY_PROFILE。
   
8.   // 队列的大小由参数 profiling_history_size 决定，默认是 15。
   
9.   void *history_iterator;
   
10.   for (history_iterator = history.new_iterator(); history_iterator != nullptr;
    
11.        history_iterator = history.iterator_next(history_iterator)) {
    
12.     query = history.iterator_value(history_iterator);
    
13. 
    
14.     ulong seq;
    
15. 
    
16.     void *entry_iterator;
    
17.     PROF_MEASUREMENT *entry, *previous = nullptr;
    
18.     // 循环每个查询中的 entries，entries 存储了每个阶段的系统当前时间。
    
19.     for (entry_iterator = query->entries.new_iterator();
    
20.          entry_iterator != nullptr;
    
21.          entry_iterator = query->entries.iterator_next(entry_iterator),
    
22.         previous = entry, row_number++) {
    
23.       entry = query->entries.iterator_value(entry_iterator);
    
24.       seq = entry->m_seq;
    
25. 
    
26.       if (previous == nullptr) continue;
    
27. 
    
28.       if (thd_arg->lex->sql_command == SQLCOM_SHOW_PROFILE) {
    
29.         if (thd_arg->lex->show_profile_query_id ==
    
30.             0) /* 0 == show final query */
    
31.         {
    
32.           if (query != last) continue;
    
33.         } else {
    
34.           // 如果记录中的 Query_ID 跟 show profile for query query_id 中的不一致，则继续判断下一条记录
    
35.           if (thd_arg->lex->show_profile_query_id != query->profiling_query_id) 
    
36.             continue;
    
37.         }
    
38.       }
    
39. 
    
40.       restore_record(table, s->default_values);
    
41.       // query->profiling_query_id 用来填充 information_schema.profiling 中的 QUERY_ID
    
42.       table->field[0]->store((ulonglong)query->profiling_query_id, true);
    
43.       // seq 用来填充 information_schema.profiling 中的 SEQ
    
44.       table->field[1]->store((ulonglong)seq,
    
45.                              true); 
    
46.       // status 用来填充 information_schema.profiling 中的 STATE
    
47.       // 注意，这里是上一条记录的 status，不是当前记录的 status
    
48.       table->field[2]->store(previous->status, strlen(previous->status),
    
49.                              system_charset_info);
    
50.       // 当前记录的 time_usecs 减去上一条记录的 time_usecs 的值，换算成秒，用来填充 information_schema.profiling 中的 DURATION
    
51.       my_decimal duration_decimal;
    
52.       double2my_decimal(
    
53.           E_DEC_FATAL_ERROR,
    
54.           (entry->time_usecs - previous->time_usecs) / (1000.0 * 1000),
    
55.           &duration_decimal); 
    
56. 
    
57.       table->field[3]->store_decimal(&duration_decimal);
    
58. #ifdef HAVE_GETRUSAGE
    
59.       my_decimal cpu_utime_decimal, cpu_stime_decimal;
    
60.       // 当前记录的 ru_utime 减去上一条记录的 ru_utime，用来填充 information_schema.profiling 中的 CPU_USER
    
61.       double2my_decimal(
    
62.           E_DEC_FATAL_ERROR,
    
63.           RUSAGE_DIFF_USEC(entry->rusage.ru_utime, previous->rusage.ru_utime) /
    
64.               (1000.0 * 1000),
    
65.           &cpu_utime_decimal);
    
66.       ...
    
67.       table->field[4]->store_decimal(&cpu_utime_decimal);
    
68. ...
    
69. 
    
70.   return 0;
    
71. }

复制代码

可以看到，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。
表空间导入操作为什么大部门耗时是在 System lock 阶段？

表空间导入操作是在mysql_discard_or_import_tablespace函数中实现的。
下面是该函数简化后的代码。

1. bool Sql_cmd_discard_import_tablespace::mysql_discard_or_import_tablespace(
   
2.     THD *thd, Table_ref *table_list) {
   
3.   ... 
   
4.   THD_STAGE_INFO(thd, stage_discard_or_import_tablespace);
   
5.   ...
   
6.   if (open_and_lock_tables(thd, table_list, 0, &alter_prelocking_strategy)) {
   
7.     return true;
   
8.   }
   
9.   ...
   
10.   const bool discard =
    
11.       (m_alter_info->flags & Alter_info::ALTER_DISCARD_TABLESPACE);
    
12.   error = table_list->table->file->ha_discard_or_import_tablespace(discard,
    
13.                                                                    table_def); 
    
14.   THD_STAGE_INFO(thd, stage_end);
    
15.   ...
    
16.   return true;
    
17. }

复制代码

可以看到，该函数实际调用的是 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来描述这一过程会更为准确。
  

参考资料

• https://dev.mysql.com/doc/refman/8.4/en/show-profile.html
  
• https://dev.mysql.com/doc/refman/8.4/en/performance-schema-query-profiling.html
  
• https://dev.mysql.com/worklog/task/?id=5522
  

免责声明：如果侵犯了您的权益，请联系站长，我们会及时删除侵权内容，谢谢合作！更多信息从访问主页：qidao123.com:ToB企服之家，中国第一个企服评测及商务社交产业平台。