标签：sele voluntary for mysq HERE 情况 count star profiling
获取一个sql执行的全部过程的时间占用情况
（1）select @@profiling; （2）set profiling = 1; #这里仅仅在该会话中改变。 （3）目标sql语句; （4）show profiles; （5）show profile for query 线程ID;
work@10.10.10.10(glc) > select @@profiling; +-------------+ | @@profiling | +-------------+ | 0 | +-------------+ 1 row in set, 1 warning (0.00 sec) Tue May 12 19:21:22 2020 work@10.10.10.10(glc) > set profiling = 1; Query OK, 0 rows affected, 1 warning (0.00 sec) Tue May 12 19:21:31 2020 work@10.10.10.10(glc) > select count(*) from album_v2_glc; +----------+ | count(*) | +----------+ | 21510971 | +----------+ 1 row in set (9.32 sec) Tue May 12 19:26:35 2020 work@10.10.10.10(glc) > show profiles; +----------+------------+---------------------------------------------------------------+ | Query_ID | Duration | Query | +----------+------------+---------------------------------------------------------------+ | 1 | 0.00109750 | select * from aggreator limit 1 | | 2 | 0.02223300 | select count(*) from aggreator where metric like ‘count‘ | | 3 | 0.00022850 | select count(*) from aggreator where tages like ‘count‘ | | 4 | 0.02158250 | select count(*) from aggreator where tags like ‘count‘ | | 5 | 0.02609875 | select count(*) from aggreator where last_update like ‘count‘ | | 6 | 0.01787200 | select count(*) from aggreator | | 7 | 0.00040125 | show tables | | 8 | 0.01804350 | select count(*) from aggreator | | 9 | 9.31783450 | select count(*) from album_v2_glc | +----------+------------+---------------------------------------------------------------+ 9 rows in set, 1 warning (0.01 sec) Tue May 12 19:26:55 2020 work@10.10.10.10(glc) > show profile for query 9; +----------------------+----------+ | Status | Duration | +----------------------+----------+ | starting | 0.000084 | | checking permissions | 0.000010 | | Opening tables | 0.007116 | | init | 0.000021 | | System lock | 0.000014 | | optimizing | 0.000006 | | statistics | 0.000020 | | preparing | 0.000020 | | executing | 0.000003 | | Sending data | 9.310305 | | end | 0.000010 | | query end | 0.000012 | | closing tables | 0.000011 | | freeing items | 0.000044 | | logging slow query | 0.000003 | | logging slow query | 0.000138 | | cleaning up | 0.000019 | +----------------------+----------+ 17 rows in set, 1 warning (0.00 sec) Tue May 12 19:27:05 2020 work@10.10.10.10(glc) > show profile all for query 2; +----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+----------------------+-------------+ | Status | Duration | CPU_user | CPU_system | Context_voluntary | Context_involuntary | Block_ops_in | Block_ops_out | Messages_sent | Messages_received | Page_faults_major | Page_faults_minor | Swaps | Source_function | Source_file | Source_line | +----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+----------------------+-------------+ | starting | 0.000086 | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | | checking permissions | 0.000010 | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | check_access | sql_authorization.cc | 810 | | Opening tables | 0.000134 | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | open_tables | sql_base.cc | 5779 | | init | 0.000020 | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | handle_query | sql_select.cc | 121 | | System lock | 0.000013 | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | mysql_lock_tables | lock.cc | 323 | | optimizing | 0.000006 | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | optimize | sql_optimizer.cc | 151 | | statistics | 0.000023 | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | optimize | sql_optimizer.cc | 386 | | preparing | 0.000018 | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | optimize | sql_optimizer.cc | 494 | | executing | 0.000002 | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | exec | sql_executor.cc | 119 | | Sending data | 8.616566 | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | exec | sql_executor.cc | 195 | | end | 0.000011 | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | handle_query | sql_select.cc | 200 | | query end | 0.000015 | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | mysql_execute_command | sql_parse.cc | 5243 | | closing tables | 0.000013 | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | mysql_execute_command | sql_parse.cc | 5321 | | freeing items | 0.000027 | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | mysql_parse | sql_parse.cc | 5941 | | logging slow query | 0.000002 | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | log_slow_do | log.cc | 1984 | | logging slow query | 0.000187 | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | log_slow_do | log.cc | 1985 | | cleaning up | 0.000019 | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | NULL | dispatch_command | sql_parse.cc | 1980 | +----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+----------------------+-------------+ 17 rows in set, 1 warning (0.00 sec) Tue May 12 19:37:30 2020 work@10.10.10.10(glc) > show profile cpu for query 2; +----------------------+----------+----------+------------+ | Status | Duration | CPU_user | CPU_system | +----------------------+----------+----------+------------+ | starting | 0.000086 | NULL | NULL | | checking permissions | 0.000010 | NULL | NULL | | Opening tables | 0.000134 | NULL | NULL | | init | 0.000020 | NULL | NULL | | System lock | 0.000013 | NULL | NULL | | optimizing | 0.000006 | NULL | NULL | | statistics | 0.000023 | NULL | NULL | | preparing | 0.000018 | NULL | NULL | | executing | 0.000002 | NULL | NULL | | Sending data | 8.616566 | NULL | NULL | | end | 0.000011 | NULL | NULL | | query end | 0.000015 | NULL | NULL | | closing tables | 0.000013 | NULL | NULL | | freeing items | 0.000027 | NULL | NULL | | logging slow query | 0.000002 | NULL | NULL | | logging slow query | 0.000187 | NULL | NULL | | cleaning up | 0.000019 | NULL | NULL | +----------------------+----------+----------+------------+ 17 rows in set, 1 warning (0.00 sec) Tue May 12 19:37:37 2020 work@10.10.10.10(glc) > show profile block io for query 2; +----------------------+----------+--------------+---------------+ | Status | Duration | Block_ops_in | Block_ops_out | +----------------------+----------+--------------+---------------+ | starting | 0.000086 | NULL | NULL | | checking permissions | 0.000010 | NULL | NULL | | Opening tables | 0.000134 | NULL | NULL | | init | 0.000020 | NULL | NULL | | System lock | 0.000013 | NULL | NULL | | optimizing | 0.000006 | NULL | NULL | | statistics | 0.000023 | NULL | NULL | | preparing | 0.000018 | NULL | NULL | | executing | 0.000002 | NULL | NULL | | Sending data | 8.616566 | NULL | NULL | | end | 0.000011 | NULL | NULL | | query end | 0.000015 | NULL | NULL | | closing tables | 0.000013 | NULL | NULL | | freeing items | 0.000027 | NULL | NULL | | logging slow query | 0.000002 | NULL | NULL | | logging slow query | 0.000187 | NULL | NULL | | cleaning up | 0.000019 | NULL | NULL | +----------------------+----------+--------------+---------------+ 17 rows in set, 1 warning (0.01 sec) Tue May 12 19:38:18 2020
标签：sele voluntary for mysq HERE 情况 count star profiling
原文地址：https://www.cnblogs.com/igoodful/p/12878136.html
