一、用途
获取一个sql执行的全部过程的时间占用情况
二、用法
（1）select @@profiling;
（2）set profiling = 1; #这里仅仅在该会话中改变。
（3）目标sql语句;
（4）show profiles;
（5）show profile for
三、举例
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
