php慢日志学习整理

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