MySQL?優(yōu)化利器?SHOW?PROFILE?的實(shí)現(xiàn)原理及細(xì)節(jié)展示

更新時(shí)間：2024年12月23日 09:00:07 作者：iVictor

這篇文章主要介紹了MySQL優(yōu)化利器SHOW?PROFILE的實(shí)現(xiàn)原理,通過(guò)實(shí)例代碼展示SHOW PROFILE的用法,需要的朋友可以參考下

背景

最近碰到一個(gè) case，通過(guò)可傳輸表空間的方式導(dǎo)入一個(gè) 4GB 大小的表，耗時(shí) 13 分鐘。

通過(guò)PROFILE定位，發(fā)現(xiàn)大部分耗時(shí)竟然是在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 在執(zhí)行的過(guò)程中，show processlist中的狀態(tài)顯示的也是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)

這個(gè)狀態(tài)其實(shí)有很大的誤導(dǎo)性。

接下來(lái)我們從SHOW PROFILE的基本用法出發(fā)，從源碼角度分析它的實(shí)現(xiàn)原理。

最后在分析的基礎(chǔ)上，看看 case 中的表空間導(dǎo)入操作為什么大部分耗時(shí)是在System lock階段。

SHOW PROFILE 的基本用法

下面通過(guò)一個(gè)示例來(lái)看看SHOW PROFILE的用法。

# 開(kāi)啟 Profiling
mysql> set profiling=1;
Query OK, 0 rows affected, 1 warning (0.00 sec)
# 執(zhí)行需要分析的 SQL
mysql> select count(*) from slowtech.t1;
+----------+
| count(*) |
+----------+
|  1048576 |
+----------+
1 row in set (1.09 sec)
# 通過(guò) show profiles 查看 SQL 對(duì)應(yīng)的 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 各個(gè)階段的執(zhí)行耗時(shí)情況，其中，1 是該 SQL 對(duì)應(yīng)的 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 還會(huì)輸出更詳細(xì)的統(tǒng)計(jì)信息，包括 CPU、上下文切換、磁盤(pán)IO、IPC（進(jìn)程間通信）發(fā)送/接受的消息數(shù)量、頁(yè)面故障次數(shù)、交換次數(shù)等。

需要注意的是，這里的統(tǒng)計(jì)信息是針對(duì)整個(gè)進(jìn)程的，不是單個(gè) SQL 的。如果在執(zhí)行上述 SQL 的同時(shí)還有其它 SQL 在執(zhí)行，那么這些數(shù)據(jù)就不能用來(lái)評(píng)估該 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 的實(shí)現(xiàn)原理

SHOW PROFILE 主要是在sql_profile.cc中實(shí)現(xiàn)的。它的實(shí)現(xiàn)主要分為兩部分：

數(shù)據(jù)的采集。
數(shù)據(jù)的計(jì)算。

下面我們分別從這兩個(gè)維度來(lái)看看 SHOW PROFILE 的實(shí)現(xiàn)原理。

數(shù)據(jù)的采集

數(shù)據(jù)的采集實(shí)際上是通過(guò)“埋點(diǎn)”實(shí)現(xiàn)的。不同階段對(duì)應(yīng)的“埋點(diǎn)”地址可通過(guò)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為例，它對(duì)應(yīng)的“埋點(diǎn)”地址是sql_union.cc文件的第 1677 行，該行對(duì)應(yīng)的代碼是：

  THD_STAGE_INFO(thd, stage_executing);

其它的“埋點(diǎn)”地址也類(lèi)似，調(diào)用的都是THD_STAGE_INFO，唯一不一樣的是 stage 的名稱。

THD_STAGE_INFO 主要會(huì)做兩件事情：

采集數(shù)據(jù)。
將采集到的數(shù)據(jù)添加到隊(duì)列中。

下面我們結(jié)合代碼看看具體的實(shí)現(xiàn)細(xì)節(jié)。

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，初始化的過(guò)程中會(huì)采集數(shù)據(jù)。
  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 是階段的序號(hào)，對(duì)應(yīng) information_schema.profiling 中的 SEQ。
  prof->m_seq = m_seq_counter++; 
  // time_usecs 是采集到的系統(tǒng)當(dāng)前時(shí)間。
  m_end_time_usecs = prof->time_usecs; 
  // 將采集到的數(shù)據(jù)添加到隊(duì)列中，這個(gè)隊(duì)列在查詢時(shí)會(huì)用到。
  entries.push_back(prof); 
  ...
}

繼續(xù)分析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 在初始化時(shí)會(huì)調(diào)用collect函數(shù)，collect()函數(shù)非常關(guān)鍵，它會(huì)做兩件事情：

通過(guò)my_getsystime()獲取系統(tǒng)的當(dāng)前時(shí)間。
通過(guò)getrusage(RUSAGE_SELF, &rusage)獲取當(dāng)前進(jìn)程（注意是進(jìn)程，不是當(dāng)前 SQL）的資源使用情況。

getrusage是一個(gè)用于獲取進(jìn)程或線程資源使用情況的系統(tǒng)調(diào)用。它返回進(jìn)程在執(zhí)行期間所消耗的資源信息，包括 CPU 時(shí)間、內(nèi)存使用、頁(yè)面故障、上下文切換等信息。

PROF_MEASUREMENT 初始化完畢后，會(huì)將其添加到 entries 中。entries 是一個(gè)隊(duì)列（Queue<PROF_MEASUREMENT> entries）。這個(gè)隊(duì)列，會(huì)在執(zhí)行show profile for query N或者information_schema.profiling時(shí)用到。

說(shuō)完數(shù)據(jù)的采集，接下來(lái)我們看看數(shù)據(jù)的計(jì)算，畢竟“埋點(diǎn)”收集的只是系統(tǒng)當(dāng)前時(shí)間，而我們?cè)?code>show profile for query N中看到的Duration 是一個(gè)時(shí)長(zhǎng)。

數(shù)據(jù)的計(jì)算

當(dāng)我們?cè)趫?zhí)行show profile for query N時(shí)，實(shí)際上查詢的是information_schema.profiling，此時(shí)，會(huì)調(diào)用PROFILING::fill_statistics_info來(lái)填充數(shù)據(jù)。

下面我們看看該函數(shù)的實(shí)現(xiàn)邏輯。

int PROFILING::fill_statistics_info(THD *thd_arg, Table_ref *tables) {
  DBUG_TRACE;
  TABLE *table = tables->table;
  ulonglong row_number = 0;
  QUERY_PROFILE *query;
  // 循環(huán) history 隊(duì)列，隊(duì)列中的元素是 QUERY_PROFILE，每一個(gè)查詢對(duì)應(yīng)一個(gè) QUERY_PROFILE。
  // 隊(duì)列的大小由參數(shù) profiling_history_size 決定，默認(rèn)是 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;
    // 循環(huán)每個(gè)查詢中的 entries，entries 存儲(chǔ)了每個(gè)階段的系統(tǒng)當(dāng)前時(shí)間。
    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 中的不一致，則繼續(xù)判斷下一條記錄
          if (thd_arg->lex->show_profile_query_id != query->profiling_query_id) 
            continue;
        }
      }
      restore_record(table, s->default_values);
      // query->profiling_query_id 用來(lái)填充 information_schema.profiling 中的 QUERY_ID
      table->field[0]->store((ulonglong)query->profiling_query_id, true);
      // seq 用來(lái)填充 information_schema.profiling 中的 SEQ
      table->field[1]->store((ulonglong)seq,
                             true); 
      // status 用來(lái)填充 information_schema.profiling 中的 STATE
      // 注意，這里是上一條記錄的 status，不是當(dāng)前記錄的 status
      table->field[2]->store(previous->status, strlen(previous->status),
                             system_charset_info);
      // 當(dāng)前記錄的 time_usecs 減去上一條記錄的 time_usecs 的值，換算成秒，用來(lái)填充 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;
      // 當(dāng)前記錄的 ru_utime 減去上一條記錄的 ru_utime，用來(lái)填充 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，對(duì)應(yīng) show profile for query N 中的 Status）存儲(chǔ)的是上一條記錄的 status（階段名），而第四列（DURATION）的值等于當(dāng)前記錄的采集時(shí)間（entry->time_usecs）減去上一條記錄的采集時(shí)間（previous->time_usecs）。

所以，我們?cè)?code>show profile for query N中看到的 Duration 實(shí)際上通過(guò)下一個(gè)階段的采集時(shí)間減去當(dāng)前階段的采集時(shí)間得到的，并不是show profile source中函數(shù)（Source_function）的執(zhí)行時(shí)長(zhǎng)。

這種實(shí)現(xiàn)方式在判斷操作當(dāng)前狀態(tài)和分析各個(gè)階段耗時(shí)時(shí)存在一定的誤導(dǎo)性。

回到開(kāi)頭的 case。

表空間導(dǎo)入操作為什么大部分耗時(shí)是在 System lock 階段？

表空間導(dǎo)入操作是在mysql_discard_or_import_tablespace函數(shù)中實(shí)現(xiàn)的。

下面是該函數(shù)簡(jiǎn)化后的代碼。

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;
}

可以看到，該函數(shù)實(shí)際調(diào)用的是 THD_STAGE_INFO(thd, stage_discard_or_import_tablespace)。

只不過(guò)，在調(diào)用 THD_STAGE_INFO(thd, stage_discard_or_import_tablespace) 后，調(diào)用了 open_and_lock_tables。

而 open_and_lock_tables 最后會(huì)調(diào)用 THD_STAGE_INFO(thd, stage_system_lock)。

這也就是為什么上述函數(shù)中雖然調(diào)用了 THD_STAGE_INFO(thd, stage_discard_or_import_tablespace)，但show profile和show processlist的輸出中卻顯示System lock。

但基于對(duì)耗時(shí)的分析，我們發(fā)現(xiàn)這么顯示其實(shí)并不合理。

在開(kāi)頭的 case 中，雖然System lock階段顯示的耗時(shí)是 788.966338 秒，但實(shí)際上open_and_lock_tables這個(gè)函數(shù)只消耗了 0.000179 秒，真正的耗時(shí)是來(lái)自 table_list->table->file->ha_discard_or_import_tablespace，其執(zhí)行時(shí)間長(zhǎng)達(dá) 788.965481 秒。

為什么這個(gè)函數(shù)需要執(zhí)行這么久呢？主要是表空間在導(dǎo)入的過(guò)程中會(huì)檢查并更新表空間中的每個(gè)頁(yè)，包括驗(yàn)證頁(yè)是否損壞、更新表空間 ID 和 LSN、處理 Btree 頁(yè)（如設(shè)置索引 ID、清除 delete marked 記錄等）、將頁(yè)標(biāo)記為臟頁(yè)等。表越大，檢查校驗(yàn)的時(shí)候會(huì)越久。

如此來(lái)看，針對(duì)表空間導(dǎo)入操作，將其狀態(tài)顯示為discard_or_import_tablespace更能反映操作的真實(shí)情況。

總結(jié)

在SHOW PROFILE中顯示的每個(gè)階段的耗時(shí)，實(shí)際上是由下一個(gè)階段的采集時(shí)間減去當(dāng)前階段的采集時(shí)間得出的。

每個(gè)階段的采集時(shí)間是通過(guò)在代碼的不同路徑中植入 THD_STAGE_INFO(thd, stage_xxx) 實(shí)現(xiàn)的，采集的是系統(tǒng)當(dāng)前時(shí)間。
這種實(shí)現(xiàn)方式在判斷操作當(dāng)前狀態(tài)（通過(guò) SHOW PROCESSLIST）和分析各個(gè)階段耗時(shí)（通過(guò) SHOW PROFILE ）時(shí)存在一定的誤導(dǎo)性，主要是因?yàn)轭A(yù)定義的階段數(shù)量是有限的。

在 MySQL 8.4 中，共定義了 98 個(gè)階段，具體的階段名可在mysqld.cc中的all_server_stages數(shù)組找到。
在表空間導(dǎo)入操作中，雖然大部分耗時(shí)顯示為System lock階段，但實(shí)際上，使用discard_or_import_tablespace來(lái)描述這一過(guò)程會(huì)更為準(zhǔn)確。

參考資料

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

到此這篇關(guān)于MySQL 優(yōu)化利器 SHOW PROFILE 的實(shí)現(xiàn)原理的文章就介紹到這了,更多相關(guān)MySQL SHOW PROFILE內(nèi)容請(qǐng)搜索腳本之家以前的文章或繼續(xù)瀏覽下面的相關(guān)文章希望大家以后多多支持腳本之家！

您可能感興趣的文章: