查看SQL语句执行时间

MySQL5.0.37版本以上支持了Profiling – 官方手册。此工具可用来查询SQL
会执行多少时间,System lock和Table lock
花多少时间等等,对定位一条语句的I/O消耗和CPU消耗 非常重要。
从启动profile之后的所有查询包括错误的语句都会记录。
关闭会话或者set profiling=0 就关闭了。
# 开启profiling
mysql> set profiling=1;
mysql> select * from user limit 1;
mysql> select count(*) from user group by sexal;
# 查看这些语句的profile
mysql> show profiles;
+————–+—————-+————————————————————–+
| Query_ID | Duration     | Query                                   
                                  |
+————–+—————-+————————————————————–+
|        1        | 0.00013200   | SELECT
DATABASE()                                               |
|        2        | 0.00044100   | select * from user limit
2                                      |
|        3        | 1.95544100   | select nick,count(*) from user group
by online|
+————–+—————-+————————————————————–+
查看具体一条(Query_ID=3
这一条)语句的profiles,包括CPU和柱塞I/O的情况
mysql> show profile cpu,block io for query 3;
+———————-+———-+———-+————+————–+—————+
| Status               | Duration | CPU_user | CPU_system |
Block_ops_in | Block_ops_out |
+———————-+———-+———-+————+————–+—————+
| starting             | 0.000057 | 0.000000 |   0.000000 |            0
|             0 |
| Opening tables       | 0.000014 | 0.000000 |   0.000000 |            0
|             0 |
| System lock          | 0.000006 | 0.000000 |   0.000000 |            0
|             0 |
| Table lock           | 0.000009 | 0.000000 |   0.000000 |            0
|             0 |
| init                 | 0.000021 | 0.000000 |   0.000000 |            0
|             0 |
| optimizing           | 0.000006 | 0.000000 |   0.000000 |            0
|             0 |
| statistics           | 0.000011 | 0.000000 |   0.000000 |            0
|             0 |
| preparing            | 0.000010 | 0.000000 |   0.000000 |            0
|             0 |
| Creating tmp table   | 0.000039 | 0.000000 |   0.000000 |            0
|             0 |
| executing            | 0.000005 | 0.000000 |   0.000000 |            0
|             0 |
| Copying to tmp table | 1.900619 | 1.030785 |   0.197970 |          127
|           127 |
| Sorting result       | 0.000015 | 0.000000 |   0.000000 |            0
|             0 |
| Sending data         | 0.000015 | 0.000000 |   0.000000 |            0
|             0 |
| end                  | 0.000005 | 0.000000 |   0.000000 |            0
|             0 |
| removing tmp table   | 0.000008 | 0.000000 |   0.000000 |            0
|             0 |
| end                  | 0.000005 | 0.000000 |   0.000000 |            0
|             0 |
| query end            | 0.000004 | 0.000000 |   0.000000 |            0
|             0 |
| freeing items        | 0.000025 | 0.000000 |   0.000000 |            0
|             0 |
| logging slow query   | 0.000004 | 0.000000 |   0.000000 |            0
|             0 |
| cleaning up          | 0.000005 | 0.000000 |   0.000000 |            0
|             0 |
+———————-+———-+———-+————+————–+—————+
上面就获得了一条语句的CPU和Block
IO消耗,对定位瓶颈很方便,其余的一些信息,可以用语句:“Show profile
*** for query 3”来获取
 
另外附上profiling 的学习质料
profiling 基础

profiling 进阶

maatkit–perldoc mk-query-profiler
profiling高级

profiling骨灰级

mysql show profiles使用分析sql性能

本文介绍用show profiles 之类的语句来简单查看sql的执行:

摘自 性能测试专栏

 

1,查一下profile是否已经打开,默认是不打开的。

官方手册。此工具可用来查询SQL 会执行多少时间,System lock和Table lock
花多少时间等等,对定位一条语句的…

Show
profiles是5.0.37之后添加的,要想使用此功能,要确保版本在5.0.37之后。

mysql> show profiles;

 

Empty set (0.02 sec)

查看一下我的数据库版本

mysql> show variables like “%pro%”;

mysql> Select  version();

+—————————+——-+

+———————+

| Variable_name | Value |

| version()           |

+—————————+——-+

+———————+

| profiling | OFF |

| 5.0.82-community-nt |

| profiling_history_size | 15 |

+———————+

| protocol_version | 10 |

  www.2cto.com  

| slave_compressed_protocol | OFF |

1 row in set (0.00 sec)

+—————————+——-+

 

4 rows in set (0.00 sec)

版本是支持show profiles功能的。接下来进入mysql性能跟踪诊断的世界

2,开启profile,然后测试

 

开启profile

查看是否打开了profiles功能,默认是关闭的

mysql> set profiling=1;

 

Query OK, 0 rows affected (0.00 sec)

mysql> use test;

测试如下:

 

mysql> show tables;

Database changed

+—————-+

 

| Tables_澳门金沙vip,in_test |

mysql> show profiles;

+—————-+

 

| aa |

Empty set (0.00 sec)

| bb |

 

| comment |

显示为空,说明profiles功能是关闭的。下面开启

| string_test |

 

| user |

mysql> set profiling=1;

+—————-+

 

5 rows in set (0.00 sec)

Query OK, 0 rows affected (0.00 sec)

mysql> select * from aa;

 

+—-+——+————+——+

执行下面的查询

| id | name | nname | sex |

  www.2cto.com  

+—-+——+————+——+

mysql> explain select distinct player_idfrom task limit 20;

| 2 | tank | bbbb,4bbbb | NULL |

 

| 3 | zhang| 3,c,u | NULL |

mysql> select distinct player_id from task ;

+—-+——+————+——+

 

2 rows in set (0.00 sec)

然后执行 show profiles

mysql> update aa set name=’d’;

 

Query OK, 2 rows affected (0.00 sec)

mysql> show profiles;

Rows matched: 2 Changed: 2 Warnings: 0

 

mysql> delete from bb;

+———-+————+——————————————————+

Query OK, 2 rows affected (0.00 sec)

 

mysql> show profiles;

| Query_ID | Duration   | Query                                        
      |

+———-+————+————————+

 

| Query_ID | Duration | Query |

+———-+————+——————————————————+

+———-+————+————————+

 

| 1 | 0.00054775 | show tables |

|       1 | 0.00035225 | explain select distinct player_id from task
limit 20 |

| 2 | 0.00022400 | select * from aa |

 

| 3 | 0.00026275 | update aa set name=’d’ |

|       2 | 1.91772775 | select distinct player_id from task          
       |

| 4 | 0.00043000 | delete from bb |

 

+———-+————+————————+

+———-+————+——————————————————+

4 rows in set (0.00 sec)

 

mysql> show profile;

此时可以看到执行select distinct player_id from task
用了1.91772775秒的时间

+———————-+———–+

 

| Status | Duration |

根据query_id 查看某个查询的详细时间耗费

+———————-+———–+

 

| (initialization) | 0.0000247 |

mysql> show profile for query 2;

| checking permissions | 0.0000077 |

  www.2cto.com  

| Opening tables | 0.0000099 |

+———————-+———-+

| System lock | 0.000004 |

 

| Table lock | 0.000005 |

| Status               | Duration |

| init | 0.0003057 |

 

| query end | 0.0000062 |

+———————-+———-+

| freeing items | 0.000057 |

 

| closing tables | 0.000008 |

| starting             | 0.000052 |

| logging slow query | 0.0000015 |

 

+———————-+———–+

| Opening tables       | 0.000009 |

10 rows in set (0.00 sec)

 

mysql> show profile for query 1;

| System lock          | 0.000003 |

+———————-+———–+

 

| Status | Duration |

| Table lock           | 0.000007 |

+———————-+———–+

 

| (initialization) | 0.000028 |