MySQL优化利器SHOWPROFILE的实现原理

转载作者：撒哈拉更新时间：2024-12-23 08:45:52

背景

最近碰到一个 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 的基本用法

下面通过一个示例来看看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（进程间通信）发送/接受的消息数量、页面故障次数、交换次数等.

需要注意的是，这里的统计信息是针对整个进程的，不是单个 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: 0
Context_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 的实现原理

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;
  ...
  // 初始化 PROF_MEASUREMENT，初始化的过程中会采集数据。
  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);
  // m_seq 是阶段的序号，对应 information_schema.profiling 中的 SEQ。
  prof->m_seq = m_seq_counter++; 
  // time_usecs 是采集到的系统当前时间。
  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; /* 1 sec was 1e7, now is 1e6 */
#ifdef HAVE_GETRUSAGE
  getrusage(RUSAGE_SELF, &rusage);
#elif defined(_WIN32)
  ...
#endif
}

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

通过my_getsystime()获取系统的当前时间.
通过getrusage(RUSAGE_SELF, &rusage)获取当前进程（注意是进程，不是当前 SQL）的资源使用情况.

getrusage是一个用于获取进程或线程资源使用情况的系统调用。它返回进程在执行期间所消耗的资源信息，包括 CPU 时间、内存使用、页面故障、上下文切换等信息.

PROF_MEASUREMENT 初始化完毕后，会将其添加到 entries 中。entries 是一个队列（Queue<PROF_MEASUREMENT> 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;
  // 循环 history 队列，队列中的元素是 QUERY_PROFILE，每一个查询对应一个 QUERY_PROFILE。
  // 队列的大小由参数 profiling_history_size 决定，默认是 15。
  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;
    // 循环每个查询中的 entries，entries 存储了每个阶段的系统当前时间。
    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) /* 0 == show final query */
        {
          if (query != last) continue;
        } else {
          // 如果记录中的 Query_ID 跟 show profile for query query_id 中的不一致，则继续判断下一条记录
          if (thd_arg->lex->show_profile_query_id != query->profiling_query_id) 
            continue;
        }
      }

      restore_record(table, s->default_values);
      // query->profiling_query_id 用来填充 information_schema.profiling 中的 QUERY_ID
      table->field[0]->store((ulonglong)query->profiling_query_id, true);
      // seq 用来填充 information_schema.profiling 中的 SEQ
      table->field[1]->store((ulonglong)seq,
                             true); 
      // status 用来填充 information_schema.profiling 中的 STATE
      // 注意，这里是上一条记录的 status，不是当前记录的 status
      table->field[2]->store(previous->status, strlen(previous->status),
                             system_charset_info);
      // 当前记录的 time_usecs 减去上一条记录的 time_usecs 的值，换算成秒，用来填充 information_schema.profiling 中的 DURATION
      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;
      // 当前记录的 ru_utime 减去上一条记录的 ru_utime，用来填充 information_schema.profiling 中的 CPU_USER
      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.

表空间导入操作为什么大部分耗时是在 System lock 阶段？

表空间导入操作是在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来描述这一过程会更为准确.

参考资料

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

最后此篇关于MySQL优化利器SHOWPROFILE的实现原理的文章就讲到这里了,如果你想了解更多关于MySQL优化利器SHOWPROFILE的实现原理的内容请搜索CFSDN的文章或继续浏览相关文章，希望大家以后支持我的博客！。

文章推荐：字节豆包，来园广告

文章推荐：创建用于预测序列的人工智能模型，设计数据集。

文章推荐： JVM简介—1.Java内存区域

文章推荐：天地图接口Python代码详解

c++ - 为什么 MSVC 不为 char 或 const char* 优化 cout 而为 int 优化？
比较代码: const char x = 'a'; std::cout > (0C310B0h) 00C3100B add esp,4 和 const i
Matlab 优化
您好，我正在使用 Matlab 优化求解器，但程序有问题。我收到此消息 fmincon 已停止，因为目标函数值小于目标函数限制的默认值，并且约束满足在约束容差的默认值范围内。我也收到以下消息。警告:矩
Eclipse 优化
处理Visual Studio optimizations的问题为我节省了大量启动和使用它的时间当我必须进行 J2EE 开发时，我很难回到 Eclipse。因此，我还想知道人们是否有任何提示或技巧可
Excel 优化
情况如下:在我的 Excel 工作表中，有一列包含 1-name 形式的条目。考虑到数字也可以是两位数，我想删除这些数字。这本身不是问题，我让它工作了，只是性能太糟糕了。现在我的程序每个单元格输入大约
jQuery 优化
这样做有什么区别吗: $(".topHorzNavLink").click(function() { var theHoverContainer = $("#hoverContainer");
jQuery $(this) 优化
这个问题已经有答案了: 已关闭11 年前。 Possible Duplicate: What is the cost of '$(this)'? 我经常在一些开发人员代码中看到$(this)引用同一个
jQuery 优化
我刚刚结束了一个大型开发项目。我们的时间紧迫，因此很多优化被“推迟”。既然我们已经达到了最后期限，我们将回去尝试优化事情。我的问题是:优化 jQuery 网站时您要寻找的最重要的东西是什么。或者，我
JavaScript 优化
所以我一直在用 JavaScript 编写游戏(不是网络游戏，而是使用 JavaScript 恰好是脚本语言的游戏引擎)。不幸的是，游戏引擎的 JavaScript 引擎是 SpiderMonkey
MYSQL查询、优化
这是我在正在构建的页面中使用的 SQL 查询。它目前运行大约 8 秒并返回 12000 条记录，这是正确的，但我想知道您是否可以就如何使其更快提出可能的建议？ SELECT DISTINCT Adve
SQL 优化
如何优化这个？ SELECT e.attr_id, e.sku, a.value FROM product_attr AS e, product_attr_text AS a WHERE e.attr
python - 优化 `in`
我正在使用这样的结构来测试是否按下了所需的键: def eventFilter(self, tableView, event): if event.type() == QtCore.QEven
JavaScript 优化
我正在使用 JavaScript 从给定的球员列表中计算出羽毛球 double 比赛的所有组合。每个玩家都与其他人组队。 EG。如果我有以下球员a、b、c、d。它们的组合可以是: a & b V c
Javascript 优化
我似乎无法弄清楚如何让这个 JS 工作。 scroll function 起作用但不能隐藏。还有没有办法用更少的代码行来做到这一点？我希望 .down-arrow 在 50px 之后 fade out
CSS高级最小化(优化)
我的问题是关于用于生产的高级优化级联样式表 (CSS) 文件。多么最新和最完整(准备在实时元素中使用)的 css 优化器/最小化器，它们不仅提供删除空格和换行符，还提供高级功能，如删除过多的属性、合
HTML 优化
我读过这个: 浏览器检索在中请求的所有资源开始呈现之前的 HTML 部分.如果您将请求放在中section 而不是，那么页面呈现和下载资源可以并行发生。您应该从移动尽可能多的资源请求。
C++ 优化
我正在处理一些现有的 C++ 代码，这些代码看起来写得不好，而且调用频率很高。我想知道我是否应该花时间更改它，或者编译器是否已经在优化问题。我正在使用 Visual Studio 2008。这是一
c++ - 优化
我正在尝试使用 OpenGL 渲染 3 个四边形(1 个背景图，2 个 Sprite )。我有以下代码: void GLRenderer::onDrawObjects(long p_dt) {
Java If 优化
我确实有以下声明: isEnabled = false; if(foo(arg) && isEnabled) { .... } public boolean foo(arg) { some re
SQL 优化
(一)深入浅出理解索引结构实际上，您可以把索引理解为一种特殊的目录。微软的SQL SERVER提供了两种索引：聚集索引(clustered index，也称聚类索引、簇集索引)和非聚集索引(no
CSS 优化、提高性能的方法有哪些？
一、写在前面 css的优化方案，之前没有提及，所以接下来进行总结一下。二、具体优化方案 2.1、加载性能 1、css压缩：将写好的css进行打包，可以减少很多的体积。 2、css单一样式：在需要下边

撒哈拉

个人简介

我是一名优秀的程序员,十分优秀！

作者热门文章

滴滴打车优惠券免费领取

全站热门文章

首页

博学

6Ren·AI

商城