赞
踩
以select
语句为例,首先打开profile
参数:
mysql> set profiling = 1;
Query OK, 0 rows affected, 1 warning (0.00 sec)
然后执行两边下面的语句:
mysql> select * from employees;
可以通过show profile
语句查看最近一条SQL的执行过程:
mysql> show profile; +----------------------+----------+ | Status | Duration | +----------------------+----------+ | starting | 0.000039 | | checking permissions | 0.000004 | | Opening tables | 0.000012 | | init | 0.000014 | | System lock | 0.000006 | | optimizing | 0.000002 | | statistics | 0.000008 | | preparing | 0.000010 | | executing | 0.000003 | | Sending data | 0.000188 | | end | 0.000004 | | query end | 0.000006 | | closing tables | 0.000008 | | freeing items | 0.000104 | | cleaning up | 0.000013 | +----------------------+----------+ 15 rows in set, 1 warning (0.00 sec)
可以看到一条SQL语句要经历上述15步。如果开启了SQL缓存且命中缓存的话,步骤会减少,但SQL缓存要求两条SQL必须完全一样才能命中,任何字符的更改(包括注释、空格等)都会导致缓存没命中,因此MySQL的缓存相当鸡肋,命中率很低。
可以通过show profiles
开启profiling
后所有SQL语句的耗时:
mysql> show profiles;
+----------+------------+-------------------------+
| Query_ID | Duration | Query |
+----------+------------+-------------------------+
| 1 | 0.00070175 | select * from employees |
| 2 | 0.00041950 | select * from employees |
+----------+------------+-------------------------+
2 rows in set, 1 warning (0.00 sec)
可以通过show profile for query Query_ID
查看:
mysql> show profile for query 1; +----------------------+----------+ | Status | Duration | +----------------------+----------+ | starting | 0.000036 | | checking permissions | 0.000004 | | Opening tables | 0.000012 | | init | 0.000013 | | System lock | 0.000006 | | optimizing | 0.000002 | | statistics | 0.000008 | | preparing | 0.000355 | | executing | 0.000006 | | Sending data | 0.000169 | | end | 0.000003 | | query end | 0.000005 | | closing tables | 0.000006 | | freeing items | 0.000070 | | cleaning up | 0.000007 | +----------------------+----------+ 15 rows in set, 1 warning (0.00 sec) mysql> show profile for query 2; +----------------------+----------+ | Status | Duration | +----------------------+----------+ | starting | 0.000039 | | checking permissions | 0.000004 | | Opening tables | 0.000012 | | init | 0.000014 | | System lock | 0.000006 | | optimizing | 0.000002 | | statistics | 0.000008 | | preparing | 0.000010 | | executing | 0.000003 | | Sending data | 0.000188 | | end | 0.000004 | | query end | 0.000006 | | closing tables | 0.000008 | | freeing items | 0.000104 | | cleaning up | 0.000013 | +----------------------+----------+ 15 rows in set, 1 warning (0.00 sec)
mysql> show profile CPU, block io;
+---------------+----------+----------+------------+--------------+---------------+
| Status | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out |
+---------------+----------+----------+------------+--------------+---------------+
| starting | 0.000066 | 0.000000 | 0.000000 | NULL | NULL |
| freeing items | 0.000058 | 0.000000 | 0.000000 | NULL | NULL |
| cleaning up | 0.000004 | 0.000000 | 0.000000 | NULL | NULL |
+---------------+----------+----------+------------+--------------+---------------+
3 rows in set, 1 warning (0.00 sec)
mysql> show profile all for query 1\G *************************** 1. row *************************** Status: starting Duration: 0.000036 CPU_user: 0.000000 CPU_system: 0.000000 Context_voluntary: NULL Context_involuntary: NULL Block_ops_in: NULL Block_ops_out: NULL Messages_sent: NULL Messages_received: NULL Page_faults_major: NULL Page_faults_minor: NULL Swaps: NULL Source_function: NULL Source_file: NULL Source_line: NULL *************************** 2. row *************************** Status: checking permissions Duration: 0.000004 CPU_user: 0.000000 CPU_system: 0.000000 Context_voluntary: NULL Context_involuntary: NULL Block_ops_in: NULL Block_ops_out: NULL Messages_sent: NULL Messages_received: NULL Page_faults_major: NULL Page_faults_minor: NULL Swaps: NULL Source_function: check_access Source_file: sql_authorization.cc Source_line: 802 *************************** 3. row *************************** Status: Opening tables Duration: 0.000012 CPU_user: 0.000000 CPU_system: 0.000000 Context_voluntary: NULL Context_involuntary: NULL Block_ops_in: NULL Block_ops_out: NULL Messages_sent: NULL Messages_received: NULL Page_faults_major: NULL Page_faults_minor: NULL Swaps: NULL Source_function: open_tables Source_file: sql_base.cc Source_line: 5714 *************************** 4. row *************************** Status: init Duration: 0.000013 CPU_user: 0.000000 CPU_system: 0.000000 Context_voluntary: NULL Context_involuntary: NULL Block_ops_in: NULL Block_ops_out: NULL Messages_sent: NULL Messages_received: NULL Page_faults_major: NULL Page_faults_minor: NULL Swaps: NULL Source_function: handle_query Source_file: sql_select.cc Source_line: 121 *************************** 5. row *************************** Status: System lock Duration: 0.000006 CPU_user: 0.000000 CPU_system: 0.000000 Context_voluntary: NULL Context_involuntary: NULL Block_ops_in: NULL Block_ops_out: NULL Messages_sent: NULL Messages_received: NULL Page_faults_major: NULL Page_faults_minor: NULL Swaps: NULL Source_function: mysql_lock_tables Source_file: lock.cc Source_line: 323 *************************** 6. row *************************** Status: optimizing Duration: 0.000002 CPU_user: 0.000000 CPU_system: 0.000000 Context_voluntary: NULL Context_involuntary: NULL Block_ops_in: NULL Block_ops_out: NULL Messages_sent: NULL Messages_received: NULL Page_faults_major: NULL Page_faults_minor: NULL Swaps: NULL Source_function: JOIN::optimize Source_file: sql_optimizer.cc Source_line: 151 *************************** 7. row *************************** Status: statistics Duration: 0.000008 CPU_user: 0.000000 CPU_system: 0.000000 Context_voluntary: NULL Context_involuntary: NULL Block_ops_in: NULL Block_ops_out: NULL Messages_sent: NULL Messages_received: NULL Page_faults_major: NULL Page_faults_minor: NULL Swaps: NULL Source_function: JOIN::optimize Source_file: sql_optimizer.cc Source_line: 367 *************************** 8. row *************************** Status: preparing Duration: 0.000355 CPU_user: 0.000000 CPU_system: 0.000000 Context_voluntary: NULL Context_involuntary: NULL Block_ops_in: NULL Block_ops_out: NULL Messages_sent: NULL Messages_received: NULL Page_faults_major: NULL Page_faults_minor: NULL Swaps: NULL Source_function: JOIN::optimize Source_file: sql_optimizer.cc Source_line: 475 *************************** 9. row *************************** Status: executing Duration: 0.000006 CPU_user: 0.000000 CPU_system: 0.000000 Context_voluntary: NULL Context_involuntary: NULL Block_ops_in: NULL Block_ops_out: NULL Messages_sent: NULL Messages_received: NULL Page_faults_major: NULL Page_faults_minor: NULL Swaps: NULL Source_function: JOIN::exec Source_file: sql_executor.cc Source_line: 119 *************************** 10. row *************************** Status: Sending data Duration: 0.000169 CPU_user: 0.000000 CPU_system: 0.000000 Context_voluntary: NULL Context_involuntary: NULL Block_ops_in: NULL Block_ops_out: NULL Messages_sent: NULL Messages_received: NULL Page_faults_major: NULL Page_faults_minor: NULL Swaps: NULL Source_function: JOIN::exec Source_file: sql_executor.cc Source_line: 195 *************************** 11. row *************************** Status: end Duration: 0.000003 CPU_user: 0.000000 CPU_system: 0.000000 Context_voluntary: NULL Context_involuntary: NULL Block_ops_in: NULL Block_ops_out: NULL Messages_sent: NULL Messages_received: NULL Page_faults_major: NULL Page_faults_minor: NULL Swaps: NULL Source_function: handle_query Source_file: sql_select.cc Source_line: 199 *************************** 12. row *************************** Status: query end Duration: 0.000005 CPU_user: 0.000000 CPU_system: 0.000000 Context_voluntary: NULL Context_involuntary: NULL Block_ops_in: NULL Block_ops_out: NULL Messages_sent: NULL Messages_received: NULL Page_faults_major: NULL Page_faults_minor: NULL Swaps: NULL Source_function: mysql_execute_command Source_file: sql_parse.cc Source_line: 4946 *************************** 13. row *************************** Status: closing tables Duration: 0.000006 CPU_user: 0.000000 CPU_system: 0.000000 Context_voluntary: NULL Context_involuntary: NULL Block_ops_in: NULL Block_ops_out: NULL Messages_sent: NULL Messages_received: NULL Page_faults_major: NULL Page_faults_minor: NULL Swaps: NULL Source_function: mysql_execute_command Source_file: sql_parse.cc Source_line: 4998 *************************** 14. row *************************** Status: freeing items Duration: 0.000070 CPU_user: 0.000000 CPU_system: 0.000000 Context_voluntary: NULL Context_involuntary: NULL Block_ops_in: NULL Block_ops_out: NULL Messages_sent: NULL Messages_received: NULL Page_faults_major: NULL Page_faults_minor: NULL Swaps: NULL Source_function: mysql_parse Source_file: sql_parse.cc Source_line: 5610 *************************** 15. row *************************** Status: cleaning up Duration: 0.000007 CPU_user: 0.000000 CPU_system: 0.000000 Context_voluntary: NULL Context_involuntary: NULL Block_ops_in: NULL Block_ops_out: NULL Messages_sent: NULL Messages_received: NULL Page_faults_major: NULL Page_faults_minor: NULL Swaps: NULL Source_function: dispatch_command Source_file: sql_parse.cc Source_line: 1924 15 rows in set, 1 warning (0.00 sec) 举其中的一行为例: *************************** 10. row *************************** Status: Sending data Duration: 0.000169 CPU_user: 0.000000 CPU_system: 0.000000 Context_voluntary: NULL Context_involuntary: NULL Block_ops_in: NULL Block_ops_out: NULL Messages_sent: NULL Messages_received: NULL Page_faults_major: NULL Page_faults_minor: NULL Swaps: NULL Source_function: JOIN::exec Source_file: sql_executor.cc Source_line: 195
每一行数据就显示该步骤下的各个阶段的耗时,甚至源文件等信息。
Copyright © 2003-2013 www.wpsshop.cn 版权所有,并保留所有权利。