mysql 查看慢语句日志_mysql慢查询日志使用总结

mysql慢查询日志使用总结

首先查看log_output参数，确认日志信息输出到操作系统文件还是数据库的表中：

mysql> show variables like 'log_output';

+---------------+-------+

| Variable_name | Value |

+---------------+-------+

| log_output    | FILE  |

+---------------+-------+

1 row in set (0.00 sec)

mysql>

通过上面的结果可以发现，log_output的值为“FILE”,证明是输出到日志文件，

如果值为“TABLE”则将日志信息输出到默认“mysql”数据库中的相应日志表中(具体为：mysql.slow_log)，

该表的默认引擎为CSV。

开启慢查询日志：

set global slow_query_log=on;

设置慢查询的阀值为4秒，超过4秒的查询都将记录到慢查询日志中：

set global long_query_time=4;

也可以设置得更低，例如：

set global long_query_time=0.1;

设置慢查询日志的名称和存储位置：

set global slow_query_log_file="e:\mysql_slow_query.log";

运行一个超过4秒的查询：

select count(*) from aa;

查询出现慢查询次数的累计值(值由0变为1)：

mysql> show global status like 'Slow_queries';

+---------------+-------+

| Variable_name | Value |

+---------------+-------+

| Slow_queries  | 1     |

+---------------+-------+

1 row in set (0.00 sec)

mysql>

打开生成的mysql_slow_query.log文件，发现新增了如下信息：

# Time: 140509 17:39:32

# User@Host: root[root] @  [127.0.0.1]

# Query_time: 13.025654  Lock_time: 0.738594 Rows_sent: 1  Rows_examined: 1187860

use database1;

SET timestamp=1399628372;

select count(*) from aa;

其中：

“Time: 140509 17:39:32”为执行这条慢查询sql语句的日期和时间。

“Query_time: 13.025654”为这条慢查询sql语句的执行时间(大约执行了13秒)。

其它可选的配置：

set global log_queries_not_using_indexes = true;

通过这个配置，可以将所有没有使用到索引的sql语句都记录到慢查询日志中

(即使执行时间小于long_query_time所指定的值！)。

测试：

select count(*) from bb;

查看慢查询日志：

# Query_time: 0.032001  Lock_time: 0.031001 Rows_sent: 1  Rows_examined: 88

SET timestamp=1399949174;

select count(*) from bb;

我们可以看到这条sql语句的执行时间虽然只有0.03秒，但由于没有使用到索引，因此也被记录到了慢查询日志中。

===========================================================================================================

继续测试：

select * from aa where id=634786438;

aa表有上百万条记录，id列上建有主键索引，由于这条sql语句使用到了索引，因此没有被记录到慢查询日志中。

===========================================================================================================

在官方文档中还描述了一种比较特殊的情况：

This option does not necessarily mean that no index is used. For example, a query that uses

a full index scan uses an index but would be logged because the index would not limit the number of rows.

文档位置：

http://mysql.cdpa.nsysu.edu.tw/doc/refman/5.1/en/server-options.html

继续测试：

select id from aa;

select id from aa limit 5;

查看慢查询日志：

# Query_time: 0.631036  Lock_time: 0.000000 Rows_sent: 1187860  Rows_examined: 1187860

SET timestamp=1399949756;

select id from aa;

......

# Query_time: 0.001000  Lock_time: 0.000000 Rows_sent: 5  Rows_examined: 5

SET timestamp=1399953250;

select id from aa limit 5;

这两条sql语句虽然也都使用到了索引，但依然被记录到慢查询日志中。

通过执行计划可以看出这两条sql语句使用了“覆盖索引”(在执行计划中显示为：“Extra: Using index”)。

所谓“覆盖索引”(Covering Index)指的是：只需读取(扫描)索引中的数据就能完成一个查询，而不需要再读取表中的行数据。

上面这两条sql语句由于只读取了主键索引列(id)的数据，因此称为“覆盖索引”。

但是，这两条sql语句并没有通过索引来限定(过滤)行数据，所以都被记录到了慢查询日志中。

如果慢查询日志中的记录内容很多，可以使用mysqldumpslow工具，对慢查询日志进行分类汇总。

mysqldumpslow是mysql数据库自带的工具，在安装mysql数据库软件时，点击“Developer Components”旁边的按钮，

选择“this feature,and all subfeatures will be Install”(安装所有子项)，就可以安装mysqldumpslow工具了。

进入mysql的basedir目录下的scripts目录，就可以找到mysqldumpslow.pl了。

在执行mysqldumpslow.pl脚本之前，

还需要下载并安装ActivePerl(linux系统没试过，至少window系统需要安装ActivePerl)，

最新版下载地址：

http://www.activestate.com/activeperl

=======================================================================================

进入mysql的basedir目录下的scripts目录：

cd D:\Program Files (x86)\MySQL\MySQL Server 5.1\scripts

执行mysqldumpslow.pl --help命令了解mysqldumpslow用法：

mysqldumpslow.pl --help

=======================================================================================

执行：

mysqldumpslow.pl -s t -t 7 e:\mysql_slow_query.log

这条命令会输出执行时间最长的7条sql语句。

这条命令中各个参数的意义：

-s, 是表示按照何种方式排序，c、t、l、r分别是按照语句query次数、query time、lock time、rows sent的总数来排序，

at、al、ar则是以query time、lock time、rows sent的平均值来排序；

-t, 是top n的意思，即返回排序在最前面的多少条sql语句。

此语句的显示结果如下：

Reading mysql slow query log from e:\mysql_slow_query.log

Count: 6  Time=2301.70s (13810s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@[127

.0.0.1]

update shuzhi set shuzhi='S' where name='S'

Count: 6  Time=2085.78s (12514s)  Lock=0.00s (0s)  Rows=7.3 (44), root[root]@[12

7.0.0.1]

select * from shuzhi lock in share mode

Count: 1  Time=6668.59s (6668s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@[127.

0.0.1]

update shuzhi set name='S' where id=N

Count: 2  Time=40.28s (80s)  Lock=0.01s (0s)  Rows=0.0 (0), root[root]@[127.0.0.

1]

insert into shuzhi values(N,'S',N)

Count: 10  Time=7.27s (72s)  Lock=0.00s (0s)  Rows=1.0 (10), root[root]@[127.0.0

.1]

select count(*) from aaaaaa

where aaaaaaTime>='S' and aaaaaaTime<='S'

Count: 3  Time=20.76s (62s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@[127.0.0.

1]

insert into aaaaaa select * from aaaaaa limit N

Count: 3  Time=17.83s (53s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@[127.0.0.

1]

insert into aaaaaa select * from aaaaaa

--------------------------------------------------------------------

其中Count即query次数，Time即query time、Lock即lock time，Rows即rows sent。

前4条sql语句是发生严重锁等待的4条sql语句。

--------------------------------------------------------------------

请注意输出结果中的最后一条sql语句：

“insert into aaaaaa select * from aaaaaa”，

可以明显看出此语句执行了3次(Count: 3)，

平均每次的执行时间为17.83秒(Time=17.83s)，

这3次执行的总执行时间是53秒(Time=17.83s后面的“(53s)”)。

---------------------------------------------------------------------

如果多条sql语句仅仅只是参数值不同，那么这些sql语句会被汇总成一条sql语句显示。

例如：

insert into aaaaaa select * from aaaaaa limit 500000;

insert into aaaaaa select * from aaaaaa limit 600000;

insert into aaaaaa select * from aaaaaa limit 700000;

会被汇总为：

“insert into aaaaaa select * from aaaaaa limit N”。  也就是输出结果中的倒数第2条sql语句。

其中“limit N”中的“N"代表不同的值(数字)。如果参数变量显示为：“S”，则代表不同的字符串。

从上面的输出结果“Count: 3  Time=20.76s (62s)”可以看出：

这样的sql语句被执行了3次，平均每条sql语句执行了20.76秒，这3条sql语句执行时间的总和是62秒。

如果不希望做这样的汇总(即：不希望将多条相似的sql语句(仅仅只是参数变量的值不同)汇总为一条显示)，

可以在命令中加入“-a”选项：

mysqldumpslow.pl -a -s t -t 7 e:\mysql_slow_query.log

===================================================================================

上面的输出结果是按照执行时间的总和排名的。

我们还可以按照平均执行时间进行排名(将“t”改成“at”)：

mysqldumpslow.pl -s at -t 5 e:\mysql_slow_query.log

输出结果如下：

Reading mysql slow query log from e:\mysql_slow_query.log

Count: 1  Time=6668.59s (6668s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@[127.

0.0.1]

update shuzhi set name='S' where id=N

Count: 6  Time=2301.70s (13810s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@[127

.0.0.1]

update shuzhi set shuzhi='S' where name='S'

Count: 6  Time=2085.78s (12514s)  Lock=0.00s (0s)  Rows=7.3 (44), root[root]@[12

7.0.0.1]

select * from shuzhi lock in share mode

Count: 2  Time=40.28s (80s)  Lock=0.01s (0s)  Rows=0.0 (0), root[root]@[127.0.0.

1]

insert into shuzhi values(N,'S',N)

Count: 3  Time=20.76s (62s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@[127.0.0.

1]

insert into aaaaaa select * from aaaaaa limit N

请注意比较两次输出结果中的前2条sql语句。

===================================================================================

其它用法举例：

mysqldumpslow.pl -s t -t 3 -g "left join" e:\mysql_slow_query.log

这条命令会输出执行时间最长的、并且包含“left join”的前3条sql语句。

注：-g, 后边可以写一个匹配模式(一个字符串)，例如：“left join”。

官方文档的描述：

http://dev.mysql.com/doc/refman/5.1/en/mysqldumpslow.html

为确保数据库系统在重启后配置依然生效，修改my.ini(Linux系统为my.cnf)文件，

在“[mysqld]”之后添加：

slow-query-log

slow_query_log_file = "e:\mysql_slow_query.log"

long_query_time = 4

如果需要记录没有使用到索引的sql语句，还可以添加：

log-queries-not-using-indexes = true

来自 “ ITPUB博客 ” ，链接：http://blog.itpub.net/29612462/viewspace-1167623/，如需转载，请注明出处，否则将追究法律责任。