MySQL?優(yōu)化利器?SHOW?PROFILE?的實(shí)現(xiàn)原理及細(xì)節(jié)展示
背景
最近碰到一個(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)文章希望大家以后多多支持腳本之家！
相關(guān)文章
這篇文章主要為大家詳細(xì)介紹了MySQL索引的作用，文中示例代碼介紹的非常詳細(xì)，具有一定的參考價(jià)值，感興趣的小伙伴們可以參考一下，希望能夠給你帶來(lái)幫助2022-03-03
淺談MySQL中float、double、decimal三個(gè)浮點(diǎn)類(lèi)型的區(qū)別與總結(jié)
這篇文章主要介紹了淺談MySQL中float、double、decimal三個(gè)浮點(diǎn)類(lèi)型的區(qū)別與總結(jié),文中通過(guò)示例代碼介紹的非常詳細(xì)，對(duì)大家的學(xué)習(xí)或者工作具有一定的參考學(xué)習(xí)價(jià)值，需要的朋友們下面隨著小編來(lái)一起學(xué)習(xí)學(xué)習(xí)吧2020-11-11
在本篇文章里小編給大家分享的是關(guān)于navicat 8 for mysql建庫(kù)的方法以及相關(guān)知識(shí)點(diǎn)，需要的朋友們參考學(xué)習(xí)下。2019-08-08
日志滾動(dòng)解決日志文件過(guò)大問(wèn)題，比如我開(kāi)啟了general_log，這個(gè)日志呢是記錄mysql服務(wù)器上面所運(yùn)行的所有sql語(yǔ)句；比如我開(kāi)啟了mysql的慢查詢2014-01-01
這篇文章主要介紹了MySQL數(shù)據(jù)安全的一些建議，幫助大家平時(shí)更好的運(yùn)維數(shù)據(jù)庫(kù)，保障數(shù)據(jù)安全，感興趣的朋友可以了解下2020-08-08
詳解讓MySQL和Redis數(shù)據(jù)保持一致的四種策略
在分布式系統(tǒng)中,保證Redis和MySQL之間的數(shù)據(jù)一致性是一個(gè)復(fù)雜且重要的問(wèn)題,下面這篇文章主要給大家介紹了關(guān)于讓MySQL和Redis數(shù)據(jù)保持一致的四種策略,文中通過(guò)代碼介紹的非常詳細(xì),需要的朋友可以參考下2024-07-07
MySQL多表關(guān)聯(lián)on和where速度對(duì)比實(shí)測(cè)看誰(shuí)更快
這篇文章主要介紹了MySQL多表關(guān)聯(lián)on和where速度對(duì)比實(shí)測(cè)看誰(shuí)更快問(wèn)題，具有很好的參考價(jià)值，希望對(duì)大家有所幫助。如有錯(cuò)誤或未考慮完全的地方，望不吝賜教2023-03-03
MySQL5.7中 performance和sys schema中的監(jiān)控參數(shù)解釋(推薦)
在MySQL5.7中，performance schema有很大改進(jìn)，包括引入大量新加入的監(jiān)控項(xiàng)、降低占用空間和負(fù)載，以及通過(guò)新的sys schema機(jī)制顯著提升易用性。下面通過(guò)本文給大家介紹 MySQL5.7中 performance和sys schema中的監(jiān)控參數(shù)解釋,需要的朋友可以參考下2017-08-08
詳解mysql數(shù)據(jù)庫(kù)中文亂碼問(wèn)題
這篇文章主要介紹了詳解mysql數(shù)據(jù)庫(kù)中文亂碼問(wèn)題的相關(guān)資料,需要的朋友可以參考下2017-10-10
MySQL啟動(dòng)失敗之MySQL服務(wù)無(wú)法啟動(dòng)的原因及解決
這篇文章主要介紹了MySQL啟動(dòng)失敗之MySQL服務(wù)無(wú)法啟動(dòng)的原因及解決，具有很好的參考價(jià)值，希望對(duì)大家有所幫助。如有錯(cuò)誤或未考慮完全的地方，望不吝賜教2022-12-12