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