SHOW PROFILE的MySQL优化原理是什么？

背景 最近碰到一个 case，通过可传输表空间的方式导入一个 4GB 大小的表，耗时 13 分钟。 通过PROFILE定位，发现大部分耗时竟然是在System lock阶段。 mysql>setprofiling=1; QueryOK,0rowsaffected,1warning(0.00sec) mysql>altertablesbtest2importtablespace; QueryOK,0rowsaffected(13min8.99sec) mysql>showprofileforquery1; +--------------------------------+------------+ |Status|Duration| +--------------------------------+------------+ |starting|0.000119| |Executinghookontransaction|0.000004| |starting|0.000055| |checkingpermissions|0.000010| |discard_or_import_tablespace|0.000007| |Openingtables|0.000156| |Systemlock|788.966338| |end|0.007391| |waitingforhandlercommit|0.000041| |waitingforhandlercommit|0.011179| |queryend|0.000022| |closingtables|0.000019| |waitingforhandlercommit|0.000031| |freeingitems|0.000035| |cleaningup|0.000043| +--------------------------------+------------+ 15rowsinset,1warning(0.03sec) 不仅如此，SQL 在执行的过程中，show processlist中的状态显示的也是System lock。 mysql>showprocesslist; +----+-----------------+-----------+--------+---------+------+------------------------+---------------------------------------+ |Id|User|Host|db|Command|Time|State|Info| +----+-----------------+-----------+--------+---------+------+------------------------+---------------------------------------+ |5|event_scheduler|localhost|NULL|Daemon|818|Waitingonemptyqueue|NULL| |10|root|localhost|sbtest|Query|648|Systemlock|altertablesbtest2importtablespace| |14|root|localhost|NULL|Query|0|init|showprocesslist| +----+-----------------+-----------+--------+---------+------+------------------------+---------------------------------------+ 3rowsinset,1warning(0.00sec) 这个状态其实有很大的误导性。 接下来我们从SHOW PROFILE的基本用法出发，从源码角度分析它的实现原理。 最后在分析的基础上，看看 case 中的表空间导入操作为什么大部分耗时是在System lock阶段。 SHOW PROFILE 的基本用法 下面通过一个示例来看看SHOW PROFILE的用法。 #开启Profiling mysql>setprofiling=1; QueryOK,0rowsaffected,1warning(0.00sec) #执行需要分析的SQL mysql>selectcount(*)fromslowtech.t1; +----------+ |count(*)| +----------+ |1048576| +----------+ 1rowinset(1.09sec) #通过showprofiles查看SQL对应的Query_ID mysql>showprofiles; +----------+------------+----------------------------------+ |Query_ID|Duration|Query| +----------+------------+----------------------------------+ |1|1.09378600|selectcount(*)fromslowtech.t1| +----------+------------+----------------------------------+ 1rowinset,1warning(0.00sec) #查看该SQL各个阶段的执行耗时情况，其中，1是该SQL对应的Query_ID mysql>showprofileforquery1; +--------------------------------+----------+ |Status|Duration| +--------------------------------+----------+ |starting|0.000157| |Executinghookontransaction|0.000009| |starting|0.000020| |checkingpermissions|0.000012| |Openingtables|0.000076| |init|0.000011| |Systemlock|0.000026| |optimizing|0.000013| |statistics|0.000033| |preparing|0.000032| |executing|1.093124| |end|0.000025| |queryend|0.000013| |waitingforhandlercommit|0.000078| |closingtables|0.000048| |freeingitems|0.000076| |cleaningup|0.000037| +--------------------------------+----------+ 17rowsinset,1warning(0.01sec) 如果指定 all 还会输出更详细的统计信息，包括 CPU、上下文切换、磁盘IO、IPC（进程间通信）发送/接受的消息数量、页面故障次数、交换次数等。 需要注意的是，这里的统计信息是针对整个进程的，不是单个 SQL 的。如果在执行上述 SQL 的同时还有其它 SQL 在执行，那么这些数据就不能用来评估该 SQL 的资源使用情况。 mysql>showprofileallforquery1\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 ... 17rowsinset,1warning(0.00sec) SHOW PROFILE 的实现原理 SHOW PROFILE 主要是在sql_profile.cc中实现的。它的实现主要分为两部分： 数据的采集。 数据的计算。 下面我们分别从这两个维度来看看 SHOW PROFILE 的实现原理。 数据的采集 数据的采集实际上是通过“埋点”实现的。不同阶段对应的“埋点”地址可通过show profile source查看。 mysql>showprofilesourceforquery1; +--------------------------------+----------+-------------------------+----------------------+-------------+ |Status|Duration|Source_function|Source_file|Source_line| +--------------------------------+----------+-------------------------+----------------------+-------------+ |starting|0.000157|NULL|NULL|NULL| |Executinghookontransaction|0.000009|launch_hook_trans_begin|rpl_handler.cc|1484| |starting|0.000020|launch_hook_trans_begin|rpl_handler.cc|1486| |checkingpermissions|0.000012|check_access|sql_authorization.cc|2173| |Openingtables|0.000076|open_tables|sql_base.cc|5911| |init|0.000011|execute|sql_select.cc|760| |Systemlock|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| |queryend|0.000013|mysql_execute_command|sql_parse.cc|4896| |waitingforhandlercommit|0.000078|ha_commit_trans|handler.cc|1636| |closingtables|0.000048|mysql_execute_command|sql_parse.cc|4960| |freeingitems|0.000076|dispatch_sql_command|sql_parse.cc|5434| |cleaningup|0.000037|dispatch_command|sql_parse.cc|2478| +--------------------------------+----------+-------------------------+----------------------+-------------+ 17rowsinset,1warning(0.00sec) 以executing为例，它对应的“埋点”地址是sql_union.cc文件的第 1677 行，该行对应的代码是： THD_STAGE_INFO(thd,stage_executing); 其它的“埋点”地址也类似，调用的都是THD_STAGE_INFO，唯一不一样的是 stage 的名称。 THD_STAGE_INFO 主要会做两件事情： 采集数据。 将采集到的数据添加到队列中。 下面我们结合代码看看具体的实现细节。 voidQUERY_PROFILE::new_status(constchar*status_arg,constchar*function_arg, constchar*file_arg,unsignedintline_arg){ PROF_MEASUREMENT*prof; ... //初始化PROF_MEASUREMENT，初始化的过程中会采集数据。 if((function_arg!=nullptr)&&(file_arg!=nullptr)) prof=newPROF_MEASUREMENT(this,status_arg,function_arg, base_name(file_arg),line_arg); else prof=newPROF_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, constchar*status_arg, constchar*function_arg, constchar*file_arg,unsignedintline_arg) :profile(profile_arg){ collect(); set_label(status_arg,function_arg,file_arg,line_arg); } voidPROF_MEASUREMENT::collect(){ time_usecs=(double)my_getsystime()/10.0;/*1secwas1e7,nowis1e6*/ #ifdefHAVE_GETRUSAGE getrusage(RUSAGE_SELF,&rusage); #elifdefined(_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来填充数据。 下面我们看看该函数的实现逻辑。 intPROFILING::fill_statistics_info(THD*thd_arg,Table_ref*tables){ DBUG_TRACE; TABLE*table=tables->table; ulonglongrow_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); ulongseq; 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==showfinalquery*/ { if(query!=last)continue; }else{ //如果记录中的Query_ID跟showprofileforqueryquery_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_decimalduration_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); #ifdefHAVE_GETRUSAGE my_decimalcpu_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); ... return0; } 可以看到，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函数中实现的。 下面是该函数简化后的代码。 boolSql_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)){ returntrue; } ... constbooldiscard= (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); ... returntrue; } 可以看到，该函数实际调用的是 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