MySQL?優(yōu)化利器?SHOW?PROFILE?的實現(xiàn)原理及細(xì)節(jié)展示
背景
最近碰到一個 case，通過可傳輸表空間的方式導(dǎo)入一個 4GB 大小的表，耗時 13 分鐘。
通過PROFILE定位，發(fā)現(xiàn)大部分耗時竟然是在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í)行的過程中，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)
這個狀態(tài)其實有很大的誤導(dǎo)性。
接下來我們從SHOW PROFILE的基本用法出發(fā)，從源碼角度分析它的實現(xiàn)原理。
最后在分析的基礎(chǔ)上，看看 case 中的表空間導(dǎo)入操作為什么大部分耗時是在System lock階段。
SHOW PROFILE 的基本用法
下面通過一個示例來看看SHOW PROFILE的用法。
# 開啟 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) # 通過 show profiles 查看 SQL 對應(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 各個階段的執(zhí)行耗時情況，其中，1 是該 SQL 對應(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 還會輸出更詳細(xì)的統(tǒng)計信息，包括 CPU、上下文切換、磁盤IO、IPC（進(jìn)程間通信）發(fā)送/接受的消息數(shù)量、頁面故障次數(shù)、交換次數(shù)等。
需要注意的是，這里的統(tǒng)計信息是針對整個進(jìn)程的，不是單個 SQL 的。如果在執(zhí)行上述 SQL 的同時還有其它 SQL 在執(zhí)行，那么這些數(shù)據(jù)就不能用來評估該 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 的實現(xiàn)原理
SHOW PROFILE 主要是在sql_profile.cc中實現(xiàn)的。它的實現(xiàn)主要分為兩部分：
- 數(shù)據(jù)的采集。
- 數(shù)據(jù)的計算。
下面我們分別從這兩個維度來看看 SHOW PROFILE 的實現(xiàn)原理。
數(shù)據(jù)的采集
數(shù)據(jù)的采集實際上是通過“埋點”實現(xiàn)的。不同階段對應(yīng)的“埋點”地址可通過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為例，它對應(yīng)的“埋點”地址是sql_union.cc文件的第 1677 行，該行對應(yīng)的代碼是：
THD_STAGE_INFO(thd, stage_executing);
其它的“埋點”地址也類似，調(diào)用的都是THD_STAGE_INFO，唯一不一樣的是 stage 的名稱。
THD_STAGE_INFO 主要會做兩件事情：
- 采集數(shù)據(jù)。
- 將采集到的數(shù)據(jù)添加到隊列中。
下面我們結(jié)合代碼看看具體的實現(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，初始化的過程中會采集數(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 是階段的序號，對應(yīng) information_schema.profiling 中的 SEQ。
prof->m_seq = m_seq_counter++;
// time_usecs 是采集到的系統(tǒng)當(dāng)前時間。
m_end_time_usecs = prof->time_usecs;
// 將采集到的數(shù)據(jù)添加到隊列中，這個隊列在查詢時會用到。
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 在初始化時會調(diào)用collect函數(shù)，collect()函數(shù)非常關(guān)鍵，它會做兩件事情：
通過
my_getsystime()獲取系統(tǒng)的當(dāng)前時間。通過
getrusage(RUSAGE_SELF, &rusage)獲取當(dāng)前進(jìn)程（注意是進(jìn)程，不是當(dāng)前 SQL）的資源使用情況。getrusage是一個用于獲取進(jìn)程或線程資源使用情況的系統(tǒng)調(diào)用。它返回進(jìn)程在執(zhí)行期間所消耗的資源信息，包括 CPU 時間、內(nèi)存使用、頁面故障、上下文切換等信息。
PROF_MEASUREMENT 初始化完畢后，會將其添加到 entries 中。entries 是一個隊列（Queue<PROF_MEASUREMENT> entries）。這個隊列，會在執(zhí)行show profile for query N或者information_schema.profiling時用到。
說完數(shù)據(jù)的采集，接下來我們看看數(shù)據(jù)的計算，畢竟“埋點”收集的只是系統(tǒng)當(dāng)前時間，而我們在show profile for query N中看到的Duration 是一個時長。
數(shù)據(jù)的計算
當(dāng)我們在執(zhí)行show profile for query N時，實際上查詢的是information_schema.profiling，此時，會調(diào)用PROFILING::fill_statistics_info來填充數(shù)據(jù)。
下面我們看看該函數(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 隊列，隊列中的元素是 QUERY_PROFILE，每一個查詢對應(yīng)一個 QUERY_PROFILE。
// 隊列的大小由參數(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)每個查詢中的 entries，entries 存儲了每個階段的系統(tǒng)當(dāng)前時間。
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 用來填充 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，不是當(dāng)前記錄的 status
table->field[2]->store(previous->status, strlen(previous->status),
system_charset_info);
// 當(dāng)前記錄的 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;
// 當(dāng)前記錄的 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，對應(yīng) show profile for query N 中的 Status）存儲的是上一條記錄的 status（階段名），而第四列（DURATION）的值等于當(dāng)前記錄的采集時間（entry->time_usecs）減去上一條記錄的采集時間（previous->time_usecs）。
所以，我們在show profile for query N中看到的 Duration 實際上通過下一個階段的采集時間減去當(dāng)前階段的采集時間得到的，并不是show profile source中函數(shù)（Source_function）的執(zhí)行時長。
這種實現(xiàn)方式在判斷操作當(dāng)前狀態(tài)和分析各個階段耗時時存在一定的誤導(dǎo)性。
回到開頭的 case。
表空間導(dǎo)入操作為什么大部分耗時是在 System lock 階段？
表空間導(dǎo)入操作是在mysql_discard_or_import_tablespace函數(shù)中實現(xiàn)的。
下面是該函數(shù)簡化后的代碼。
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ù)實際調(diào)用的是 THD_STAGE_INFO(thd, stage_discard_or_import_tablespace)。
只不過，在調(diào)用 THD_STAGE_INFO(thd, stage_discard_or_import_tablespace) 后，調(diào)用了 open_and_lock_tables。
而 open_and_lock_tables 最后會調(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。
但基于對耗時的分析，我們發(fā)現(xiàn)這么顯示其實并不合理。
在開頭的 case 中，雖然System lock階段顯示的耗時是 788.966338 秒，但實際上open_and_lock_tables這個函數(shù)只消耗了 0.000179 秒，真正的耗時是來自 table_list->table->file->ha_discard_or_import_tablespace，其執(zhí)行時間長達(dá) 788.965481 秒。
為什么這個函數(shù)需要執(zhí)行這么久呢？主要是表空間在導(dǎo)入的過程中會檢查并更新表空間中的每個頁，包括驗證頁是否損壞、更新表空間 ID 和 LSN、處理 Btree 頁（如設(shè)置索引 ID、清除 delete marked 記錄等）、將頁標(biāo)記為臟頁等。表越大，檢查校驗的時候會越久。
如此來看，針對表空間導(dǎo)入操作，將其狀態(tài)顯示為discard_or_import_tablespace更能反映操作的真實情況。
總結(jié)
在
SHOW PROFILE中顯示的每個階段的耗時，實際上是由下一個階段的采集時間減去當(dāng)前階段的采集時間得出的。每個階段的采集時間是通過在代碼的不同路徑中植入
THD_STAGE_INFO(thd, stage_xxx)實現(xiàn)的，采集的是系統(tǒng)當(dāng)前時間。這種實現(xiàn)方式在判斷操作當(dāng)前狀態(tài)（通過 SHOW PROCESSLIST）和分析各個階段耗時（通過 SHOW PROFILE ）時存在一定的誤導(dǎo)性，主要是因為預(yù)定義的階段數(shù)量是有限的。
在 MySQL 8.4 中，共定義了 98 個階段，具體的階段名可在
mysqld.cc中的all_server_stages數(shù)組找到。在表空間導(dǎo)入操作中，雖然大部分耗時顯示為
System lock階段，但實際上，使用discard_or_import_tablespace來描述這一過程會更為準(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 的實現(xiàn)原理的文章就介紹到這了,更多相關(guān)MySQL SHOW PROFILE內(nèi)容請搜索腳本之家以前的文章或繼續(xù)瀏覽下面的相關(guān)文章希望大家以后多多支持腳本之家！
相關(guān)文章
MySQL主從復(fù)制的原理及配置方法（比較詳細(xì)）
MySQL 的數(shù)據(jù)庫的高可用性的架構(gòu)大概有以下幾種：集群，讀寫分離，主備。而后面兩種都是通過復(fù)制來實現(xiàn)的。下面將簡單介紹復(fù)制的原理及配置，以及一些常見的問題2014-05-05
多主互備和主從復(fù)制有一些區(qū)別，因為多主中都可以對服務(wù)器有寫權(quán)限，所以設(shè)計到自增長重復(fù)問題2011-09-09
本文記錄了一次因MySQL版本不一致導(dǎo)致項目啟動失敗的經(jīng)歷,詳細(xì)解析了連接錯誤的原因,并提供了兩種解決方案：調(diào)整連接字符串禁用SSL或統(tǒng)一MySQL版本,需要的朋友可以參考下2025-06-06
這篇文章主要給大家介紹了關(guān)于SQL面試之WHERE?1=1到底是什么意思的相關(guān)資料,WHERE 1=1子句只是一些開發(fā)人員采用的一種慣性做法,以簡化靜態(tài)和動態(tài)形式的SQL語句的使用,文中介紹的非常詳細(xì),需要的朋友可以參考下2023-09-09
MySQL深入詳解delete與Truncate及drop的使用區(qū)別
對于drop、truncate和delete雖然簡單,但是真要使用或者面試時候問到還是需要有一定的總結(jié),下面這篇文章主要給大家介紹了關(guān)于mysql中drop、truncate與delete區(qū)別的相關(guān)資料,需要的朋友可以參考下2022-07-07
備份恢復(fù)是 DBA 繞不開的核心話題，市面上也有很多開源的備份恢復(fù)方案，不過官方的 mysqldump 一直是處于鄙視鏈底端的那個。終于，官方在 MySQL5.7 之后新添加了一個備份工具：mysqlpump，本文將簡單的介紹該工具的使用2021-05-05
這篇文章主要介紹了mysql如何將id重新修改為遞增,本文模擬場景結(jié)合實例代碼給大家介紹的非常詳細(xì),對大家的學(xué)習(xí)或工作具有一定的參考借鑒價值,需要的朋友可以參考下2023-08-08
Mysql中返回一個數(shù)據(jù)庫的所有表名,列名數(shù)據(jù)類型備注
在Mysql中怎樣返回一個數(shù)據(jù)庫的所有表名,列名數(shù)據(jù)類型備注2010-04-04
mysql誤刪root用戶或者忘記root密碼解決方法，需要的朋友可以參考下。2011-05-05
如何解決MySQL?this?is?incompatible?with?sql_mode=only_full_
MySQL的ONLY_FULL_GROUP_BY模式要求在使用GROUP?BY時,SELECT語句中引用的所有列必須在GROUP?BY子句中明確指定,或者是聚合函數(shù)的一部分,本文提供了修改SQL語句、使用聚合函數(shù)、禁用ONLY_FULL_GROUP_BY等解決方法,并強(qiáng)調(diào)了在禁用該模式時應(yīng)評估其影響2024-11-11