MySQL 之 slow log

慢查询有什么用？      
      它能记录下所有执行超过long_query_time时间的SQL语句，帮你找到执行慢的SQL，方便我们对这些SQL进行优化。      

测试用 MySQL 版本。      
Server version: 5.6.10-log Source distribution      

未做任何慢日志设置时。      

01	mysql> show variables like "%query%";

02	+------------------------------+--------------------------------------+

03	| Variable_name                | Value                                |

04	+------------------------------+--------------------------------------+

05	| binlog_rows_query_log_events | OFF                                  |

06	| ft_query_expansion_limit     | 20                                   |

07	| have_query_cache             | YES                                  |

08	| long_query_time              | 10.000000                            |

09	| query_alloc_block_size       | 8192                                 |

10	| query_cache_limit            | 1048576                              |

11	| query_cache_min_res_unit     | 4096                                 |

12	| query_cache_size             | 1048576                              |

13	| query_cache_type             | OFF                                  |

14	| query_cache_wlock_invalidate | OFF                                  |

15	| query_prealloc_size          | 8192                                 |

16	| slow_query_log               | OFF                                  |

17	| slow_query_log_file          | /usr/local/mysql/data/Betty-slow.log |

18	+------------------------------+--------------------------------------+

19	13 rows in set (0.01 sec)

20

21

mysql>

修改配置文件，开启 slow log 。   

01	[root@Betty data]# vi /etc/my.cnf

02

03	# For advice on how to change settings please see

04	# http://dev.mysql.com/doc/refman/5.6/en/server-configuration-defaults.html

05	# *** DO NOT EDIT THIS FILE. It's a template which will be copied to the

06	# *** default location during install, and will be replaced if you

07	# *** upgrade to a newer version of MySQL.

08

09

[mysqld]

10

11	# Remove leading # and set to the amount of RAM for the most important data

12	# cache in MySQL. Start at 70% of total RAM for dedicated server, else 10%.

13	# innodb_buffer_pool_size = 128M

14

15	# Remove leading # to turn on a very important data integrity option: logging

16	# changes to the binary log between backups.

17	log_bin=mysql-bin

18

19	slow_query_log=on

20	slow_query_log_file=mysql-slow

21	long_query_time=2

22

23	# These are commonly set, remove the # and set as required.

24	# basedir = .....

25	# datadir = .....

26	# port = .....

27	# server_id = .....

28	# socket = .....

29

30	# Remove leading # to set options mainly useful for reporting servers.

31	# The server defaults are faster for transactions and fast SELECTs.

32	# Adjust sizes as needed, experiment to find the optimal values.

33	# join_buffer_size = 128M

34	# sort_buffer_size = 2M

35	# read_rnd_buffer_size = 2M

36

37	sql_mode=NO_ENGINE_SUBSTITUTION,STRICT_TRANS_TABLES

38

39

[mysql]

40	socket = /tmp/mysql.sock

重启 MySQL 。   

1	[root@Betty data]# /etc/init.d/mysql restart

2	Shutting down MySQL..                                      [  OK  ]

3	Starting MySQL.                                            [  OK  ]

4	[root@Betty data]#

查看 slow log 。   

1	[root@Betty data]# ll mysql-slow

2	-rw-rw---- 1 mysql mysql 719 Sep  6 12:43 mysql-slow

重新查看系统变量值。   

01

mysql>

02	mysql> show variables like "%query%";

03	+------------------------------+------------+

04	| Variable_name                | Value      |

05	+------------------------------+------------+

06	| binlog_rows_query_log_events | OFF        |

07	| ft_query_expansion_limit     | 20         |

08	| have_query_cache             | YES        |

09	| long_query_time              | 2.000000   |

10	| query_alloc_block_size       | 8192       |

11	| query_cache_limit            | 1048576    |

12	| query_cache_min_res_unit     | 4096       |

13	| query_cache_size             | 1048576    |

14	| query_cache_type             | OFF        |

15	| query_cache_wlock_invalidate | OFF        |

16	| query_prealloc_size          | 8192       |

17	| slow_query_log               | ON         |

18	| slow_query_log_file          | mysql-slow |

19	+------------------------------+------------+

20	13 rows in set (0.00 sec)

21

22

mysql>

查看新生成的 slow log 的内容。   

1	[root@Betty data]# cat mysql-slow

2	/usr/local/mysql/bin/mysqld, Version: 5.6.10-log (Source distribution). started with:

3	Tcp port: 0  Unix socket: (null)

4	Time                 Id Command    Argument

5	[root@Betty data]#

测试 slow log 。

01

mysql>

02	mysql> select 1;

03

+---+

04

| 1 |

05

+---+

06

| 1 |

07

+---+

08	1 row in set (0.00 sec)

09

10

mysql>

11	mysql> select sleep(1);

12	+----------+

13	| sleep(1) |

14	+----------+

15	|        0 |

16	+----------+

17	1 row in set (1.00 sec)

18

19

mysql>

20

mysql>

21	mysql> select sleep(3);

22	+----------+

23	| sleep(3) |

24	+----------+

25	|        0 |

26	+----------+

27	1 row in set (3.00 sec)

28

29

mysql>

30	mysql> select sleep(4);

31	+----------+

32	| sleep(4) |

33	+----------+

34	|        0 |

35	+----------+

36	1 row in set (4.01 sec)

37

38

mysql>

39

mysql>

40	mysql> select sleep(5);

41	+----------+

42	| sleep(5) |

43	+----------+

44	|        0 |

45	+----------+

46	1 row in set (5.00 sec)

47

48	mysql> select sleep(2);

49	+----------+

50	| sleep(2) |

51	+----------+

52	|        0 |

53	+----------+

54	1 row in set (2.01 sec)

55

56

mysql>

57	mysql> select sleep(1);

58	+----------+

59	| sleep(1) |

60	+----------+

61	|        0 |

62	+----------+

63	1 row in set (1.00 sec)

64

65	mysql> select 2;

66

+---+

67

| 2 |

68

+---+

69

| 2 |

70

+---+

71	1 row in set (0.00 sec)

72

73

mysql>

查看此时 slow log 的内容。   

01	[root@Betty data]# cat mysql-slow

02	/usr/local/mysql/bin/mysqld, Version: 5.6.10-log (Source distribution). started with:

03	Tcp port: 0  Unix socket: (null)

04	Time                 Id Command    Argument

05	# Time: 130906 12:52:51

06	# User@Host: root[root] @ localhost []  Id:     1

07	# Query_time: 3.002864  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 0

08	SET timestamp=1378443171;

09	select sleep(3);

10	# Time: 130906 12:53:01

11	# User@Host: root[root] @ localhost []  Id:     1

12	# Query_time: 4.001943  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 0

13	SET timestamp=1378443181;

14	select sleep(4);

15	# Time: 130906 12:53:09

16	# User@Host: root[root] @ localhost []  Id:     1

17	# Query_time: 5.002093  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 0

18	SET timestamp=1378443189;

19	select sleep(5);

20	# Time: 130906 12:53:15

21	# User@Host: root[root] @ localhost []  Id:     1

22	# Query_time: 2.002984  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 0

23	SET timestamp=1378443195;

24	select sleep(2);

25	[root@Betty data]#

实验：   

a. 使用 mysql 自带慢查询日志分析工具 mysqldumpslow 。   

1	[root@Betty data]# mysqldumpslow mysql-slow

2

3	Reading mysql slow query log from mysql-slow

4	Count: 4  Time=3.50s (14s)  Lock=0.00s (0s)  Rows=1.0 (4), root[root]@localhost

5	select sleep(N)

6

7	[root@Betty data]#

b. 使用 hackmysql.com 推出的一款日志分析工具 mysqlsla 。   

01	[root@Betty data]# mysqlsla -lt slow mysql-slow

02	Report for slow logs: mysql-slow

03	4 queries total, 1 unique

04	Sorted by 't_sum'

05	Grand Totals: Time 14 s, Lock 0 s, Rows sent 4, Rows Examined 0

06

07	______________________________________________________________________ 001 ___

08	Count         : 4  (100.00%)

09	Time          : 14.009884 s total, 3.502471 s avg, 2.002984 s to 5.002093 s max  (100.00%)

10	Lock Time (s) : 0 total, 0 avg, 0 to 0 max  (0.00%)

11	Rows sent     : 1 avg, 1 to 1 max  (100.00%)

12	Rows examined : 0 avg, 0 to 0 max  (0.00%)

13	Database      :

14	Users         :

15	root@localhost  : 100.00% (4) of query, 100.00% (4) of all users

16

17	Query abstract:

18	SET timestamp=N; SELECT sleep(N);

19

20	Query sample:

21	SET timestamp=1378443171;

22	select sleep(3);

23	[root@Betty data]#

c. 使用德国人写的 mysql_explain_slow_log 。（不知道为什么未统计出信息）   

01	[root@Betty WGET_DIR]# ./mysql_explain_slow_log --user=root --password= --socket=/tmp/mysql.sock < /usr/local/mysql/data/mysql-slow

02	mysql_explain_slow_log

03	======================

04

05	Index usage ------------------------------------

06

07	Queries causing table scans -------------------

08

09	Sum: 0 table scans

10

11	Summary ---------------------------------------

12

13	Select:         0 queries

14	Update:         0 queries

15	Load:   0 queries

16

17	Logfile:        26 lines

18	Started:        Fri Sep  6 15:59:13 2013

19	Finished:       Fri Sep  6 15:59:13 2013

20	[root@Betty WGET_DIR]#

d.        google code 上的一个分析工具 mysql_filter_slow_log （最后更新日期为2007年），提供了 python 和 php 两种可执行的脚本。      

01	[root@Betty WGET_DIR]# python mysql_filter_slow_log.py /usr/local/mysql/data/mysql-slow --no-duplicates --sort-execution-count --top=10

02	# Execution count: 1 time on 2013-09-06 16:07:23.

03	# Column       : avg | max | sum

04	# Query time   :   5 |   5 |   5

05	# Lock time    :   0 |   0 |   0

06	# Rows examined:   0 |   0 |   0

07	# Rows sent    :   1 |   1 |   1

08	# User@Host: root[root] @ localhost []  Id:     1

09

10	SET timestamp=1378454843;select sleep(5);

11

12	# Execution count: 1 time on 2013-09-06 16:07:15.

13	# Column       : avg | max | sum

14	# Query time   :   4 |   4 |   4

15	# Lock time    :   0 |   0 |   0

16	# Rows examined:   0 |   0 |   0

17	# Rows sent    :   1 |   1 |   1

18	# User@Host: root[root] @ localhost []  Id:     1

19

20	SET timestamp=1378454835;select sleep(4);

21

22	# Execution count: 1 time on 2013-09-06 16:07:01.

23	# Column       : avg | max | sum

24	# Query time   :   3 |   3 |   3

25	# Lock time    :   0 |   0 |   0

26	# Rows examined:   0 |   0 |   0

27	# Rows sent    :   1 |   1 |   1

28	# User@Host: root[root] @ localhost []  Id:     1

29

30	SET timestamp=1378454821;select sleep(3);

31

32	# Execution count: 1 time on 2013-09-06 16:07:28.

33	# Column       : avg | max | sum

34	# Query time   :   2 |   2 |   2

35	# Lock time    :   0 |   0 |   0

36	# Rows examined:   0 |   0 |   0

37	# Rows sent    :   1 |   1 |   1

38	# User@Host: root[root] @ localhost []  Id:     1

39

40	SET timestamp=1378454848;select sleep(2);

41

42	[root@Betty WGET_DIR]#

e. 使用 percona-toolkit 中的 pt-query-digest （在《高性能MySQL》中多次提出，值得使用的工具）。      

01	[root@Betty data]# pt-query-digest --user=root  mysql-slow

02

03	# 120ms user time, 10ms system time, 20.21M rss, 68.70M vsz

04	# Current date: Mon Sep  9 13:21:38 2013

05	# Hostname: Betty

06	# Files: mysql-slow

07	# Overall: 4 total, 1 unique, 0.15 QPS, 0.52x concurrency ________________

08	# Time range: 2013-09-06 16:07:01 to 16:07:28

09	# Attribute          total     min     max     avg     95%  stddev  median

10	# ============     ======= ======= ======= ======= ======= ======= =======

11	# Exec time            14s      2s      5s      4s      5s      1s      4s

12	# Lock time              0       0       0       0       0       0       0

13	# Rows sent              4       1       1       1       1       0       1

14	# Rows examine           0       0       0       0       0       0       0

15	# Query size            60      15      15      15      15       0      15

16

17

# Profile

18	# Rank Query ID           Response time  Calls R/Call V/M   Item

19	# ==== ================== ============== ===== ====== ===== ======

20	#    1 0xF9A57DD5A41825CA 14.0097 100.0%     4 3.5024  0.36 SELECT

21

22	# Query 1: 0.15 QPS, 0.52x concurrency, ID 0xF9A57DD5A41825CA at byte 548

23	# This item is included in the report because it matches --limit.

24	# Scores: V/M = 0.36

25	# Time range: 2013-09-06 16:07:01 to 16:07:28

26	# Attribute    pct   total     min     max     avg     95%  stddev  median

27	# ============ === ======= ======= ======= ======= ======= ======= =======

28	# Count        100       4

29	# Exec time    100     14s      2s      5s      4s      5s      1s      4s

30	# Lock time      0       0       0       0       0       0       0       0

31	# Rows sent    100       4       1       1       1       1       0       1

32	# Rows examine   0       0       0       0       0       0       0       0

33	# Query size   100      60      15      15      15      15       0      15

34

# String:

35	# Hosts        localhost

36	# Users        root

37	# Query_time distribution

38

#   1us

39

#  10us

40

# 100us

41

#   1ms

42

#  10ms

43

# 100ms

44	#    1s  ################################################################

45

#  10s+

46	# EXPLAIN /*!50100 PARTITIONS*/

47	select sleep(5)\G

48	[root@Betty data]#

慢查询配置项      

01	# I.e. you could add the following lines under the [mysqld] section of your my.ini or my.cnf configuration file:

02

03	# Log all queries taking more than 3 seconds

04	long_query_time=3  # minimum: 1, default: 10

05

06	# MySQL >= 5.1.21 (or patched): 3 seconds = 3000000 microseconds

07	# long_query_time=3.000000  # minimum: 0.000001 (1 microsecond)

08

09	# Activate the Slow Query Log

10	slow_query_log  # >= 5.1.29

11	# log-slow-queries  # deprecated since 5.1.29

12

13	# Write to a custom file name (>= 5.1.29)

14	# slow_query_log_file=file_name  # default: /data_dir/host_name-slow.log

15

16	# Log all queries without indexes

17	# log-queries-not-using-indexes

18

19	# Log only queries which examine at least N rows (>= 5.1.21)

20	# min_examined_row_limit=1000  # default: 0

21

22	# Log slow OPTIMIZE TABLE, ANALYZE TABLE, and ALTER TABLE statements

23	# log-slow-admin-statements

24

25	# Log slow queries executed by replication slaves (>= 5.1.21)

26	# log-slow-slave-statements

27

28	# MySQL 5.1.6 through 5.1.20 had a default value of log-output=TABLE, so you should force

29	# Attention: logging to TABLE only includes whole seconds information

30	log-output=FILE

31

32

33	## Admin query for online activation is possible since MySQL 5.1 (without server restart)

34	## SET @@global.slow_query_log=1

35	## SET @@global.long_query_time=1

36

37

38	## Show current variables related to the Slow Query Log

39	## SHOW GLOBAL VARIABLES WHERE Variable_name REGEXP 'admin|min_examined|log_output|log_queries|log_slave|long|slow_quer'

========= 我是分割线 =========       

下面给出网上一篇流传已久的博客文章，供参考（做了部分修正）。
参考：《   五款常用mysql slow log分析工具的比较   》，原文写于2008年。              

mysql slow log 分析工具的比较              

mysql 中的 slow log 是用来记录执行时间较长(超过 long_query_time 秒)的 sql 的一种日志工具。              

启用 slow log              
在 my.cnf 中设置

1

[mysqld]

2	slow_query_log=on

3	slow_query_log_file=mysql-slow

重启 MySQL 服务。

五款常用工具              

1. mysqldumpslow
2. mysqlsla
3. myprofi
4. mysql-explain-slow-log
5. mysql-log-filter

mysqldumpslow
      mysql官方提供的慢查询日志分析工具。输出图表如下：              
             
主要功能包括统计不同慢 sql 的              

• 出现次数(Count)
• 执行耗费的平均时间和累计总耗费时间(Time)
• 等待锁耗费的时间(Lock)
• 发送给客户端的行总数(Rows)
• 扫描的行总数(Rows)
• 用户以及sql语句本身(抽象了一下格式，比如 limit 1, 20 用 limit N,N 表示)

mysqlsla
      hackmysql.com 推出的一款日志分析工具(该网站还维护了 mysqlreport，mysqlidxchk 等比较实用的mysql 工具)。              
             
      整体来说，功能非常强大。输出的数据报表非常有利于分析慢查询的原因，包括执行频率、数据量、查询消耗等。            

格式说明如下：              

• 总查询次数 (queries total)，去重后的 sql 数量 (unique)
• 输出报表的内容排序(sorted by)
• 最重大的慢 sql 统计信息，包括平均执行时间、等待锁时间、结果行的总数、扫描的行总数。

• Count -- sql 的执行次数及占总的 slow log 数量的百分比。
• Time -- 执行时间，包括总时间、平均时间、最小、最大时间、时间占到总慢 sql 时间的百分比。
• 95% of Time -- 去除最快和最慢的 sql，覆盖率占 95% 的 sql 的执行时间。
• Lock Time -- 等待锁的时间。
• 95% of Lock -- 95% 的慢 sql 等待锁时间。
• Rows sent -- 结果行统计数量，包括平均、最小、最大数量。
• Rows examined -- 扫描的行数量。
• Database -- 属于哪个数据库。
• Users -- 哪个用户、IP、占到所有用户执行的 sql 百分比。
• Query abstract -- 抽象后的 sql 语句。
• Query sample -- sql 语句。

除了以上的输出，官方还提供了很多定制化参数，是一款不可多得的好工具。              


mysql-explain-slow-log
      德国人写的一个 perl 脚本。              
http://www.willamowius.de/mysql-tools.html              
http://www.bt285.cn/content.php?id=1196863              
             

             
功能上有点瑕疵。不仅把所有的 slow log 打印到屏幕上，而且统计也只有数量而已，不推荐使用。

mysql-log-filter
      google code 上找到的一个分析工具，提供了 python 和 php 两种可执行的脚本。              
http://code.google.com/p/mysql-log-filter/              
                功能上比官方的 mysqldumpslow 多了查询时间的统计信息(平均、最大、累计)，其他功能都与 mysqldumpslow 类似。              
      特色功能除了统计信息外，还针对输出内容做了排版和格式化，保证整体输出的简洁。喜欢简洁报表的朋友，推荐使用一下。

myprofi
      纯 php 写的一个开源分析工具.项目在 sourceforge 上。              
http://myprofi.sourceforge.net/              
 
      功能上，列出了总的慢查询次数和类型、去重后的 sql 语句、执行次数及其占总的 slow log 数量的百分比。          
      从整体输出样式来看，比 mysql-log-filter 还要简洁，省去了很多不必要的内容。对于只想看 sql 语句及执行次数的用户来说，比较推荐。              

总结：      

工具/功能	一般统计信息	高级统计信息	脚本	优势
mysqldumpslow	支持	不支持	perl	mysql官方自带
mysqlsla	支持	支持	perl	功能强大,数据报表齐全,定制化能力强
mysql-explain-slow-log	支持	不支持	perl	无
mysql-log-filter	支持	部分支持	python or php	不失功能的前提下,保持输出简洁
myprofi	支持	不支持	php	非常精简