首页 » 数据库技术

mysql慢查询日志使用总结

   发表于:数据库技术评论 ()   热度:1218

首先查看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           

(。・v・。)
喜欢这篇文章吗?欢迎分享到你的微博、QQ群,并关注我们的微博,谢谢支持。